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 18:00:03 UTC
[JENKINS] Lucene-Solr-4.x-Linux (64bit/jdk1.6.0_45) - Build # 6095
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/6095/
Java: 64bit/jdk1.6.0_45 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.testDistribSearch
Error Message:
shard3 is not consistent. Got 67 from http://127.0.0.1:49899/collection1lastClient and got 65 from http://127.0.0.1:51098/collection1
Stack Trace:
java.lang.AssertionError: shard3 is not consistent. Got 67 from http://127.0.0.1:49899/collection1lastClient and got 65 from http://127.0.0.1:51098/collection1
at __randomizedtesting.SeedInfo.seed([AD4107D3BC660698:2CA789CBCB3966A4]: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:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:662)
Build Log:
[...truncated 9019 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
[junit4:junit4] 2> 428103 T1780 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 428110 T1780 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-1371397429222
[junit4:junit4] 2> 428111 T1780 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 428112 T1781 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 428212 T1780 oasc.ZkTestServer.run start zk server on port:53240
[junit4:junit4] 2> 428213 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 428274 T1787 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@17515776 name:ZooKeeperConnection Watcher:127.0.0.1:53240 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 428274 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 428274 T1780 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 428279 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 428280 T1789 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4bf1b8d4 name:ZooKeeperConnection Watcher:127.0.0.1:53240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 428280 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 428280 T1780 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 428283 T1780 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 428285 T1780 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 428287 T1780 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 428289 T1780 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> 428289 T1780 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 428293 T1780 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> 428293 T1780 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 428296 T1780 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> 428296 T1780 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 428298 T1780 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> 428299 T1780 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 428300 T1780 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> 428301 T1780 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 428305 T1780 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> 428306 T1780 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 428308 T1780 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> 428308 T1780 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 428310 T1780 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> 428311 T1780 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 428312 T1780 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> 428313 T1780 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 428390 T1780 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 428410 T1780 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:37963
[junit4:junit4] 2> 428411 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 428411 T1780 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 428412 T1780 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-1371397429426
[junit4:junit4] 2> 428412 T1780 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-1371397429426/solr.xml
[junit4:junit4] 2> 428412 T1780 oasc.CoreContainer.<init> New CoreContainer 1341763828
[junit4:junit4] 2> 428413 T1780 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-1371397429426/'
[junit4:junit4] 2> 428413 T1780 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-1371397429426/'
[junit4:junit4] 2> 428470 T1780 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 428470 T1780 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 428471 T1780 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 428471 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 428471 T1780 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 428472 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 428472 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 428472 T1780 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 428473 T1780 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 428473 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 428476 T1780 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 428476 T1780 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53240/solr
[junit4:junit4] 2> 428477 T1780 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 428478 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 428479 T1800 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2fcedbc name:ZooKeeperConnection Watcher:127.0.0.1:53240 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 428479 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 428481 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 428484 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 428485 T1802 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3e1425f0 name:ZooKeeperConnection Watcher:127.0.0.1:53240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 428486 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 428487 T1780 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 428490 T1780 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 428492 T1780 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 428493 T1780 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37963_
[junit4:junit4] 2> 428494 T1780 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:37963_
[junit4:junit4] 2> 428496 T1780 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 428500 T1780 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 428502 T1780 oasc.Overseer.start Overseer (id=89875901921624067-127.0.0.1:37963_-n_0000000000) starting
[junit4:junit4] 2> 428505 T1780 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 428508 T1804 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 428508 T1780 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 428517 T1780 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 428519 T1780 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 428521 T1803 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 428523 T1805 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 428524 T1805 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 430024 T1803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 430025 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:37963_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:37963"}
[junit4:junit4] 2> 430025 T1803 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 430026 T1803 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 430028 T1802 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> 430525 T1805 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-1371397429426/collection1
[junit4:junit4] 2> 430525 T1805 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 430526 T1805 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 430526 T1805 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 430527 T1805 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-1371397429426/collection1/'
[junit4:junit4] 2> 430528 T1805 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-1371397429426/collection1/lib/README' to classloader
[junit4:junit4] 2> 430528 T1805 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-1371397429426/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 430561 T1805 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 430617 T1805 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 430618 T1805 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 430622 T1805 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 431147 T1805 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 431153 T1805 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 431156 T1805 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 431167 T1805 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 431171 T1805 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 431174 T1805 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 431175 T1805 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 431175 T1805 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 431175 T1805 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 431176 T1805 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 431176 T1805 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 431177 T1805 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 431184 T1805 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-1371397429426/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/control/data/
[junit4:junit4] 2> 431184 T1805 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4f536eec
[junit4:junit4] 2> 431185 T1805 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 431185 T1805 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-1371397429222/control/data
[junit4:junit4] 2> 431185 T1805 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/control/data/index/
[junit4:junit4] 2> 431186 T1805 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 431186 T1805 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-1371397429222/control/data/index
[junit4:junit4] 2> 431189 T1805 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-1371397429222/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 431189 T1805 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 431191 T1805 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 431192 T1805 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 431192 T1805 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 431193 T1805 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 431193 T1805 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 431194 T1805 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 431194 T1805 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 431194 T1805 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 431195 T1805 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 431197 T1805 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 431200 T1805 oass.SolrIndexSearcher.<init> Opening Searcher@73d4e056 main
[junit4:junit4] 2> 431200 T1805 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 431201 T1805 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 431210 T1806 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@73d4e056 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 431211 T1805 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 431212 T1805 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:37963 collection:control_collection shard:shard1
[junit4:junit4] 2> 431212 T1805 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 431217 T1805 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 431218 T1805 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 431218 T1805 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 431219 T1805 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:37963/collection1/
[junit4:junit4] 2> 431219 T1805 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 431219 T1805 oasc.SyncStrategy.syncToMe http://127.0.0.1:37963/collection1/ has no replicas
[junit4:junit4] 2> 431219 T1805 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:37963/collection1/
[junit4:junit4] 2> 431219 T1805 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 431533 T1803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 431539 T1802 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> 431574 T1805 oasc.ZkController.register We are http://127.0.0.1:37963/collection1/ and leader is http://127.0.0.1:37963/collection1/
[junit4:junit4] 2> 431575 T1805 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:37963
[junit4:junit4] 2> 431575 T1805 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 431575 T1805 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 431575 T1805 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 431577 T1805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 431578 T1780 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 431578 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 431578 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 431581 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 431583 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 431585 T1809 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1568339e name:ZooKeeperConnection Watcher:127.0.0.1:53240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 431585 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 431586 T1780 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 431588 T1780 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 431654 T1780 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 431656 T1780 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:38184
[junit4:junit4] 2> 431657 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 431657 T1780 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 431657 T1780 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-1371397432700
[junit4:junit4] 2> 431658 T1780 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-1371397432700/solr.xml
[junit4:junit4] 2> 431658 T1780 oasc.CoreContainer.<init> New CoreContainer 1109631126
[junit4:junit4] 2> 431658 T1780 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-1371397432700/'
[junit4:junit4] 2> 431659 T1780 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-1371397432700/'
[junit4:junit4] 2> 431730 T1780 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 431731 T1780 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 431731 T1780 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 431731 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 431732 T1780 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 431732 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 431733 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 431733 T1780 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 431733 T1780 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 431734 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 431737 T1780 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 431737 T1780 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53240/solr
[junit4:junit4] 2> 431737 T1780 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 431738 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 431740 T1820 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8c1b982 name:ZooKeeperConnection Watcher:127.0.0.1:53240 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 431741 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 431743 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 431745 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 431746 T1822 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@65ba368a name:ZooKeeperConnection Watcher:127.0.0.1:53240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 431747 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 431750 T1780 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 432752 T1780 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38184_
[junit4:junit4] 2> 432754 T1780 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38184_
[junit4:junit4] 2> 432758 T1802 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 432758 T1809 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 432758 T1802 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> 432758 T1822 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 432762 T1823 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 432762 T1823 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 433043 T1803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 433044 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:37963_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:37963"}
[junit4:junit4] 2> 433049 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:38184_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38184"}
[junit4:junit4] 2> 433049 T1803 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 3
[junit4:junit4] 2> 433050 T1803 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 433057 T1822 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> 433057 T1802 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> 433057 T1809 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> 433763 T1823 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-1371397432700/collection1
[junit4:junit4] 2> 433764 T1823 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 433765 T1823 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 433765 T1823 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 433766 T1823 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-1371397432700/collection1/'
[junit4:junit4] 2> 433767 T1823 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-1371397432700/collection1/lib/README' to classloader
[junit4:junit4] 2> 433768 T1823 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-1371397432700/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 433823 T1823 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 433868 T1823 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 433870 T1823 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 433873 T1823 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 434517 T1823 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 434536 T1823 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 434541 T1823 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 434560 T1823 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 434564 T1823 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 434567 T1823 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 434568 T1823 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 434569 T1823 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 434569 T1823 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 434570 T1823 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 434570 T1823 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 434571 T1823 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 434571 T1823 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-1371397432700/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty1/
[junit4:junit4] 2> 434571 T1823 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4f536eec
[junit4:junit4] 2> 434572 T1823 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 434572 T1823 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-1371397429222/jetty1
[junit4:junit4] 2> 434572 T1823 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty1/index/
[junit4:junit4] 2> 434573 T1823 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 434573 T1823 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-1371397429222/jetty1/index
[junit4:junit4] 2> 434606 T1823 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-1371397429222/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 434606 T1823 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 434608 T1823 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 434609 T1823 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 434609 T1823 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 434610 T1823 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 434610 T1823 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 434611 T1823 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 434611 T1823 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 434611 T1823 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 434612 T1823 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 434614 T1823 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 434618 T1823 oass.SolrIndexSearcher.<init> Opening Searcher@6438ec85 main
[junit4:junit4] 2> 434619 T1823 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 434619 T1823 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 434625 T1824 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6438ec85 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 434629 T1823 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 434629 T1823 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38184 collection:collection1 shard:shard1
[junit4:junit4] 2> 434630 T1823 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 434635 T1823 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 434637 T1823 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 434637 T1823 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 434638 T1823 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:38184/collection1/
[junit4:junit4] 2> 434638 T1823 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 434638 T1823 oasc.SyncStrategy.syncToMe http://127.0.0.1:38184/collection1/ has no replicas
[junit4:junit4] 2> 434638 T1823 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:38184/collection1/
[junit4:junit4] 2> 434638 T1823 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 436064 T1803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 436071 T1822 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> 436071 T1802 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> 436071 T1809 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> 436098 T1823 oasc.ZkController.register We are http://127.0.0.1:38184/collection1/ and leader is http://127.0.0.1:38184/collection1/
[junit4:junit4] 2> 436098 T1823 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38184
[junit4:junit4] 2> 436099 T1823 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 436099 T1823 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 436099 T1823 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 436101 T1823 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 436109 T1780 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 436110 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 436110 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 436214 T1780 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 436216 T1780 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52812
[junit4:junit4] 2> 436217 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 436217 T1780 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 436218 T1780 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-1371397437224
[junit4:junit4] 2> 436218 T1780 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-1371397437224/solr.xml
[junit4:junit4] 2> 436218 T1780 oasc.CoreContainer.<init> New CoreContainer 1874901094
[junit4:junit4] 2> 436219 T1780 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-1371397437224/'
[junit4:junit4] 2> 436219 T1780 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-1371397437224/'
[junit4:junit4] 2> 436298 T1780 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 436299 T1780 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 436300 T1780 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 436300 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 436301 T1780 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 436301 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 436302 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 436302 T1780 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 436303 T1780 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 436304 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 436308 T1780 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 436309 T1780 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53240/solr
[junit4:junit4] 2> 436310 T1780 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 436311 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 436312 T1836 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@51898d80 name:ZooKeeperConnection Watcher:127.0.0.1:53240 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 436313 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 436316 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 436321 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 436322 T1838 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5c4d0f8c name:ZooKeeperConnection Watcher:127.0.0.1:53240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 436322 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 436327 T1780 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 437336 T1780 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52812_
[junit4:junit4] 2> 437338 T1780 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52812_
[junit4:junit4] 2> 437340 T1822 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> 437340 T1809 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> 437343 T1802 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 437343 T1838 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 437343 T1802 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> 437344 T1822 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 437345 T1809 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 437348 T1839 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 437348 T1839 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 437580 T1803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 437581 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:38184_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38184"}
[junit4:junit4] 2> 437584 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:52812_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52812"}
[junit4:junit4] 2> 437585 T1803 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 437585 T1803 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 437588 T1809 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> 437588 T1802 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> 437588 T1838 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> 437588 T1822 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> 438350 T1839 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-1371397437224/collection1
[junit4:junit4] 2> 438350 T1839 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 438351 T1839 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 438351 T1839 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 438352 T1839 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-1371397437224/collection1/'
[junit4:junit4] 2> 438353 T1839 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-1371397437224/collection1/lib/README' to classloader
[junit4:junit4] 2> 438354 T1839 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-1371397437224/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 438405 T1839 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 438472 T1839 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 438474 T1839 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 438479 T1839 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 439081 T1839 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 439089 T1839 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 439093 T1839 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 439117 T1839 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 439121 T1839 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 439125 T1839 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 439127 T1839 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 439130 T1839 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 439131 T1839 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 439132 T1839 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 439132 T1839 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 439132 T1839 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 439133 T1839 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-1371397437224/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty2/
[junit4:junit4] 2> 439133 T1839 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4f536eec
[junit4:junit4] 2> 439134 T1839 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 439134 T1839 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-1371397429222/jetty2
[junit4:junit4] 2> 439135 T1839 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty2/index/
[junit4:junit4] 2> 439135 T1839 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 439135 T1839 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-1371397429222/jetty2/index
[junit4:junit4] 2> 439139 T1839 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-1371397429222/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 439139 T1839 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 439141 T1839 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 439141 T1839 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 439142 T1839 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 439146 T1839 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 439148 T1839 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 439148 T1839 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 439148 T1839 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 439149 T1839 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 439149 T1839 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 439151 T1839 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 439154 T1839 oass.SolrIndexSearcher.<init> Opening Searcher@682efb74 main
[junit4:junit4] 2> 439155 T1839 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 439155 T1839 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 439160 T1840 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@682efb74 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 439162 T1839 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 439162 T1839 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52812 collection:collection1 shard:shard2
[junit4:junit4] 2> 439163 T1839 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 439172 T1839 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 439174 T1839 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 439174 T1839 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 439174 T1839 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52812/collection1/
[junit4:junit4] 2> 439175 T1839 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 439175 T1839 oasc.SyncStrategy.syncToMe http://127.0.0.1:52812/collection1/ has no replicas
[junit4:junit4] 2> 439175 T1839 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52812/collection1/
[junit4:junit4] 2> 439175 T1839 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 440596 T1803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 440603 T1809 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> 440603 T1802 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> 440603 T1822 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> 440603 T1838 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> 440631 T1839 oasc.ZkController.register We are http://127.0.0.1:52812/collection1/ and leader is http://127.0.0.1:52812/collection1/
[junit4:junit4] 2> 440632 T1839 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52812
[junit4:junit4] 2> 440632 T1839 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 440632 T1839 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 440632 T1839 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 440634 T1839 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 440635 T1780 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 440635 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 440636 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 440723 T1780 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 440726 T1780 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57878
[junit4:junit4] 2> 440726 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 440727 T1780 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 440727 T1780 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-1371397441749
[junit4:junit4] 2> 440728 T1780 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-1371397441749/solr.xml
[junit4:junit4] 2> 440728 T1780 oasc.CoreContainer.<init> New CoreContainer 1580675587
[junit4:junit4] 2> 440728 T1780 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-1371397441749/'
[junit4:junit4] 2> 440729 T1780 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-1371397441749/'
[junit4:junit4] 2> 440790 T1780 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 440791 T1780 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 440791 T1780 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 440792 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 440792 T1780 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 440792 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 440793 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 440793 T1780 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 440793 T1780 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 440794 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 440797 T1780 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 440797 T1780 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53240/solr
[junit4:junit4] 2> 440798 T1780 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 440799 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 440800 T1852 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f7d3aef name:ZooKeeperConnection Watcher:127.0.0.1:53240 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 440801 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 440803 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 440806 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 440808 T1854 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7e32d97 name:ZooKeeperConnection Watcher:127.0.0.1:53240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 440808 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 440812 T1780 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 441821 T1780 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57878_
[junit4:junit4] 2> 441823 T1780 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57878_
[junit4:junit4] 2> 441825 T1822 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> 441825 T1809 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> 441826 T1802 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 441827 T1802 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> 441827 T1854 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 441827 T1838 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 441827 T1838 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> 441829 T1822 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 441829 T1809 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 441834 T1855 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 441835 T1855 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 442108 T1803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 442109 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:52812_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52812"}
[junit4:junit4] 2> 442112 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:57878_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57878"}
[junit4:junit4] 2> 442112 T1803 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 442112 T1803 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 442116 T1854 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> 442116 T1822 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> 442117 T1802 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> 442117 T1809 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> 442116 T1838 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> 442837 T1855 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-1371397441749/collection1
[junit4:junit4] 2> 442837 T1855 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 442838 T1855 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 442838 T1855 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 442839 T1855 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-1371397441749/collection1/'
[junit4:junit4] 2> 442839 T1855 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-1371397441749/collection1/lib/README' to classloader
[junit4:junit4] 2> 442840 T1855 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-1371397441749/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 442878 T1855 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 442934 T1855 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 442935 T1855 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 442940 T1855 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 443566 T1855 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 443573 T1855 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 443577 T1855 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 443596 T1855 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 443599 T1855 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 443602 T1855 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 443603 T1855 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 443604 T1855 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 443604 T1855 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 443607 T1855 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 443607 T1855 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 443608 T1855 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 443608 T1855 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-1371397441749/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty3/
[junit4:junit4] 2> 443608 T1855 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4f536eec
[junit4:junit4] 2> 443609 T1855 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 443609 T1855 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-1371397429222/jetty3
[junit4:junit4] 2> 443610 T1855 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty3/index/
[junit4:junit4] 2> 443610 T1855 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 443611 T1855 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-1371397429222/jetty3/index
[junit4:junit4] 2> 443618 T1855 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-1371397429222/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 443619 T1855 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 443622 T1855 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 443622 T1855 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 443623 T1855 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 443623 T1855 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 443624 T1855 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 443624 T1855 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 443624 T1855 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 443625 T1855 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 443633 T1855 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 443637 T1855 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 443642 T1855 oass.SolrIndexSearcher.<init> Opening Searcher@5e03cb03 main
[junit4:junit4] 2> 443643 T1855 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 443643 T1855 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 443649 T1856 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5e03cb03 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 443651 T1855 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 443652 T1855 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57878 collection:collection1 shard:shard3
[junit4:junit4] 2> 443654 T1855 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4:junit4] 2> 443665 T1855 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 443667 T1855 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 443668 T1855 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 443668 T1855 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:57878/collection1/
[junit4:junit4] 2> 443668 T1855 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 443668 T1855 oasc.SyncStrategy.syncToMe http://127.0.0.1:57878/collection1/ has no replicas
[junit4:junit4] 2> 443668 T1855 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:57878/collection1/
[junit4:junit4] 2> 443669 T1855 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4:junit4] 2> 445124 T1803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 445131 T1822 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> 445132 T1802 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> 445131 T1854 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> 445131 T1809 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> 445132 T1838 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> 445177 T1855 oasc.ZkController.register We are http://127.0.0.1:57878/collection1/ and leader is http://127.0.0.1:57878/collection1/
[junit4:junit4] 2> 445177 T1855 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57878
[junit4:junit4] 2> 445177 T1855 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 445177 T1855 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 445178 T1855 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 445179 T1855 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 445180 T1780 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 445180 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 445181 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 445262 T1780 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 445265 T1780 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53658
[junit4:junit4] 2> 445266 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 445267 T1780 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 445267 T1780 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-1371397446296
[junit4:junit4] 2> 445268 T1780 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-1371397446296/solr.xml
[junit4:junit4] 2> 445268 T1780 oasc.CoreContainer.<init> New CoreContainer 1512492983
[junit4:junit4] 2> 445269 T1780 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-1371397446296/'
[junit4:junit4] 2> 445270 T1780 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-1371397446296/'
[junit4:junit4] 2> 445331 T1780 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 445331 T1780 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 445332 T1780 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 445332 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 445333 T1780 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 445333 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 445334 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 445334 T1780 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 445335 T1780 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 445336 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 445340 T1780 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 445341 T1780 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53240/solr
[junit4:junit4] 2> 445341 T1780 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 445343 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 445344 T1868 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4a46cea8 name:ZooKeeperConnection Watcher:127.0.0.1:53240 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 445344 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 445346 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 445350 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 445352 T1870 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@76bd8a1b name:ZooKeeperConnection Watcher:127.0.0.1:53240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 445352 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 445355 T1780 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 446358 T1780 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53658_
[junit4:junit4] 2> 446359 T1780 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53658_
[junit4:junit4] 2> 446361 T1822 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> 446362 T1809 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> 446363 T1854 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> 446363 T1802 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 446363 T1870 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 446363 T1802 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> 446364 T1838 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 446364 T1838 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> 446365 T1822 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 446373 T1809 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 446373 T1854 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 446556 T1871 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 446557 T1871 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 446637 T1803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 446638 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:57878_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57878"}
[junit4:junit4] 2> 446641 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53658_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53658"}
[junit4:junit4] 2> 446641 T1803 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 446641 T1803 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 446644 T1870 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> 446644 T1809 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> 446645 T1838 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> 446645 T1822 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> 446645 T1854 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> 446645 T1802 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> 447559 T1871 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-1371397446296/collection1
[junit4:junit4] 2> 447559 T1871 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 447560 T1871 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 447560 T1871 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 447562 T1871 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-1371397446296/collection1/'
[junit4:junit4] 2> 447562 T1871 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-1371397446296/collection1/lib/README' to classloader
[junit4:junit4] 2> 447562 T1871 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-1371397446296/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 447601 T1871 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 447649 T1871 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 447650 T1871 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 447654 T1871 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 448207 T1871 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 448213 T1871 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 448216 T1871 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 448229 T1871 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 448233 T1871 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 448238 T1871 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 448239 T1871 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 448240 T1871 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 448240 T1871 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 448242 T1871 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 448242 T1871 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 448242 T1871 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 448243 T1871 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-1371397446296/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty4/
[junit4:junit4] 2> 448243 T1871 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4f536eec
[junit4:junit4] 2> 448244 T1871 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 448244 T1871 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-1371397429222/jetty4
[junit4:junit4] 2> 448244 T1871 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty4/index/
[junit4:junit4] 2> 448245 T1871 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 448245 T1871 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-1371397429222/jetty4/index
[junit4:junit4] 2> 448249 T1871 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-1371397429222/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 448249 T1871 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 448252 T1871 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 448252 T1871 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 448253 T1871 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 448254 T1871 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 448254 T1871 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 448255 T1871 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 448255 T1871 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 448256 T1871 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 448256 T1871 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 448259 T1871 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 448263 T1871 oass.SolrIndexSearcher.<init> Opening Searcher@6122b55d main
[junit4:junit4] 2> 448264 T1871 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 448264 T1871 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 448277 T1872 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6122b55d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 448279 T1871 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 448279 T1871 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53658 collection:collection1 shard:shard1
[junit4:junit4] 2> 448282 T1871 oasc.ZkController.register We are http://127.0.0.1:53658/collection1/ and leader is http://127.0.0.1:38184/collection1/
[junit4:junit4] 2> 448282 T1871 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53658
[junit4:junit4] 2> 448282 T1871 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 448282 T1871 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2880 name=collection1 org.apache.solr.core.SolrCore@a058635 url=http://127.0.0.1:53658/collection1 node=127.0.0.1:53658_ C2880_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:53658_, base_url=http://127.0.0.1:53658}
[junit4:junit4] 2> 448283 T1873 C2880 P53658 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 448283 T1871 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 448283 T1873 C2880 P53658 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 448284 T1873 C2880 P53658 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 448284 T1873 C2880 P53658 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 448284 T1780 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 448285 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 448285 T1873 C2880 P53658 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 448285 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 448292 T1818 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 448364 T1780 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 448369 T1780 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:48185
[junit4:junit4] 2> 448370 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 448370 T1780 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 448370 T1780 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-1371397449400
[junit4:junit4] 2> 448371 T1780 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-1371397449400/solr.xml
[junit4:junit4] 2> 448371 T1780 oasc.CoreContainer.<init> New CoreContainer 1017310065
[junit4:junit4] 2> 448372 T1780 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-1371397449400/'
[junit4:junit4] 2> 448372 T1780 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-1371397449400/'
[junit4:junit4] 2> 448444 T1780 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 448445 T1780 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 448445 T1780 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 448445 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 448446 T1780 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 448446 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 448446 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 448447 T1780 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 448447 T1780 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 448447 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 448450 T1780 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 448451 T1780 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53240/solr
[junit4:junit4] 2> 448452 T1780 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 448453 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 448455 T1885 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@36091576 name:ZooKeeperConnection Watcher:127.0.0.1:53240 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 448456 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 448461 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 448464 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 448467 T1887 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@53ed8bc name:ZooKeeperConnection Watcher:127.0.0.1:53240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 448467 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 448471 T1780 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 449473 T1780 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:48185_
[junit4:junit4] 2> 449475 T1780 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:48185_
[junit4:junit4] 2> 449477 T1809 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> 449477 T1854 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> 449478 T1822 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> 449479 T1838 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 449479 T1838 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> 449479 T1870 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 449480 T1887 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 449479 T1802 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 449480 T1802 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> 449480 T1870 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> 449481 T1822 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 449481 T1854 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 449481 T1809 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 449486 T1888 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 449487 T1888 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 449654 T1803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 449654 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53658_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53658"}
[junit4:junit4] 2> 449657 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:48185_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48185"}
[junit4:junit4] 2> 449657 T1803 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 449658 T1803 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 449661 T1870 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> 449661 T1822 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> 449661 T1809 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> 449661 T1802 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> 449661 T1854 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> 449661 T1887 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> 449661 T1838 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> 450293 T1818 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 450293 T1818 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:53658_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2001
[junit4:junit4] 2> 450488 T1888 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-1371397449400/collection1
[junit4:junit4] 2> 450488 T1888 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 450489 T1888 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 450489 T1888 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 450490 T1888 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-1371397449400/collection1/'
[junit4:junit4] 2> 450491 T1888 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-1371397449400/collection1/lib/README' to classloader
[junit4:junit4] 2> 450491 T1888 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-1371397449400/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 450534 T1888 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 450576 T1888 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 450578 T1888 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 450582 T1888 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 451039 T1888 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 451052 T1888 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 451054 T1888 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 451064 T1888 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 451067 T1888 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 451071 T1888 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 451072 T1888 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 451072 T1888 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 451073 T1888 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 451074 T1888 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 451074 T1888 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 451074 T1888 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 451074 T1888 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-1371397449400/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty5/
[junit4:junit4] 2> 451074 T1888 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4f536eec
[junit4:junit4] 2> 451075 T1888 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 451075 T1888 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-1371397429222/jetty5
[junit4:junit4] 2> 451075 T1888 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty5/index/
[junit4:junit4] 2> 451076 T1888 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 451076 T1888 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-1371397429222/jetty5/index
[junit4:junit4] 2> 451079 T1888 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-1371397429222/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 451079 T1888 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 451081 T1888 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 451081 T1888 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 451082 T1888 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 451082 T1888 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 451083 T1888 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 451083 T1888 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 451083 T1888 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 451084 T1888 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 451084 T1888 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 451086 T1888 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 451088 T1888 oass.SolrIndexSearcher.<init> Opening Searcher@790f55e6 main
[junit4:junit4] 2> 451089 T1888 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 451089 T1888 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 451093 T1889 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@790f55e6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 451095 T1888 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 451095 T1888 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:48185 collection:collection1 shard:shard2
[junit4:junit4] 2> 451097 T1888 oasc.ZkController.register We are http://127.0.0.1:48185/collection1/ and leader is http://127.0.0.1:52812/collection1/
[junit4:junit4] 2> 451098 T1888 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:48185
[junit4:junit4] 2> 451098 T1888 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 451098 T1888 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2881 name=collection1 org.apache.solr.core.SolrCore@1af2b854 url=http://127.0.0.1:48185/collection1 node=127.0.0.1:48185_ C2881_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:48185_, base_url=http://127.0.0.1:48185}
[junit4:junit4] 2> 451098 T1890 C2881 P48185 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 451099 T1888 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 451099 T1890 C2881 P48185 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 451099 T1890 C2881 P48185 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 451099 T1890 C2881 P48185 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 451099 T1780 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 451100 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 451100 T1890 C2881 P48185 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 451100 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 451105 T1831 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 451168 T1803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 451169 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:48185_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48185"}
[junit4:junit4] 2> 451172 T1870 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> 451172 T1887 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> 451172 T1838 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> 451172 T1854 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> 451172 T1802 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> 451172 T1822 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> 451172 T1809 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> 451184 T1780 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 451186 T1780 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:46691
[junit4:junit4] 2> 451187 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 451187 T1780 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 451188 T1780 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-1371397452214
[junit4:junit4] 2> 451188 T1780 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-1371397452214/solr.xml
[junit4:junit4] 2> 451188 T1780 oasc.CoreContainer.<init> New CoreContainer 1530978093
[junit4:junit4] 2> 451189 T1780 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-1371397452214/'
[junit4:junit4] 2> 451189 T1780 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-1371397452214/'
[junit4:junit4] 2> 451245 T1780 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 451246 T1780 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 451246 T1780 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 451247 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 451247 T1780 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 451247 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 451248 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 451248 T1780 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 451248 T1780 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 451249 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 451252 T1780 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 451252 T1780 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53240/solr
[junit4:junit4] 2> 451252 T1780 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 451253 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 451255 T1902 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2d9199a3 name:ZooKeeperConnection Watcher:127.0.0.1:53240 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 451255 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 451258 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 451261 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 451262 T1904 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@274f60d4 name:ZooKeeperConnection Watcher:127.0.0.1:53240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 451262 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 451265 T1780 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 452106 T1831 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 452107 T1831 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=6&state=recovering&nodeName=127.0.0.1:48185_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 452268 T1780 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46691_
[junit4:junit4] 2> 452269 T1780 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46691_
[junit4:junit4] 2> 452272 T1854 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> 452273 T1822 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> 452274 T1809 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> 452274 T1838 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 452275 T1838 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> 452275 T1802 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 452275 T1887 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 452275 T1904 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 452275 T1870 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 452276 T1870 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> 452275 T1802 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> 452275 T1887 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> 452277 T1854 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 452278 T1809 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 452280 T1822 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 452283 T1905 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 452283 T1905 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> ASYNC NEW_CORE C2882 name=collection1 org.apache.solr.core.SolrCore@a058635 url=http://127.0.0.1:53658/collection1 node=127.0.0.1:53658_ C2882_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53658_, base_url=http://127.0.0.1:53658}
[junit4:junit4] 2> 452294 T1873 C2882 P53658 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:38184/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 452295 T1873 C2882 P53658 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53658 START replicas=[http://127.0.0.1:38184/collection1/] nUpdates=100
[junit4:junit4] 2> 452295 T1873 C2882 P53658 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 452296 T1873 C2882 P53658 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 452296 T1873 C2882 P53658 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 452296 T1873 C2882 P53658 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 452296 T1873 C2882 P53658 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 452297 T1873 C2882 P53658 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:38184/collection1/. core=collection1
[junit4:junit4] 2> 452297 T1873 C2882 P53658 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2883 name=collection1 org.apache.solr.core.SolrCore@1902536 url=http://127.0.0.1:38184/collection1 node=127.0.0.1:38184_ C2883_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:38184_, base_url=http://127.0.0.1:38184, leader=true}
[junit4:junit4] 2> 452302 T1818 C2883 P38184 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 452302 T1816 C2883 P38184 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 452305 T1816 C2883 P38184 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-1371397429222/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 452306 T1816 C2883 P38184 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 452313 T1816 C2883 P38184 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-1371397429222/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-1371397429222/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 452313 T1816 C2883 P38184 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 452315 T1816 C2883 P38184 oass.SolrIndexSearcher.<init> Opening Searcher@59129cbe realtime
[junit4:junit4] 2> 452315 T1816 C2883 P38184 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 452315 T1816 C2883 P38184 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 13
[junit4:junit4] 2> 452316 T1873 C2882 P53658 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 452316 T1873 C2882 P53658 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 452319 T1817 C2883 P38184 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 452319 T1817 C2883 P38184 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> ASYNC NEW_CORE C2884 name=collection1 org.apache.solr.core.SolrCore@a058635 url=http://127.0.0.1:53658/collection1 node=127.0.0.1:53658_ C2884_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53658_, base_url=http://127.0.0.1:53658}
[junit4:junit4] 2> 452326 T1873 C2884 P53658 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 452326 T1873 C2884 P53658 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 452326 T1873 C2884 P53658 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> ASYNC NEW_CORE C2885 name=collection1 org.apache.solr.core.SolrCore@1902536 url=http://127.0.0.1:38184/collection1 node=127.0.0.1:38184_ C2885_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:38184_, base_url=http://127.0.0.1:38184, leader=true}
[junit4:junit4] 2> 452329 T1818 C2885 P38184 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 452330 T1873 C2884 P53658 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 452330 T1873 C2884 P53658 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-1371397429222/jetty4/index.20130616034413441
[junit4:junit4] 2> 452331 T1873 C2884 P53658 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-1371397429222/jetty4/index.20130616034413441 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6369fec fullCopy=false
[junit4:junit4] 2> 452333 T1816 C2885 P38184 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 452335 T1873 C2884 P53658 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 452344 T1873 C2884 P53658 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 452344 T1873 C2884 P53658 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 452346 T1873 C2884 P53658 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-1371397429222/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-1371397429222/jetty4/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 452346 T1873 C2884 P53658 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 452346 T1873 C2884 P53658 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 452347 T1873 C2884 P53658 oass.SolrIndexSearcher.<init> Opening Searcher@40e4b035 main
[junit4:junit4] 2> 452348 T1872 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@40e4b035 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 452348 T1873 C2884 P53658 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-1371397429222/jetty4/index.20130616034413441 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty4/index.20130616034413441;done=true>>]
[junit4:junit4] 2> 452349 T1873 C2884 P53658 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-1371397429222/jetty4/index.20130616034413441
[junit4:junit4] 2> 452349 T1873 C2884 P53658 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-1371397429222/jetty4/index.20130616034413441
[junit4:junit4] 2> 452349 T1873 C2884 P53658 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 452349 T1873 C2884 P53658 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 452349 T1873 C2884 P53658 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 452350 T1873 C2884 P53658 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 452352 T1873 C2884 P53658 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 452677 T1803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 452677 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"7",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46691_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46691"}
[junit4:junit4] 2> 452678 T1803 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 452678 T1803 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 452680 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53658_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53658"}
[junit4:junit4] 2> 452684 T1870 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> 452684 T1838 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> 452684 T1809 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> 452684 T1822 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> 452684 T1887 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> 452684 T1854 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> 452684 T1802 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> 452684 T1904 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> 453285 T1905 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-1371397452214/collection1
[junit4:junit4] 2> 453285 T1905 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 453286 T1905 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 453286 T1905 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 453288 T1905 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-1371397452214/collection1/'
[junit4:junit4] 2> 453288 T1905 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-1371397452214/collection1/lib/README' to classloader
[junit4:junit4] 2> 453288 T1905 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-1371397452214/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 453324 T1905 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 453368 T1905 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 453369 T1905 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 453373 T1905 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 453855 T1905 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 453861 T1905 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 453864 T1905 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 453875 T1905 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 453878 T1905 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 453881 T1905 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 453882 T1905 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 453882 T1905 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 453882 T1905 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 453883 T1905 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 453883 T1905 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 453884 T1905 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 453884 T1905 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-1371397452214/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty6/
[junit4:junit4] 2> 453884 T1905 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4f536eec
[junit4:junit4] 2> 453884 T1905 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 453885 T1905 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-1371397429222/jetty6
[junit4:junit4] 2> 453885 T1905 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty6/index/
[junit4:junit4] 2> 453885 T1905 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty6/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 453886 T1905 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-1371397429222/jetty6/index
[junit4:junit4] 2> 453888 T1905 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-1371397429222/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 453888 T1905 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 453890 T1905 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 453891 T1905 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 453891 T1905 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 453892 T1905 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 453892 T1905 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 453892 T1905 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 453893 T1905 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 453893 T1905 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 453894 T1905 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 453895 T1905 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 453906 T1905 oass.SolrIndexSearcher.<init> Opening Searcher@12651ad6 main
[junit4:junit4] 2> 453906 T1905 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 453907 T1905 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 453913 T1908 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12651ad6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 453916 T1905 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 453916 T1905 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46691 collection:collection1 shard:shard3
[junit4:junit4] 2> 453919 T1905 oasc.ZkController.register We are http://127.0.0.1:46691/collection1/ and leader is http://127.0.0.1:57878/collection1/
[junit4:junit4] 2> 453919 T1905 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46691
[junit4:junit4] 2> 453920 T1905 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 453920 T1905 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2886 name=collection1 org.apache.solr.core.SolrCore@7a84a043 url=http://127.0.0.1:46691/collection1 node=127.0.0.1:46691_ C2886_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:46691_, base_url=http://127.0.0.1:46691}
[junit4:junit4] 2> 453920 T1909 C2886 P46691 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 453921 T1909 C2886 P46691 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 453921 T1905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 453921 T1909 C2886 P46691 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 453921 T1909 C2886 P46691 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 453922 T1780 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 453923 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 453923 T1909 C2886 P46691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 453923 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 453927 T1847 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 454033 T1780 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 454035 T1780 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:36805
[junit4:junit4] 2> 454036 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 454036 T1780 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 454037 T1780 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-1371397455038
[junit4:junit4] 2> 454037 T1780 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-1371397455038/solr.xml
[junit4:junit4] 2> 454038 T1780 oasc.CoreContainer.<init> New CoreContainer 897628093
[junit4:junit4] 2> 454038 T1780 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-1371397455038/'
[junit4:junit4] 2> 454038 T1780 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-1371397455038/'
[junit4:junit4] 2> ASYNC NEW_CORE C2887 name=collection1 org.apache.solr.core.SolrCore@1af2b854 url=http://127.0.0.1:48185/collection1 node=127.0.0.1:48185_ C2887_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:48185_, base_url=http://127.0.0.1:48185}
[junit4:junit4] 2> 454108 T1890 C2887 P48185 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52812/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 454108 T1890 C2887 P48185 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:48185 START replicas=[http://127.0.0.1:52812/collection1/] nUpdates=100
[junit4:junit4] 2> 454108 T1890 C2887 P48185 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 454109 T1890 C2887 P48185 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 454109 T1890 C2887 P48185 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 454109 T1890 C2887 P48185 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 454109 T1890 C2887 P48185 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 454109 T1890 C2887 P48185 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52812/collection1/. core=collection1
[junit4:junit4] 2> 454109 T1890 C2887 P48185 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 454113 T1780 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 454114 T1780 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 454115 T1780 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 454115 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 454128 T1780 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> ASYNC NEW_CORE C2888 name=collection1 org.apache.solr.core.SolrCore@18c367c1 url=http://127.0.0.1:52812/collection1 node=127.0.0.1:52812_ C2888_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52812_, base_url=http://127.0.0.1:52812, leader=true}
[junit4:junit4] 2> 454129 T1832 C2888 P52812 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 454129 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 454130 T1834 C2888 P52812 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 454130 T1780 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 454131 T1780 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 454131 T1780 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 454132 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 454132 T1834 C2888 P52812 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-1371397429222/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 454133 T1834 C2888 P52812 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 454136 T1780 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 454137 T1780 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53240/solr
[junit4:junit4] 2> 454137 T1780 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 454138 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 454143 T1834 C2888 P52812 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-1371397429222/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-1371397429222/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 454144 T1834 C2888 P52812 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 454144 T1922 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@57e3ead3 name:ZooKeeperConnection Watcher:127.0.0.1:53240 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 454144 T1834 C2888 P52812 oass.SolrIndexSearcher.<init> Opening Searcher@35977920 realtime
[junit4:junit4] 2> 454144 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 454145 T1834 C2888 P52812 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 454146 T1834 C2888 P52812 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 16
[junit4:junit4] 2> 454146 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> ASYNC NEW_CORE C2889 name=collection1 org.apache.solr.core.SolrCore@1af2b854 url=http://127.0.0.1:48185/collection1 node=127.0.0.1:48185_ C2889_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:48185_, base_url=http://127.0.0.1:48185}
[junit4:junit4] 2> 454147 T1890 C2889 P48185 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 454147 T1890 C2889 P48185 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 454149 T1832 C2888 P52812 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 454149 T1832 C2888 P52812 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 454150 T1890 C2889 P48185 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 454150 T1890 C2889 P48185 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 454150 T1890 C2889 P48185 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 454151 T1780 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 454152 T1834 C2888 P52812 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 454152 T1924 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6282e5a0 name:ZooKeeperConnection Watcher:127.0.0.1:53240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 454153 T1780 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 454153 T1890 C2889 P48185 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 454154 T1890 C2889 P48185 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-1371397429222/jetty5/index.20130616034415265
[junit4:junit4] 2> 454154 T1890 C2889 P48185 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-1371397429222/jetty5/index.20130616034415265 lockFactory=org.apache.lucene.store.NativeFSLockFactory@51410367 fullCopy=false
[junit4:junit4] 2> 454157 T1833 C2888 P52812 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 454158 T1890 C2889 P48185 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 454165 T1890 C2889 P48185 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 454165 T1890 C2889 P48185 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 454168 T1890 C2889 P48185 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-1371397429222/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-1371397429222/jetty5/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 454168 T1780 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 454168 T1890 C2889 P48185 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 454169 T1890 C2889 P48185 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 454169 T1890 C2889 P48185 oass.SolrIndexSearcher.<init> Opening Searcher@79a2687f main
[junit4:junit4] 2> 454171 T1889 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@79a2687f main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 454171 T1890 C2889 P48185 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-1371397429222/jetty5/index.20130616034415265 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty5/index.20130616034415265;done=true>>]
[junit4:junit4] 2> 454171 T1890 C2889 P48185 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-1371397429222/jetty5/index.20130616034415265
[junit4:junit4] 2> 454172 T1890 C2889 P48185 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-1371397429222/jetty5/index.20130616034415265
[junit4:junit4] 2> 454172 T1890 C2889 P48185 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 454172 T1890 C2889 P48185 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 454173 T1890 C2889 P48185 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 454173 T1890 C2889 P48185 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 454174 T1890 C2889 P48185 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 454189 T1803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 454190 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"7",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46691_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46691"}
[junit4:junit4] 2> 454192 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:48185_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48185"}
[junit4:junit4] 2> 454223 T1870 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> 454223 T1887 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> 454224 T1809 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> 454224 T1838 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> 454224 T1924 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> 454223 T1822 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> 454223 T1904 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> 454223 T1802 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> 454223 T1854 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> 454927 T1847 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 454928 T1847 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=7&state=recovering&nodeName=127.0.0.1:46691_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 455173 T1780 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36805_
[junit4:junit4] 2> 455175 T1780 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:36805_
[junit4:junit4] 2> 455179 T1822 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> 455180 T1809 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> 455180 T1802 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 455180 T1924 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> 455181 T1887 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 455180 T1854 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> 455180 T1904 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> 455182 T1887 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> 455181 T1870 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 455181 T1802 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> 455181 T1838 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 455185 T1838 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> 455184 T1809 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 455184 T1870 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> 455183 T1822 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 455186 T1904 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 455186 T1854 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 455187 T1924 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 455193 T1926 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 455193 T1926 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 455733 T1803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 455734 T1803 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"8",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:36805_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36805"}
[junit4:junit4] 2> 455734 T1803 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 455734 T1803 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 455738 T1870 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> 455738 T1904 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> 455738 T1854 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> 455738 T1822 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> 455738 T1802 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> 455738 T1809 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> 455738 T1887 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> 455738 T1838 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> 455738 T1924 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> 456194 T1926 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-1371397455038/collection1
[junit4:junit4] 2> 456194 T1926 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 456195 T1926 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 456195 T1926 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 456197 T1926 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-1371397455038/collection1/'
[junit4:junit4] 2> 456197 T1926 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-1371397455038/collection1/lib/README' to classloader
[junit4:junit4] 2> 456198 T1926 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-1371397455038/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 456239 T1926 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 456279 T1926 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 456280 T1926 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 456293 T1926 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 456746 T1926 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 456757 T1926 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 456760 T1926 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 456773 T1926 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 456777 T1926 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 456783 T1926 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 456784 T1926 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 456784 T1926 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 456785 T1926 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 456786 T1926 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 456786 T1926 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 456787 T1926 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 456787 T1926 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-1371397455038/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty7/
[junit4:junit4] 2> 456787 T1926 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4f536eec
[junit4:junit4] 2> 456788 T1926 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 456789 T1926 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-1371397429222/jetty7
[junit4:junit4] 2> 456790 T1926 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty7/index/
[junit4:junit4] 2> 456790 T1926 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371397429222/jetty7/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 456791 T1926 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-1371397429222/jetty7/index
[junit4:junit4] 2> 456794 T1926 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-1371397429222/jetty7/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 456795 T1926 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 456797 T1926 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 456797 T1926 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 456798 T1926 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 456798 T1926 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 456799 T1926 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 456799 T1926 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 456799 T1926 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 456800 T1926 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 456800 T1926 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 456802 T1926 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 456806 T1926 oass.SolrIndexSearcher.<init> Opening Searcher@3a766442 main
[junit4:junit4] 2> 456806 T1926 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 456806 T1926 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 456811 T1927 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3a766442 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 456813 T1926 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 456813 T1926 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:36805 collection:collection1 shard:shard1
[junit4:junit4] 2> 456815 T1926 oasc.ZkController.register We are http://127.0.0.1:36805/collection1/ and leader is http://127.0.0.1:38184/collection1/
[junit4:junit4] 2> 456816 T1926 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:36805
[junit4:junit4] 2> 456816 T1926 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 456816 T1926 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2890 name=collection1 org.apache.solr.core.SolrCore@225f06e0 url=http://127.0.0.1:36805/collection1 node=127.0.0.1:36805_ C2890_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:36805_, base_url=http://127.0.0.1:36805}
[junit4:junit4] 2> 456816 T1928 C2890 P36805 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 456816 T1928 C2890 P36805 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 456816 T1926 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 456817 T1928 C2890 P36805 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 456817 T1928 C2890 P36805 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 456818 T1780 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 456818 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 456818 T1928 C2890 P36805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 456818 T1780 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 456830 T1816 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 8, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 456897 T1780 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 456900 T1780 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55321
[junit4:junit4] 2> 456901 T1780 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 456901 T1780 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 456902 T1780 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-jetty8-1371397457932
[junit4:junit4] 2> 456902 T1780 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-jetty8-1371397457932/solr.xml
[junit4:junit4] 2> 456902 T1780 oasc.CoreContainer.<init> New CoreContainer 554487873
[junit4:junit4] 2> 456903 T1780 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-jetty8-1371397457932/'
[junit4:junit4] 2> 456903 T1780 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-jetty8-1371397457932/'
[junit4:junit4] 2> ASYNC NEW_CORE C2891 name=collection1 org.apache.solr.core.SolrCore@7a84a043 url=http://127.0.0.1:46691/collection1 node=127.0.0.1:46691_ C2891_STATE=coll:collection1 core:collection1 props:{shard=shard3, state=recovering, core=co
[...truncated too long message...]
83 T1780 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 51098
[junit4:junit4] 2> 569984 T1780 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=2032134777
[junit4:junit4] 2> 570115 T1980 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 570116 T1980 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> 570116 T1980 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 570986 T1780 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 570986 T1780 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 570988 T1780 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@5fa485a7
[junit4:junit4] 2> 571010 T1780 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=111,cumulative_deletesById=46,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 571011 T1780 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 571012 T1780 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 571012 T1780 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 571014 T1780 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 571015 T1780 oasc.CachingDirectoryFactory.close Closing StandardDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 571015 T1780 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-1371397429222/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-1371397429222/jetty12;done=false>>]
[junit4:junit4] 2> 571016 T1780 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-1371397429222/jetty12
[junit4:junit4] 2> 571016 T1780 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-1371397429222/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-1371397429222/jetty12/index;done=false>>]
[junit4:junit4] 2> 571017 T1780 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-1371397429222/jetty12/index
[junit4:junit4] 2> 571018 T2208 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89875901921624092-127.0.0.1:51098_-n_0000000012) am no longer a leader.
[junit4:junit4] 2> 571020 T2018 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> 571020 T2018 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 571020 T2018 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 571041 T1780 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 571128 T1780 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 571130 T1780 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:53240 53240
[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> 571210 T2001 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 571215 T2001 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> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeySafeLeaderTest -Dtests.method=testDistribSearch -Dtests.seed=AD4107D3BC660698 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=en_MT -Dtests.timezone=Etc/GMT+12 -Dtests.file.encoding=US-ASCII
[junit4:junit4] 2> 571216 T2001 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] FAILURE 143s J1 | ChaosMonkeySafeLeaderTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard3 is not consistent. Got 67 from http://127.0.0.1:49899/collection1lastClient and got 65 from http://127.0.0.1:51098/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([AD4107D3BC660698:2CA789CBCB3966A4]: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:662)
[junit4:junit4] 2> 571216 T1780 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 143116 T1779 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {range_facet_l=PostingsFormat(name=MockSep), text=PostingsFormat(name=NestedPulsing), _version_=PostingsFormat(name=SimpleText), rnd_b=PostingsFormat(name=Lucene41WithOrds), intDefault=PostingsFormat(name=MockSep), id=PostingsFormat(name=Lucene41WithOrds), timestamp=PostingsFormat(name=MockSep), a_t=PostingsFormat(name=MockSep), range_facet_sl=PostingsFormat(name=Lucene41WithOrds), range_facet_si=PostingsFormat(name=MockSep), other_tl1=PostingsFormat(name=MockSep), multiDefault=PostingsFormat(name=MockSep), a_si=PostingsFormat(name=SimpleText)}, docValues:{}, sim=DefaultSimilarity, locale=en_MT, timezone=Etc/GMT+12
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic amd64/Sun Microsystems Inc. 1.6.0_45 (64-bit)/cpus=8,threads=1,free=32517272,total=225435648
[junit4:junit4] 2> NOTE: All tests run in this JVM: [XsltUpdateRequestHandlerTest, NumericFieldsTest, SpellCheckComponentTest, SuggesterWFSTTest, TestManagedSchemaFieldResource, TestBinaryField, TestStressLucene, DistanceFunctionTest, TestArbitraryIndexDir, TestHashPartitioner, FullSolrCloudDistribCmdsTest, DebugComponentTest, URLClassifyProcessorTest, TestCodecSupport, TermVectorComponentDistributedTest, DirectSolrSpellCheckerTest, DOMUtilTest, TestQuerySenderNoQuery, TestCopyFieldCollectionResource, XmlUpdateRequestHandlerTest, StandardRequestHandlerTest, TestLazyCores, SolrCmdDistributorTest, ZkNodePropsTest, TestPostingsSolrHighlighter, TestSchemaVersionResource, TestZkChroot, SortByFunctionTest, TimeZoneUtilsTest, JSONWriterTest, TestUpdate, TestRangeQuery, IndexReaderFactoryTest, TestCSVLoader, TestSolrQueryParserDefaultOperatorResource, TestFieldTypeResource, TestSolrJ, TestRTGBase, TestDistributedGrouping, TestCoreDiscovery, NotRequiredUniqueKeyTest, TestSuggestSpellingConverter, RequiredFieldsTest, SolrCoreCheckLockOnStartupTest, CollectionsAPIDistributedZkTest, TestUtils, StatsComponentTest, TestPartialUpdateDeduplication, TestIndexSearcher, IndexSchemaRuntimeFieldTest, TestAnalyzedSuggestions, FieldAnalysisRequestHandlerTest, TestSystemIdResolver, TestCSVResponseWriter, DateMathParserTest, SignatureUpdateProcessorFactoryTest, TestCollationField, TestFastOutputStream, RequestHandlersTest, TestCollationKeyRangeQueries, TestAtomicUpdateErrorCases, TestStressReorder, CoreContainerCoreInitFailuresTest, TestDistributedSearch, TestSolrXml, UniqFieldsUpdateProcessorFactoryTest, TestFieldResource, LeaderElectionIntegrationTest, SolrRequestParserTest, SpellPossibilityIteratorTest, DocValuesMultiTest, ChaosMonkeySafeLeaderTest]
[junit4:junit4] Completed on J1 in 143.90s, 1 test, 1 failure <<< FAILURES!
[...truncated 546 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, 13 ignored (7 assumptions)
Total time: 42 minutes 34 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.6.0_45 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure