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/16 20:56:39 UTC
[JENKINS] Lucene-Solr-4.x-Linux (64bit/jdk1.8.0-ea-b93) - Build #
6097 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/6097/
Java: 64bit/jdk1.8.0-ea-b93 -XX:+UseCompressedOops -XX:+UseParallelGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.testDistribSearch
Error Message:
shard2 is not consistent. Got 350 from http://127.0.0.1:34539/collection1lastClient and got 348 from http://127.0.0.1:37851/collection1
Stack Trace:
java.lang.AssertionError: shard2 is not consistent. Got 350 from http://127.0.0.1:34539/collection1lastClient and got 348 from http://127.0.0.1:37851/collection1
at __randomizedtesting.SeedInfo.seed([7FBFA98732E885AA:FE59279F45B7E596]: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:491)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Build Log:
[...truncated 9703 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
[junit4:junit4] 2> 402131 T1238 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 402136 T1238 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeySafeLeaderTest-1371408294390
[junit4:junit4] 2> 402137 T1238 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 402137 T1239 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 402237 T1238 oasc.ZkTestServer.run start zk server on port:53059
[junit4:junit4] 2> 402239 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 402327 T1245 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4454c6d1 name:ZooKeeperConnection Watcher:127.0.0.1:53059 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 402327 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 402327 T1238 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 402332 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 402333 T1247 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4a93202b name:ZooKeeperConnection Watcher:127.0.0.1:53059/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 402333 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 402333 T1238 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 402336 T1238 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 402338 T1238 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 402340 T1238 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 402342 T1238 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 402343 T1238 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 402346 T1238 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 402347 T1238 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 402349 T1238 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 402350 T1238 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 402352 T1238 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 402352 T1238 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 402355 T1238 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 402355 T1238 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 402357 T1238 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 402358 T1238 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 402360 T1238 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 402361 T1238 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 402363 T1238 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 402363 T1238 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 402366 T1238 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 402366 T1238 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 402432 T1238 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 402435 T1238 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54621
[junit4:junit4] 2> 402435 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 402435 T1238 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 402436 T1238 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371408294622
[junit4:junit4] 2> 402436 T1238 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371408294622/solr.xml
[junit4:junit4] 2> 402436 T1238 oasc.CoreContainer.<init> New CoreContainer 1913228802
[junit4:junit4] 2> 402436 T1238 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371408294622/'
[junit4:junit4] 2> 402436 T1238 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371408294622/'
[junit4:junit4] 2> 402472 T1238 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 402472 T1238 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 402472 T1238 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 402473 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 402473 T1238 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 402473 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 402473 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 402473 T1238 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 402474 T1238 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 402474 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 402477 T1238 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 402477 T1238 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53059/solr
[junit4:junit4] 2> 402477 T1238 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 402478 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 402479 T1258 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@60324209 name:ZooKeeperConnection Watcher:127.0.0.1:53059 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 402480 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 402481 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 402484 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 402485 T1260 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@21ebb1a5 name:ZooKeeperConnection Watcher:127.0.0.1:53059/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 402485 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 402486 T1238 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 402489 T1238 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 402491 T1238 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 402493 T1238 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54621_
[junit4:junit4] 2> 402493 T1238 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54621_
[junit4:junit4] 2> 402496 T1238 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 402501 T1238 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 402503 T1238 oasc.Overseer.start Overseer (id=89876613981274115-127.0.0.1:54621_-n_0000000000) starting
[junit4:junit4] 2> 402506 T1238 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 402510 T1262 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 402511 T1238 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 402513 T1238 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 402515 T1238 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 402517 T1261 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 402519 T1263 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 402519 T1263 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 404021 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 404021 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54621",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54621_"}
[junit4:junit4] 2> 404021 T1261 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 404022 T1261 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 404025 T1260 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> 404521 T1263 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371408294622/collection1
[junit4:junit4] 2> 404522 T1263 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 404522 T1263 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 404523 T1263 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 404524 T1263 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371408294622/collection1/'
[junit4:junit4] 2> 404524 T1263 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371408294622/collection1/lib/README' to classloader
[junit4:junit4] 2> 404525 T1263 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371408294622/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 404552 T1263 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 404588 T1263 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 404590 T1263 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 404593 T1263 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 404884 T1263 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 404890 T1263 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 404893 T1263 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 404904 T1263 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 404907 T1263 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 404909 T1263 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 404910 T1263 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 404911 T1263 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 404911 T1263 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 404912 T1263 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 404912 T1263 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 404912 T1263 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 404912 T1263 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371408294622/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/control/data/
[junit4:junit4] 2> 404912 T1263 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1bac204f
[junit4:junit4] 2> 404913 T1263 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 404913 T1263 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/control/data
[junit4:junit4] 2> 404913 T1263 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/control/data/index/
[junit4:junit4] 2> 404914 T1263 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 404914 T1263 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/control/data/index
[junit4:junit4] 2> 404918 T1263 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 404918 T1263 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 404920 T1263 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 404920 T1263 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 404920 T1263 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 404921 T1263 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 404921 T1263 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 404921 T1263 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 404921 T1263 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 404921 T1263 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 404922 T1263 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 404923 T1263 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 404925 T1263 oass.SolrIndexSearcher.<init> Opening Searcher@3d75756d main
[junit4:junit4] 2> 404926 T1263 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 404926 T1263 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 404929 T1264 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3d75756d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 404930 T1263 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 404930 T1263 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54621 collection:control_collection shard:shard1
[junit4:junit4] 2> 404931 T1263 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 404937 T1263 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 404939 T1263 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 404939 T1263 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 404939 T1263 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54621/collection1/
[junit4:junit4] 2> 404940 T1263 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 404940 T1263 oasc.SyncStrategy.syncToMe http://127.0.0.1:54621/collection1/ has no replicas
[junit4:junit4] 2> 404940 T1263 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54621/collection1/
[junit4:junit4] 2> 404940 T1263 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 405529 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 405537 T1260 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> 405546 T1263 oasc.ZkController.register We are http://127.0.0.1:54621/collection1/ and leader is http://127.0.0.1:54621/collection1/
[junit4:junit4] 2> 405546 T1263 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54621
[junit4:junit4] 2> 405546 T1263 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 405546 T1263 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 405546 T1263 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 405548 T1263 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 405549 T1238 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 405549 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 405550 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 405554 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 405555 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 405557 T1267 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7611b58a name:ZooKeeperConnection Watcher:127.0.0.1:53059/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 405557 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 405559 T1238 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 405561 T1238 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 405639 T1238 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 405641 T1238 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:44898
[junit4:junit4] 2> 405641 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 405642 T1238 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 405642 T1238 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371408297814
[junit4:junit4] 2> 405642 T1238 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371408297814/solr.xml
[junit4:junit4] 2> 405642 T1238 oasc.CoreContainer.<init> New CoreContainer 113879503
[junit4:junit4] 2> 405643 T1238 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371408297814/'
[junit4:junit4] 2> 405643 T1238 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371408297814/'
[junit4:junit4] 2> 405685 T1238 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 405686 T1238 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 405686 T1238 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 405687 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 405687 T1238 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 405687 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 405687 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 405688 T1238 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 405688 T1238 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 405688 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 405691 T1238 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 405692 T1238 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53059/solr
[junit4:junit4] 2> 405692 T1238 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 405693 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 405694 T1278 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@32371c4e name:ZooKeeperConnection Watcher:127.0.0.1:53059 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 405694 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 405697 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 405700 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 405701 T1280 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2064afc9 name:ZooKeeperConnection Watcher:127.0.0.1:53059/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 405701 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 405705 T1238 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 406708 T1238 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44898_
[junit4:junit4] 2> 406709 T1238 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:44898_
[junit4:junit4] 2> 406711 T1260 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> 406711 T1280 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 406711 T1267 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 406712 T1260 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 406716 T1281 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 406716 T1281 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 407042 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 407043 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54621",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:54621_"}
[junit4:junit4] 2> 407046 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44898",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44898_"}
[junit4:junit4] 2> 407046 T1261 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 3
[junit4:junit4] 2> 407046 T1261 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 407050 T1280 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> 407050 T1260 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> 407050 T1267 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> 407717 T1281 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371408297814/collection1
[junit4:junit4] 2> 407717 T1281 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 407718 T1281 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 407718 T1281 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 407719 T1281 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371408297814/collection1/'
[junit4:junit4] 2> 407720 T1281 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371408297814/collection1/lib/README' to classloader
[junit4:junit4] 2> 407720 T1281 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371408297814/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 407742 T1281 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 407772 T1281 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 407774 T1281 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 407777 T1281 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 408069 T1281 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 408074 T1281 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 408077 T1281 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 408088 T1281 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 408090 T1281 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 408093 T1281 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 408094 T1281 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 408094 T1281 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 408095 T1281 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 408095 T1281 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 408096 T1281 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 408096 T1281 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 408096 T1281 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371408297814/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty1/
[junit4:junit4] 2> 408096 T1281 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1bac204f
[junit4:junit4] 2> 408097 T1281 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 408097 T1281 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty1
[junit4:junit4] 2> 408097 T1281 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty1/index/
[junit4:junit4] 2> 408098 T1281 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 408098 T1281 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty1/index
[junit4:junit4] 2> 408101 T1281 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 408101 T1281 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 408103 T1281 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 408103 T1281 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 408104 T1281 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 408104 T1281 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 408105 T1281 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 408105 T1281 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 408105 T1281 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 408106 T1281 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 408106 T1281 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 408107 T1281 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 408110 T1281 oass.SolrIndexSearcher.<init> Opening Searcher@584f4a3c main
[junit4:junit4] 2> 408110 T1281 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 408111 T1281 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 408115 T1282 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@584f4a3c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 408117 T1281 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 408117 T1281 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:44898 collection:collection1 shard:shard1
[junit4:junit4] 2> 408118 T1281 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 408123 T1281 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 408125 T1281 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 408125 T1281 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 408125 T1281 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:44898/collection1/
[junit4:junit4] 2> 408125 T1281 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 408125 T1281 oasc.SyncStrategy.syncToMe http://127.0.0.1:44898/collection1/ has no replicas
[junit4:junit4] 2> 408126 T1281 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:44898/collection1/
[junit4:junit4] 2> 408126 T1281 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 408556 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 408561 T1260 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> 408561 T1267 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> 408562 T1280 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> 408584 T1281 oasc.ZkController.register We are http://127.0.0.1:44898/collection1/ and leader is http://127.0.0.1:44898/collection1/
[junit4:junit4] 2> 408584 T1281 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44898
[junit4:junit4] 2> 408584 T1281 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 408584 T1281 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 408584 T1281 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 408585 T1281 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 408586 T1238 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 408586 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 408587 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 408664 T1238 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 408667 T1238 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:35870
[junit4:junit4] 2> 408667 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 408667 T1238 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 408668 T1238 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371408300843
[junit4:junit4] 2> 408668 T1238 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371408300843/solr.xml
[junit4:junit4] 2> 408668 T1238 oasc.CoreContainer.<init> New CoreContainer 280993259
[junit4:junit4] 2> 408669 T1238 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371408300843/'
[junit4:junit4] 2> 408669 T1238 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371408300843/'
[junit4:junit4] 2> 408708 T1238 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 408708 T1238 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 408708 T1238 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 408708 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 408709 T1238 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 408709 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 408709 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 408709 T1238 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 408710 T1238 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 408710 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 408713 T1238 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 408713 T1238 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53059/solr
[junit4:junit4] 2> 408713 T1238 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 408714 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 408715 T1294 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6e8b4ceb name:ZooKeeperConnection Watcher:127.0.0.1:53059 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 408716 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 408717 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 408720 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 408721 T1296 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4868b113 name:ZooKeeperConnection Watcher:127.0.0.1:53059/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 408722 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 408725 T1238 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 409728 T1238 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35870_
[junit4:junit4] 2> 409730 T1238 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:35870_
[junit4:junit4] 2> 409732 T1267 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> 409732 T1260 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> 409732 T1280 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> 409733 T1296 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 409734 T1267 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 409734 T1260 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 409734 T1280 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 409738 T1297 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 409738 T1297 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 410068 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 410069 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44898",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:44898_"}
[junit4:junit4] 2> 410072 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35870",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:35870_"}
[junit4:junit4] 2> 410072 T1261 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 410072 T1261 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 410076 T1260 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> 410076 T1280 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> 410076 T1267 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> 410076 T1296 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> 410739 T1297 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371408300843/collection1
[junit4:junit4] 2> 410739 T1297 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 410740 T1297 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 410740 T1297 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 410741 T1297 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371408300843/collection1/'
[junit4:junit4] 2> 410741 T1297 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371408300843/collection1/lib/README' to classloader
[junit4:junit4] 2> 410742 T1297 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371408300843/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 410764 T1297 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 410795 T1297 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 410797 T1297 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 410799 T1297 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 411096 T1297 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 411101 T1297 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 411103 T1297 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 411116 T1297 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 411119 T1297 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 411121 T1297 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 411122 T1297 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 411123 T1297 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 411123 T1297 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 411124 T1297 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 411124 T1297 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 411124 T1297 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 411125 T1297 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371408300843/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty2/
[junit4:junit4] 2> 411125 T1297 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1bac204f
[junit4:junit4] 2> 411125 T1297 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 411125 T1297 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty2
[junit4:junit4] 2> 411126 T1297 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty2/index/
[junit4:junit4] 2> 411126 T1297 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 411126 T1297 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty2/index
[junit4:junit4] 2> 411157 T1297 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 411157 T1297 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 411159 T1297 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 411159 T1297 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 411159 T1297 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 411160 T1297 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 411160 T1297 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 411160 T1297 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 411161 T1297 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 411161 T1297 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 411161 T1297 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 411163 T1297 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 411165 T1297 oass.SolrIndexSearcher.<init> Opening Searcher@3f69c2e0 main
[junit4:junit4] 2> 411166 T1297 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 411166 T1297 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 411170 T1298 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3f69c2e0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 411172 T1297 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 411172 T1297 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:35870 collection:collection1 shard:shard3
[junit4:junit4] 2> 411172 T1297 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4:junit4] 2> 411178 T1297 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 411180 T1297 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 411180 T1297 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 411181 T1297 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:35870/collection1/
[junit4:junit4] 2> 411181 T1297 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 411181 T1297 oasc.SyncStrategy.syncToMe http://127.0.0.1:35870/collection1/ has no replicas
[junit4:junit4] 2> 411181 T1297 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:35870/collection1/
[junit4:junit4] 2> 411181 T1297 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4:junit4] 2> 411582 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 411590 T1280 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> 411590 T1260 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> 411590 T1296 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> 411590 T1267 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> 411637 T1297 oasc.ZkController.register We are http://127.0.0.1:35870/collection1/ and leader is http://127.0.0.1:35870/collection1/
[junit4:junit4] 2> 411637 T1297 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35870
[junit4:junit4] 2> 411637 T1297 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 411637 T1297 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 411637 T1297 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 411639 T1297 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 411640 T1238 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 411641 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 411641 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 411715 T1238 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 411718 T1238 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:33718
[junit4:junit4] 2> 411718 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 411719 T1238 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 411719 T1238 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371408303897
[junit4:junit4] 2> 411719 T1238 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371408303897/solr.xml
[junit4:junit4] 2> 411719 T1238 oasc.CoreContainer.<init> New CoreContainer 1308246299
[junit4:junit4] 2> 411720 T1238 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371408303897/'
[junit4:junit4] 2> 411720 T1238 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371408303897/'
[junit4:junit4] 2> 411761 T1238 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 411761 T1238 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 411762 T1238 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 411762 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 411762 T1238 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 411762 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 411762 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 411763 T1238 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 411763 T1238 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 411763 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 411766 T1238 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 411766 T1238 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53059/solr
[junit4:junit4] 2> 411767 T1238 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 411767 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 411770 T1310 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1524a3b5 name:ZooKeeperConnection Watcher:127.0.0.1:53059 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 411770 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 411772 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 411775 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 411776 T1312 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@28601502 name:ZooKeeperConnection Watcher:127.0.0.1:53059/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 411776 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 411781 T1238 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 412784 T1238 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33718_
[junit4:junit4] 2> 412797 T1238 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:33718_
[junit4:junit4] 2> 412807 T1267 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> 412808 T1280 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 412808 T1280 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> 412808 T1296 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 412808 T1260 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 412808 T1296 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> 412809 T1260 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> 412809 T1312 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 412811 T1267 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 412821 T1313 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 412821 T1313 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 413096 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 413096 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35870",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "node_name":"127.0.0.1:35870_"}
[junit4:junit4] 2> 413100 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:33718",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:33718_"}
[junit4:junit4] 2> 413100 T1261 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 413100 T1261 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 413103 T1296 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> 413103 T1312 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> 413103 T1267 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> 413103 T1260 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> 413103 T1280 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> 413823 T1313 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371408303897/collection1
[junit4:junit4] 2> 413823 T1313 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 413824 T1313 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 413824 T1313 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 413825 T1313 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371408303897/collection1/'
[junit4:junit4] 2> 413825 T1313 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371408303897/collection1/lib/README' to classloader
[junit4:junit4] 2> 413825 T1313 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371408303897/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 413847 T1313 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 413873 T1313 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 413874 T1313 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 413877 T1313 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 414156 T1313 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 414161 T1313 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 414163 T1313 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 414174 T1313 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 414176 T1313 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 414179 T1313 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 414180 T1313 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 414180 T1313 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 414180 T1313 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 414182 T1313 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 414182 T1313 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 414182 T1313 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 414182 T1313 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371408303897/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty3/
[junit4:junit4] 2> 414182 T1313 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1bac204f
[junit4:junit4] 2> 414183 T1313 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 414183 T1313 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty3
[junit4:junit4] 2> 414183 T1313 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty3/index/
[junit4:junit4] 2> 414184 T1313 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 414184 T1313 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty3/index
[junit4:junit4] 2> 414207 T1313 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 414207 T1313 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 414209 T1313 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 414210 T1313 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 414210 T1313 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 414210 T1313 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 414211 T1313 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 414211 T1313 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 414211 T1313 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 414212 T1313 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 414212 T1313 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 414213 T1313 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 414216 T1313 oass.SolrIndexSearcher.<init> Opening Searcher@1e3ff06b main
[junit4:junit4] 2> 414216 T1313 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 414216 T1313 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 414220 T1314 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1e3ff06b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 414222 T1313 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 414222 T1313 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:33718 collection:collection1 shard:shard2
[junit4:junit4] 2> 414223 T1313 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 414228 T1313 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 414230 T1313 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 414230 T1313 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 414230 T1313 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:33718/collection1/
[junit4:junit4] 2> 414230 T1313 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 414230 T1313 oasc.SyncStrategy.syncToMe http://127.0.0.1:33718/collection1/ has no replicas
[junit4:junit4] 2> 414230 T1313 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:33718/collection1/
[junit4:junit4] 2> 414231 T1313 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 414608 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 414617 T1296 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> 414617 T1312 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> 414618 T1280 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> 414618 T1260 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> 414617 T1267 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> 414635 T1313 oasc.ZkController.register We are http://127.0.0.1:33718/collection1/ and leader is http://127.0.0.1:33718/collection1/
[junit4:junit4] 2> 414636 T1313 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:33718
[junit4:junit4] 2> 414636 T1313 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 414636 T1313 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 414637 T1313 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 414640 T1313 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 414642 T1238 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 414642 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 414643 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 414709 T1238 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 414712 T1238 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55867
[junit4:junit4] 2> 414713 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 414713 T1238 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 414713 T1238 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371408306901
[junit4:junit4] 2> 414713 T1238 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371408306901/solr.xml
[junit4:junit4] 2> 414714 T1238 oasc.CoreContainer.<init> New CoreContainer 784421167
[junit4:junit4] 2> 414714 T1238 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371408306901/'
[junit4:junit4] 2> 414714 T1238 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371408306901/'
[junit4:junit4] 2> 414748 T1238 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 414749 T1238 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 414749 T1238 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 414749 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 414749 T1238 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 414750 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 414750 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 414750 T1238 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 414750 T1238 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 414750 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 414753 T1238 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 414753 T1238 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53059/solr
[junit4:junit4] 2> 414754 T1238 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 414754 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 414756 T1326 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f5ada95 name:ZooKeeperConnection Watcher:127.0.0.1:53059 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 414756 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 414758 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 414760 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 414762 T1328 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@383db6f1 name:ZooKeeperConnection Watcher:127.0.0.1:53059/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 414762 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 414766 T1238 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 415769 T1238 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55867_
[junit4:junit4] 2> 415770 T1238 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55867_
[junit4:junit4] 2> 415772 T1280 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> 415772 T1296 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> 415772 T1267 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> 415773 T1312 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 415773 T1312 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> 415773 T1260 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 415773 T1260 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> 415773 T1328 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 415774 T1280 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 415774 T1296 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 415774 T1267 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 415779 T1329 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 415779 T1329 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 416127 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 416129 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:33718",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:33718_"}
[junit4:junit4] 2> 416134 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55867",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55867_"}
[junit4:junit4] 2> 416134 T1261 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 416135 T1261 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 416140 T1328 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> 416140 T1280 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> 416140 T1296 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> 416140 T1312 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> 416140 T1260 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> 416140 T1267 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> 416781 T1329 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371408306901/collection1
[junit4:junit4] 2> 416781 T1329 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 416782 T1329 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 416782 T1329 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 416783 T1329 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371408306901/collection1/'
[junit4:junit4] 2> 416783 T1329 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371408306901/collection1/lib/README' to classloader
[junit4:junit4] 2> 416784 T1329 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371408306901/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 416807 T1329 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 416839 T1329 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 416840 T1329 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 416843 T1329 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 417150 T1329 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 417155 T1329 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 417157 T1329 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 417167 T1329 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 417170 T1329 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 417172 T1329 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 417173 T1329 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 417173 T1329 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 417173 T1329 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 417174 T1329 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 417174 T1329 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 417174 T1329 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 417175 T1329 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371408306901/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty4/
[junit4:junit4] 2> 417175 T1329 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1bac204f
[junit4:junit4] 2> 417175 T1329 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 417175 T1329 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty4
[junit4:junit4] 2> 417175 T1329 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty4/index/
[junit4:junit4] 2> 417176 T1329 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 417176 T1329 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty4/index
[junit4:junit4] 2> 417207 T1329 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 417207 T1329 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 417211 T1329 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 417211 T1329 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 417212 T1329 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 417212 T1329 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 417213 T1329 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 417213 T1329 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 417213 T1329 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 417214 T1329 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 417214 T1329 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 417215 T1329 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 417218 T1329 oass.SolrIndexSearcher.<init> Opening Searcher@4560d131 main
[junit4:junit4] 2> 417218 T1329 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 417219 T1329 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 417222 T1330 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4560d131 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 417224 T1329 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 417224 T1329 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55867 collection:collection1 shard:shard1
[junit4:junit4] 2> 417227 T1329 oasc.ZkController.register We are http://127.0.0.1:55867/collection1/ and leader is http://127.0.0.1:44898/collection1/
[junit4:junit4] 2> 417227 T1329 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55867
[junit4:junit4] 2> 417227 T1329 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 417227 T1329 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2527 name=collection1 org.apache.solr.core.SolrCore@7be8ef21 url=http://127.0.0.1:55867/collection1 node=127.0.0.1:55867_ C2527_STATE=coll:collection1 core:collection1 props:{core=collection1, base_url=http://127.0.0.1:55867, state=down, collection=collection1, node_name=127.0.0.1:55867_}
[junit4:junit4] 2> 417227 T1331 C2527 P55867 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 417228 T1329 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 417228 T1331 C2527 P55867 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 417228 T1331 C2527 P55867 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 417228 T1331 C2527 P55867 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 417229 T1238 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 417229 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 417229 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 417230 T1331 C2527 P55867 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 417233 T1276 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 417301 T1238 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 417303 T1238 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:56897
[junit4:junit4] 2> 417304 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 417304 T1238 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 417304 T1238 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371408309485
[junit4:junit4] 2> 417304 T1238 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371408309485/solr.xml
[junit4:junit4] 2> 417305 T1238 oasc.CoreContainer.<init> New CoreContainer 2122467586
[junit4:junit4] 2> 417305 T1238 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371408309485/'
[junit4:junit4] 2> 417305 T1238 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371408309485/'
[junit4:junit4] 2> 417343 T1238 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 417343 T1238 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 417343 T1238 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 417344 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 417344 T1238 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 417344 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 417344 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 417345 T1238 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 417345 T1238 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 417345 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 417348 T1238 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 417348 T1238 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53059/solr
[junit4:junit4] 2> 417348 T1238 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 417349 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 417351 T1343 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2e23238e name:ZooKeeperConnection Watcher:127.0.0.1:53059 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 417351 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 417353 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 417356 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 417357 T1345 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@23a172d7 name:ZooKeeperConnection Watcher:127.0.0.1:53059/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 417357 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 417360 T1238 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 417649 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 417650 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55867",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:55867_"}
[junit4:junit4] 2> 417653 T1260 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> 417653 T1296 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> 417653 T1312 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> 417653 T1267 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> 417653 T1280 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> 417653 T1328 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> 417653 T1345 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> 418233 T1276 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 418234 T1276 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={core=collection1&checkLive=true&onlyIfLeader=true&state=recovering&nodeName=127.0.0.1:55867_&coreNodeName=5&wt=javabin&version=2&action=PREPRECOVERY} status=0 QTime=1001
[junit4:junit4] 2> 418363 T1238 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56897_
[junit4:junit4] 2> 418364 T1238 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:56897_
[junit4:junit4] 2> 418366 T1328 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> 418366 T1312 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> 418367 T1345 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 418367 T1267 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 418367 T1260 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 418367 T1280 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 418368 T1260 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> 418368 T1267 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> 418368 T1296 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 418368 T1345 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> 418369 T1328 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 418369 T1296 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> 418368 T1280 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> 418369 T1312 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 418373 T1346 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 418374 T1346 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 419158 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 419159 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56897",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:56897_"}
[junit4:junit4] 2> 419159 T1261 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 419159 T1261 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 419177 T1345 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> 419177 T1260 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> 419177 T1267 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> 419177 T1296 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> 419177 T1280 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> 419177 T1312 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> 419177 T1328 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> 419375 T1346 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371408309485/collection1
[junit4:junit4] 2> 419375 T1346 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 419376 T1346 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 419376 T1346 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 419377 T1346 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371408309485/collection1/'
[junit4:junit4] 2> 419377 T1346 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371408309485/collection1/lib/README' to classloader
[junit4:junit4] 2> 419377 T1346 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371408309485/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 419403 T1346 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 419432 T1346 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 419433 T1346 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 419436 T1346 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 419705 T1346 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 419709 T1346 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 419711 T1346 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 419723 T1346 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 419725 T1346 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 419728 T1346 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 419729 T1346 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 419729 T1346 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 419729 T1346 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 419730 T1346 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 419730 T1346 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 419731 T1346 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 419731 T1346 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371408309485/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty5/
[junit4:junit4] 2> 419731 T1346 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1bac204f
[junit4:junit4] 2> 419731 T1346 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 419732 T1346 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty5
[junit4:junit4] 2> 419732 T1346 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty5/index/
[junit4:junit4] 2> 419732 T1346 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 419733 T1346 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty5/index
[junit4:junit4] 2> 419757 T1346 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 419757 T1346 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 419759 T1346 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 419759 T1346 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 419760 T1346 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 419760 T1346 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 419761 T1346 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 419761 T1346 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 419761 T1346 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 419762 T1346 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 419762 T1346 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 419764 T1346 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 419766 T1346 oass.SolrIndexSearcher.<init> Opening Searcher@12a8e1ae main
[junit4:junit4] 2> 419767 T1346 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 419767 T1346 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 419770 T1347 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12a8e1ae main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 419772 T1346 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 419772 T1346 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:56897 collection:collection1 shard:shard3
[junit4:junit4] 2> 419775 T1346 oasc.ZkController.register We are http://127.0.0.1:56897/collection1/ and leader is http://127.0.0.1:35870/collection1/
[junit4:junit4] 2> 419775 T1346 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56897
[junit4:junit4] 2> 419775 T1346 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 419775 T1346 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2528 name=collection1 org.apache.solr.core.SolrCore@522f3972 url=http://127.0.0.1:56897/collection1 node=127.0.0.1:56897_ C2528_STATE=coll:collection1 core:collection1 props:{core=collection1, base_url=http://127.0.0.1:56897, state=down, collection=collection1, node_name=127.0.0.1:56897_}
[junit4:junit4] 2> 419776 T1348 C2528 P56897 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 419776 T1348 C2528 P56897 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 419776 T1346 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 419776 T1348 C2528 P56897 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 419777 T1348 C2528 P56897 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 419777 T1238 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 419777 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 419777 T1348 C2528 P56897 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 419778 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 419782 T1292 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 419852 T1238 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 419854 T1238 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:35261
[junit4:junit4] 2> 419855 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 419855 T1238 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 419855 T1238 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371408312034
[junit4:junit4] 2> 419855 T1238 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371408312034/solr.xml
[junit4:junit4] 2> 419856 T1238 oasc.CoreContainer.<init> New CoreContainer 503136867
[junit4:junit4] 2> 419856 T1238 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371408312034/'
[junit4:junit4] 2> 419856 T1238 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371408312034/'
[junit4:junit4] 2> 419909 T1238 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 419909 T1238 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 419910 T1238 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 419910 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 419910 T1238 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 419910 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 419911 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 419911 T1238 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 419911 T1238 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 419911 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 419914 T1238 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 419915 T1238 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53059/solr
[junit4:junit4] 2> 419915 T1238 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 419916 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 419917 T1360 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6bdeb2ae name:ZooKeeperConnection Watcher:127.0.0.1:53059 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 419918 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 419920 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 419924 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 419925 T1362 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5830a787 name:ZooKeeperConnection Watcher:127.0.0.1:53059/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 419926 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 419929 T1238 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C2529 name=collection1 org.apache.solr.core.SolrCore@7be8ef21 url=http://127.0.0.1:55867/collection1 node=127.0.0.1:55867_ C2529_STATE=coll:collection1 core:collection1 props:{core=collection1, base_url=http://127.0.0.1:55867, state=recovering, collection=collection1, shard=shard1, node_name=127.0.0.1:55867_}
[junit4:junit4] 2> 420235 T1331 C2529 P55867 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:44898/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 420236 T1331 C2529 P55867 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55867 START replicas=[http://127.0.0.1:44898/collection1/] nUpdates=100
[junit4:junit4] 2> 420236 T1331 C2529 P55867 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 420236 T1331 C2529 P55867 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 420236 T1331 C2529 P55867 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 420237 T1331 C2529 P55867 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 420237 T1331 C2529 P55867 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 420237 T1331 C2529 P55867 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:44898/collection1/. core=collection1
[junit4:junit4] 2> 420237 T1331 C2529 P55867 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2530 name=collection1 org.apache.solr.core.SolrCore@3d55e742 url=http://127.0.0.1:44898/collection1 node=127.0.0.1:44898_ C2530_STATE=coll:collection1 core:collection1 props:{core=collection1, base_url=http://127.0.0.1:44898, state=active, collection=collection1, shard=shard1, node_name=127.0.0.1:44898_, leader=true}
[junit4:junit4] 2> 420241 T1275 C2530 P44898 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 420244 T1273 C2530 P44898 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 420246 T1273 C2530 P44898 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 420247 T1273 C2530 P44898 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 420256 T1273 C2530 P44898 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 420256 T1273 C2530 P44898 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 420257 T1273 C2530 P44898 oass.SolrIndexSearcher.<init> Opening Searcher@796ec5f9 realtime
[junit4:junit4] 2> 420257 T1273 C2530 P44898 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 420258 T1273 C2530 P44898 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={openSearcher=false&waitSearcher=true&commit_end_point=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4] 2> 420259 T1331 C2529 P55867 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 420259 T1331 C2529 P55867 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 420262 T1276 C2530 P44898 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 420262 T1276 C2530 P44898 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&wt=javabin&command=indexversion&version=2} status=0 QTime=1
[junit4:junit4] 2> 420263 T1331 C2529 P55867 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 420264 T1331 C2529 P55867 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 420264 T1331 C2529 P55867 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 420266 T1275 C2530 P44898 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&generation=2&wt=javabin&command=filelist&version=2} status=0 QTime=0
[junit4:junit4] 2> 420267 T1331 C2529 P55867 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 420270 T1331 C2529 P55867 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty4/index.20130616204512522
[junit4:junit4] 2> 420270 T1331 C2529 P55867 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty4/index.20130616204512522 lockFactory=org.apache.lucene.store.NativeFSLockFactory@60d1e303 fullCopy=false
[junit4:junit4] 2> 420274 T1273 C2530 P44898 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&checksum=true&generation=2&file=segments_2&wt=filestream&command=filecontent} status=0 QTime=1
[junit4:junit4] 2> 420276 T1331 C2529 P55867 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 420287 T1331 C2529 P55867 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 420287 T1331 C2529 P55867 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 420289 T1331 C2529 P55867 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty4/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 420290 T1331 C2529 P55867 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 420290 T1331 C2529 P55867 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 420291 T1331 C2529 P55867 oass.SolrIndexSearcher.<init> Opening Searcher@b7138a2 main
[junit4:junit4] 2> 420292 T1330 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@b7138a2 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 420292 T1331 C2529 P55867 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty4/index.20130616204512522 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty4/index.20130616204512522;done=true>>]
[junit4:junit4] 2> 420293 T1331 C2529 P55867 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty4/index.20130616204512522
[junit4:junit4] 2> 420293 T1331 C2529 P55867 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty4/index.20130616204512522
[junit4:junit4] 2> 420293 T1331 C2529 P55867 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 420294 T1331 C2529 P55867 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 420294 T1331 C2529 P55867 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 420294 T1331 C2529 P55867 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 420296 T1331 C2529 P55867 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 420682 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 420683 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56897",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "node_name":"127.0.0.1:56897_"}
[junit4:junit4] 2> 420686 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55867",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:55867_"}
[junit4:junit4] 2> 420710 T1328 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> 420710 T1280 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> 420710 T1267 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> 420711 T1296 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> 420710 T1362 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> 420710 T1260 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> 420710 T1312 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> 420710 T1345 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> 420782 T1292 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 420782 T1292 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={core=collection1&checkLive=true&onlyIfLeader=true&state=recovering&nodeName=127.0.0.1:56897_&coreNodeName=6&wt=javabin&version=2&action=PREPRECOVERY} status=0 QTime=1001
[junit4:junit4] 2> 420932 T1238 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35261_
[junit4:junit4] 2> 420933 T1238 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:35261_
[junit4:junit4] 2> 420935 T1312 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> 420935 T1267 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> 420935 T1362 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> 420936 T1345 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 420936 T1280 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 420935 T1260 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> 420935 T1296 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> 420935 T1328 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> 420936 T1280 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> 420936 T1345 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> 420938 T1362 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 420939 T1267 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 420940 T1312 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 420940 T1328 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 420940 T1260 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 420941 T1296 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 420943 T1365 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 420943 T1365 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 422218 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 422219 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35261",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core_node_name":"7",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:35261_"}
[junit4:junit4] 2> 422219 T1261 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 422219 T1261 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 422224 T1260 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> 422224 T1267 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> 422224 T1280 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> 422224 T1345 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> 422224 T1328 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> 422224 T1312 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> 422224 T1362 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> 422225 T1296 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> ASYNC NEW_CORE C2531 name=collection1 org.apache.solr.core.SolrCore@522f3972 url=http://127.0.0.1:56897/collection1 node=127.0.0.1:56897_ C2531_STATE=coll:collection1 core:collection1 props:{core=collection1, base_url=http://127.0.0.1:56897, state=recovering, collection=collection1, shard=shard3, node_name=127.0.0.1:56897_}
[junit4:junit4] 2> 422783 T1348 C2531 P56897 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:35870/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 422784 T1348 C2531 P56897 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56897 START replicas=[http://127.0.0.1:35870/collection1/] nUpdates=100
[junit4:junit4] 2> 422784 T1348 C2531 P56897 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 422784 T1348 C2531 P56897 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 422785 T1348 C2531 P56897 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 422785 T1348 C2531 P56897 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 422785 T1348 C2531 P56897 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 422785 T1348 C2531 P56897 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:35870/collection1/. core=collection1
[junit4:junit4] 2> 422785 T1348 C2531 P56897 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2532 name=collection1 org.apache.solr.core.SolrCore@47eb3aa4 url=http://127.0.0.1:35870/collection1 node=127.0.0.1:35870_ C2532_STATE=coll:collection1 core:collection1 props:{core=collection1, base_url=http://127.0.0.1:35870, state=active, collection=collection1, shard=shard3, node_name=127.0.0.1:35870_, leader=true}
[junit4:junit4] 2> 422789 T1289 C2532 P35870 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 422789 T1292 C2532 P35870 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 422794 T1289 C2532 P35870 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 422795 T1289 C2532 P35870 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 422806 T1289 C2532 P35870 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 422806 T1289 C2532 P35870 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 422807 T1289 C2532 P35870 oass.SolrIndexSearcher.<init> Opening Searcher@572d6ffb realtime
[junit4:junit4] 2> 422808 T1289 C2532 P35870 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 422808 T1289 C2532 P35870 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={openSearcher=false&waitSearcher=true&commit_end_point=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 19
[junit4:junit4] 2> 422809 T1348 C2531 P56897 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 422809 T1348 C2531 P56897 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 422810 T1291 C2532 P35870 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 422810 T1291 C2532 P35870 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&wt=javabin&command=indexversion&version=2} status=0 QTime=0
[junit4:junit4] 2> 422811 T1348 C2531 P56897 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 422811 T1348 C2531 P56897 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 422811 T1348 C2531 P56897 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 422813 T1292 C2532 P35870 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&generation=2&wt=javabin&command=filelist&version=2} status=0 QTime=1
[junit4:junit4] 2> 422813 T1348 C2531 P56897 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 422814 T1348 C2531 P56897 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty5/index.20130616204515066
[junit4:junit4] 2> 422814 T1348 C2531 P56897 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty5/index.20130616204515066 lockFactory=org.apache.lucene.store.NativeFSLockFactory@40cf38a3 fullCopy=false
[junit4:junit4] 2> 422816 T1289 C2532 P35870 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&checksum=true&generation=2&file=segments_2&wt=filestream&command=filecontent} status=0 QTime=0
[junit4:junit4] 2> 422817 T1348 C2531 P56897 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 422826 T1348 C2531 P56897 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 422826 T1348 C2531 P56897 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 422828 T1348 C2531 P56897 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty5/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 422828 T1348 C2531 P56897 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 422828 T1348 C2531 P56897 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 422829 T1348 C2531 P56897 oass.SolrIndexSearcher.<init> Opening Searcher@287a6623 main
[junit4:junit4] 2> 422830 T1347 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@287a6623 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 422830 T1348 C2531 P56897 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty5/index.20130616204515066 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty5/index.20130616204515066;done=true>>]
[junit4:junit4] 2> 422830 T1348 C2531 P56897 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty5/index.20130616204515066
[junit4:junit4] 2> 422830 T1348 C2531 P56897 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty5/index.20130616204515066
[junit4:junit4] 2> 422831 T1348 C2531 P56897 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 422831 T1348 C2531 P56897 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 422831 T1348 C2531 P56897 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 422831 T1348 C2531 P56897 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 422833 T1348 C2531 P56897 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 422945 T1365 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371408312034/collection1
[junit4:junit4] 2> 422945 T1365 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 422946 T1365 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 422946 T1365 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 422947 T1365 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371408312034/collection1/'
[junit4:junit4] 2> 422947 T1365 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371408312034/collection1/lib/README' to classloader
[junit4:junit4] 2> 422948 T1365 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371408312034/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 422972 T1365 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 422998 T1365 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 423000 T1365 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 423003 T1365 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 423312 T1365 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 423317 T1365 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 423319 T1365 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 423330 T1365 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 423333 T1365 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 423335 T1365 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 423336 T1365 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 423337 T1365 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 423337 T1365 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 423338 T1365 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 423338 T1365 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 423338 T1365 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 423338 T1365 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371408312034/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty6/
[junit4:junit4] 2> 423338 T1365 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1bac204f
[junit4:junit4] 2> 423339 T1365 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 423339 T1365 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty6
[junit4:junit4] 2> 423339 T1365 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty6/index/
[junit4:junit4] 2> 423339 T1365 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty6/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 423340 T1365 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty6/index
[junit4:junit4] 2> 423357 T1365 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 423357 T1365 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 423359 T1365 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 423360 T1365 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 423360 T1365 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 423361 T1365 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 423361 T1365 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 423361 T1365 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 423363 T1365 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 423363 T1365 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 423363 T1365 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 423365 T1365 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 423367 T1365 oass.SolrIndexSearcher.<init> Opening Searcher@2fa80105 main
[junit4:junit4] 2> 423368 T1365 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 423368 T1365 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 423372 T1368 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2fa80105 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 423373 T1365 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 423374 T1365 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:35261 collection:collection1 shard:shard2
[junit4:junit4] 2> 423376 T1365 oasc.ZkController.register We are http://127.0.0.1:35261/collection1/ and leader is http://127.0.0.1:33718/collection1/
[junit4:junit4] 2> 423376 T1365 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35261
[junit4:junit4] 2> 423377 T1365 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 423377 T1365 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2533 name=collection1 org.apache.solr.core.SolrCore@6acea4f5 url=http://127.0.0.1:35261/collection1 node=127.0.0.1:35261_ C2533_STATE=coll:collection1 core:collection1 props:{core=collection1, base_url=http://127.0.0.1:35261, state=down, collection=collection1, node_name=127.0.0.1:35261_}
[junit4:junit4] 2> 423377 T1369 C2533 P35261 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 423378 T1369 C2533 P35261 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 423378 T1365 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 423378 T1369 C2533 P35261 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 423378 T1369 C2533 P35261 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 423379 T1238 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 423379 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 423380 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 423380 T1369 C2533 P35261 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 423386 T1308 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 423456 T1238 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 423458 T1238 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:44443
[junit4:junit4] 2> 423458 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 423459 T1238 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 423459 T1238 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371408315637
[junit4:junit4] 2> 423459 T1238 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371408315637/solr.xml
[junit4:junit4] 2> 423459 T1238 oasc.CoreContainer.<init> New CoreContainer 1808499534
[junit4:junit4] 2> 423460 T1238 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371408315637/'
[junit4:junit4] 2> 423460 T1238 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371408315637/'
[junit4:junit4] 2> 423497 T1238 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 423498 T1238 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 423498 T1238 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 423498 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 423498 T1238 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 423499 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 423499 T1238 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 423499 T1238 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 423499 T1238 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 423500 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 423502 T1238 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 423503 T1238 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53059/solr
[junit4:junit4] 2> 423503 T1238 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 423504 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 423505 T1381 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7b4192b2 name:ZooKeeperConnection Watcher:127.0.0.1:53059 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 423506 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 423507 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 423510 T1238 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 423511 T1383 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5dee98d3 name:ZooKeeperConnection Watcher:127.0.0.1:53059/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 423511 T1238 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 423514 T1238 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 423729 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 423731 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56897",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "node_name":"127.0.0.1:56897_"}
[junit4:junit4] 2> 423736 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35261",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core_node_name":"7",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:35261_"}
[junit4:junit4] 2> 423741 T1260 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> 423741 T1280 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> 423741 T1362 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> 423742 T1328 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> 423741 T1267 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> 423741 T1383 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> 423741 T1296 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> 423742 T1312 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> 423742 T1345 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> 424386 T1308 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 424387 T1308 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={core=collection1&checkLive=true&onlyIfLeader=true&state=recovering&nodeName=127.0.0.1:35261_&coreNodeName=7&wt=javabin&version=2&action=PREPRECOVERY} status=0 QTime=1001
[junit4:junit4] 2> 424517 T1238 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44443_
[junit4:junit4] 2> 424519 T1238 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:44443_
[junit4:junit4] 2> 424520 T1328 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> 424521 T1280 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> 424521 T1267 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> 424521 T1296 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> 424521 T1345 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 424521 T1312 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 424522 T1362 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 424522 T1260 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 424522 T1260 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> 424522 T1383 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 424522 T1383 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> 424522 T1345 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> 424522 T1362 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> 424523 T1328 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 424522 T1312 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> 424523 T1280 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 424524 T1267 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 424524 T1296 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 424528 T1384 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 424528 T1384 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 425251 T1261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 425252 T1261 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44443",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core_node_name":"8",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44443_"}
[junit4:junit4] 2> 425252 T1261 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 425252 T1261 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 425256 T1260 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> 425256 T1296 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> 425257 T1328 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> 425257 T1312 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> 425257 T1383 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> 425256 T1362 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> 425256 T1267 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> 425256 T1280 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> 425257 T1345 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> 425530 T1384 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371408315637/collection1
[junit4:junit4] 2> 425530 T1384 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 425531 T1384 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 425531 T1384 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 425532 T1384 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371408315637/collection1/'
[junit4:junit4] 2> 425533 T1384 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371408315637/collection1/lib/README' to classloader
[junit4:junit4] 2> 425533 T1384 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371408315637/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 425568 T1384 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 425593 T1384 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 425595 T1384 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 425597 T1384 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 425877 T1384 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 425882 T1384 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 425884 T1384 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 425897 T1384 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 425899 T1384 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 425902 T1384 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 425903 T1384 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 425904 T1384 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 425904 T1384 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 425905 T1384 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 425905 T1384 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 425905 T1384 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 425906 T1384 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371408315637/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty7/
[junit4:junit4] 2> 425906 T1384 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1bac204f
[junit4:junit4] 2> 425906 T1384 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 425907 T1384 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty7
[junit4:junit4] 2> 425907 T1384 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty7/index/
[junit4:junit4] 2> 425907 T1384 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty7/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 425907 T1384 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty7/index
[junit4:junit4] 2> 425910 T1384 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty7/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 425910 T1384 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 425912 T1384 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 425912 T1384 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 425913 T1384 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 425913 T1384 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 425914 T1384 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 425914 T1384 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 425914 T1384 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 425914 T1384 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 425915 T1384 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 425916 T1384 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 425918 T1384 oass.SolrIndexSearcher.<init> Opening Searcher@2f2e15c0 main
[junit4:junit4] 2> 425919 T1384 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 425919 T1384 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 425922 T1385 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2f2e15c0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 425924 T1384 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 425924 T1384 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:44443 collection:collection1 shard:shard1
[junit4:junit4] 2> 425927 T1384 oasc.ZkController.register We are http://127.0.0.1:44443/collection1/ and leader is http://127.0.0.1:44898/collection1/
[junit4:junit4] 2> 425927 T1384 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44443
[junit4:junit4] 2> 425927 T1384 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 425927 T1384 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2534 name=collection1 org.apache.solr.core.SolrCore@648d4814 url=http://127.0.0.1:44443/collection1 node=127.0.0.1:44443_ C2534_STATE=coll:collection1 core:collection1 props:{core=collection1, base_url=http://127.0.0.1:44443, state=down, collection=collection1, node_name=127.0.0.1:44443_}
[junit4:junit4] 2> 425928 T1386 C2534 P44443 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 425928 T1386 C2534 P44443 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 425928 T1386 C2534 P44443 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 425928 T1384 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 425928 T1386 C2534 P44443 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 425929 T1238 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 425930 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 425929 T1386 C2534 P44443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 425930 T1238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 425935 T1276 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 8, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 426012 T1238 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 426014 T1238 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49052
[junit4:junit4] 2> 426015 T1238 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 426015 T1238 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 426015 T1238 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Lin
[...truncated too long message...]
numShards=null message={
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58981",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core_node_name":"12",
[junit4:junit4] 2> "numShards":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "node_name":"127.0.0.1:58981_"}
[junit4:junit4] 2> 562756 T1238 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 562757 T1476 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> 562807 T1238 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 37851
[junit4:junit4] 2> 562807 T1238 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=2144954026
[junit4:junit4] 2> 563809 T1238 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 563810 T1238 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 563811 T1238 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@47f4d781
[junit4:junit4] 2> 563819 T1238 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=624,cumulative_deletesById=276,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 563820 T1238 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 563820 T1238 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 563820 T1238 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 563821 T1238 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 563821 T1238 oasc.CachingDirectoryFactory.close Closing StandardDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 563822 T1238 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty12/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty12/index;done=false>>]
[junit4:junit4] 2> 563822 T1238 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty12/index
[junit4:junit4] 2> 563822 T1238 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty12 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty12;done=false>>]
[junit4:junit4] 2> 563822 T1238 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371408294390/jetty12
[junit4:junit4] 2> 563823 T1741 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89876613981274140-127.0.0.1:37851_-n_0000000012) am no longer a leader.
[junit4:junit4] 2> 563845 T1238 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 563932 T1238 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 563934 T1238 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:53059 53059
[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=7FBFA98732E885AA -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=lv -Dtests.timezone=Europe/Luxembourg -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 162s J1 | ChaosMonkeySafeLeaderTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard2 is not consistent. Got 350 from http://127.0.0.1:34539/collection1lastClient and got 348 from http://127.0.0.1:37851/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([7FBFA98732E885AA:FE59279F45B7E596]: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:724)
[junit4:junit4] 2> 563942 T1238 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 161814 T1237 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 564034 T1459 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 564034 T1459 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> 564035 T1459 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 565124 T1476 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 565124 T1476 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> 565124 T1476 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {range_facet_sl=PostingsFormat(name=Lucene41WithOrds), other_tl1=PostingsFormat(name=NestedPulsing), range_facet_si=Lucene41(blocksize=128), multiDefault=Lucene41(blocksize=128), _version_=PostingsFormat(name=NestedPulsing), rnd_b=PostingsFormat(name=MockSep), timestamp=PostingsFormat(name=NestedPulsing), a_si=Lucene41(blocksize=128), a_t=PostingsFormat(name=NestedPulsing), intDefault=PostingsFormat(name=NestedPulsing), text=PostingsFormat(name=Lucene41WithOrds), id=PostingsFormat(name=MockSep), range_facet_l=PostingsFormat(name=NestedPulsing)}, docValues:{}, sim=DefaultSimilarity, locale=lv, timezone=Europe/Luxembourg
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic amd64/Oracle Corporation 1.8.0-ea (64-bit)/cpus=8,threads=3,free=101015056,total=335675392
[junit4:junit4] 2> NOTE: All tests run in this JVM: [ShardRoutingCustomTest, TestSolrJ, NoCacheHeaderTest, TestUpdate, FullSolrCloudDistribCmdsTest, BasicZkTest, TestElisionMultitermQuery, TestQueryTypes, TestFoldingMultitermQuery, SpellCheckComponentTest, TestDistributedSearch, TestNumberUtils, TestSolrQueryParserResource, TestArbitraryIndexDir, DistanceFunctionTest, NotRequiredUniqueKeyTest, TestCollationKeyRangeQueries, FileUtilsTest, DirectUpdateHandlerTest, TestZkChroot, DisMaxRequestHandlerTest, TestHashPartitioner, TestClassNameShortening, PingRequestHandlerTest, TestUtils, TestRandomFaceting, TestCollationField, CurrencyFieldXmlFileTest, DocValuesMultiTest, ClusterStateTest, TestPropInject, SolrCmdDistributorTest, TestAnalyzedSuggestions, OpenCloseCoreStressTest, SpellPossibilityIteratorTest, TestLuceneMatchVersion, TestRecovery, TestSolrXMLSerializer, UniqFieldsUpdateProcessorFactoryTest, MultiTermTest, IndexReaderFactoryTest, ConvertedLegacyTest, DocumentAnalysisRequestHandlerTest, TestDefaultSimilarityFactory, TestReload, TimeZoneUtilsTest, TestSolr4Spatial, SolrIndexConfigTest, TestShardHandlerFactory, TestIndexSearcher, TestSuggestSpellingConverter, TestBinaryResponseWriter, TestJmxIntegration, TestSchemaResource, ChaosMonkeySafeLeaderTest]
[junit4:junit4] Completed on J1 in 163.09s, 1 test, 1 failure <<< FAILURES!
[...truncated 490 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:392: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:372: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1246: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:890: There were test failures: 297 suites, 1246 tests, 1 failure, 16 ignored (7 assumptions)
Total time: 35 minutes 22 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.8.0-ea-b93 -XX:+UseCompressedOops -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure