You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/15 23:02:27 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.7.0_21) - Build #
6153 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/6153/
Java: 32bit/jdk1.7.0_21 -client -XX:+UseParallelGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.testDistribSearch
Error Message:
shard2 is not consistent. Got 176 from http://127.0.0.1:54604/collection1lastClient and got 43 from http://127.0.0.1:56880/collection1
Stack Trace:
java.lang.AssertionError: shard2 is not consistent. Got 176 from http://127.0.0.1:54604/collection1lastClient and got 43 from http://127.0.0.1:56880/collection1
at __randomizedtesting.SeedInfo.seed([FA14D7FDC17C949D:7BF259E5B623F4A1]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9417 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
[junit4:junit4] 2> 136959 T743 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 136963 T743 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeySafeLeaderTest-1371328993600
[junit4:junit4] 2> 136963 T743 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 136964 T744 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 137064 T743 oasc.ZkTestServer.run start zk server on port:42724
[junit4:junit4] 2> 137065 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 137070 T750 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@14d8fdf name:ZooKeeperConnection Watcher:127.0.0.1:42724 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 137070 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 137070 T743 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 137074 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 137075 T752 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@103104e name:ZooKeeperConnection Watcher:127.0.0.1:42724/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 137075 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 137075 T743 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 137077 T743 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 137079 T743 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 137081 T743 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 137083 T743 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 137083 T743 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 137086 T743 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 137087 T743 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 137089 T743 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 137090 T743 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 137092 T743 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 137092 T743 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 137094 T743 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 137095 T743 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 137097 T743 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 137097 T743 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 137099 T743 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 137099 T743 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 137104 T743 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 137104 T743 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 137106 T743 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 137106 T743 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 137168 T743 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 137170 T743 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40621
[junit4:junit4] 2> 137170 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 137171 T743 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 137171 T743 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371328993746
[junit4:junit4] 2> 137171 T743 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371328993746/solr.xml
[junit4:junit4] 2> 137172 T743 oasc.CoreContainer.<init> New CoreContainer 31080105
[junit4:junit4] 2> 137172 T743 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371328993746/'
[junit4:junit4] 2> 137172 T743 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371328993746/'
[junit4:junit4] 2> 137218 T743 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 137219 T743 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 137219 T743 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 137219 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 137220 T743 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 137220 T743 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 137220 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 137221 T743 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 137221 T743 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 137221 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 137224 T743 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 137225 T743 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42724/solr
[junit4:junit4] 2> 137225 T743 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 137226 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 137227 T763 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@173f990 name:ZooKeeperConnection Watcher:127.0.0.1:42724 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 137227 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 137229 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 137232 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 137232 T765 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1ec64cc name:ZooKeeperConnection Watcher:127.0.0.1:42724/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 137233 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 137234 T743 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 137236 T743 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 137238 T743 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 137239 T743 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40621_
[junit4:junit4] 2> 137240 T743 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40621_
[junit4:junit4] 2> 137242 T743 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 137246 T743 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 137247 T743 oasc.Overseer.start Overseer (id=89871416924897283-127.0.0.1:40621_-n_0000000000) starting
[junit4:junit4] 2> 137250 T743 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 137252 T767 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 137252 T743 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 137255 T743 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 137256 T743 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 137258 T766 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 137260 T768 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 137260 T768 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 138762 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 138763 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:40621_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40621"}
[junit4:junit4] 2> 138763 T766 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 138763 T766 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 138767 T765 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> 139262 T768 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371328993746/collection1
[junit4:junit4] 2> 139262 T768 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 139263 T768 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 139263 T768 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 139264 T768 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371328993746/collection1/'
[junit4:junit4] 2> 139265 T768 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371328993746/collection1/lib/README' to classloader
[junit4:junit4] 2> 139265 T768 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371328993746/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 139292 T768 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 139326 T768 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 139327 T768 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 139331 T768 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 139687 T768 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 139693 T768 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 139695 T768 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 139705 T768 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 139708 T768 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 139710 T768 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 139711 T768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 139711 T768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 139712 T768 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 139712 T768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 139712 T768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 139713 T768 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 139719 T768 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371328993746/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/control/data/
[junit4:junit4] 2> 139719 T768 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e3ff04
[junit4:junit4] 2> 139719 T768 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 139720 T768 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/control/data
[junit4:junit4] 2> 139720 T768 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/control/data/index/
[junit4:junit4] 2> 139720 T768 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 139721 T768 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/control/data/index
[junit4:junit4] 2> 139723 T768 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 139724 T768 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 139725 T768 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 139725 T768 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 139725 T768 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 139726 T768 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 139726 T768 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 139726 T768 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 139727 T768 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 139727 T768 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 139727 T768 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 139730 T768 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 139732 T768 oass.SolrIndexSearcher.<init> Opening Searcher@1437b4b main
[junit4:junit4] 2> 139733 T768 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 139733 T768 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 139737 T769 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1437b4b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 139739 T768 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 139739 T768 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40621 collection:control_collection shard:shard1
[junit4:junit4] 2> 139740 T768 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 139745 T768 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 139747 T768 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 139747 T768 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 139747 T768 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:40621/collection1/
[junit4:junit4] 2> 139748 T768 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 139748 T768 oasc.SyncStrategy.syncToMe http://127.0.0.1:40621/collection1/ has no replicas
[junit4:junit4] 2> 139748 T768 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:40621/collection1/
[junit4:junit4] 2> 139749 T768 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 140271 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 140290 T765 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> 140304 T768 oasc.ZkController.register We are http://127.0.0.1:40621/collection1/ and leader is http://127.0.0.1:40621/collection1/
[junit4:junit4] 2> 140305 T768 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40621
[junit4:junit4] 2> 140305 T768 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 140305 T768 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 140305 T768 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 140306 T768 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 140307 T743 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 140307 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 140308 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 140311 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 140312 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 140313 T772 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bdd770 name:ZooKeeperConnection Watcher:127.0.0.1:42724/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 140313 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 140315 T743 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 140317 T743 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 140381 T743 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 140383 T743 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:41387
[junit4:junit4] 2> 140383 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 140384 T743 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 140384 T743 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371328996954
[junit4:junit4] 2> 140384 T743 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371328996954/solr.xml
[junit4:junit4] 2> 140385 T743 oasc.CoreContainer.<init> New CoreContainer 11895354
[junit4:junit4] 2> 140385 T743 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371328996954/'
[junit4:junit4] 2> 140385 T743 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371328996954/'
[junit4:junit4] 2> 140435 T743 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 140435 T743 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 140435 T743 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 140436 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 140436 T743 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 140436 T743 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 140437 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 140437 T743 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 140437 T743 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 140438 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 140441 T743 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 140441 T743 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42724/solr
[junit4:junit4] 2> 140442 T743 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 140443 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 140444 T783 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1200dc2 name:ZooKeeperConnection Watcher:127.0.0.1:42724 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 140444 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 140446 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 140449 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 140450 T785 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15163bb name:ZooKeeperConnection Watcher:127.0.0.1:42724/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 140450 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 140453 T743 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 141455 T743 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41387_
[junit4:junit4] 2> 141457 T743 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:41387_
[junit4:junit4] 2> 141459 T765 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> 141459 T772 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 141460 T785 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 141461 T765 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 141464 T786 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 141465 T786 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 141794 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 141795 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:40621__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:40621_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40621"}
[junit4:junit4] 2> 141799 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:41387_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41387"}
[junit4:junit4] 2> 141799 T766 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 3
[junit4:junit4] 2> 141800 T766 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 141805 T765 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> 141805 T772 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> 141805 T785 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> 142466 T786 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371328996954/collection1
[junit4:junit4] 2> 142466 T786 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 142467 T786 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 142467 T786 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 142468 T786 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371328996954/collection1/'
[junit4:junit4] 2> 142469 T786 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371328996954/collection1/lib/README' to classloader
[junit4:junit4] 2> 142469 T786 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371328996954/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 142501 T786 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 142539 T786 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 142540 T786 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 142544 T786 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 142912 T786 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 142918 T786 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 142920 T786 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 142930 T786 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 142933 T786 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 142936 T786 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 142936 T786 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 142937 T786 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 142937 T786 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 142938 T786 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 142938 T786 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 142938 T786 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 142939 T786 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371328996954/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty1/
[junit4:junit4] 2> 142939 T786 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e3ff04
[junit4:junit4] 2> 142939 T786 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 142940 T786 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty1
[junit4:junit4] 2> 142940 T786 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty1/index/
[junit4:junit4] 2> 142940 T786 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 142940 T786 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty1/index
[junit4:junit4] 2> 142944 T786 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 142944 T786 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 142945 T786 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 142946 T786 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 142946 T786 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 142946 T786 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 142947 T786 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 142947 T786 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 142947 T786 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 142948 T786 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 142948 T786 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 142950 T786 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 142953 T786 oass.SolrIndexSearcher.<init> Opening Searcher@fd484c main
[junit4:junit4] 2> 142954 T786 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 142954 T786 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 142958 T787 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@fd484c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 142960 T786 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 142960 T786 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:41387 collection:collection1 shard:shard1
[junit4:junit4] 2> 142961 T786 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 142967 T786 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 142969 T786 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 142970 T786 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 142970 T786 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:41387/collection1/
[junit4:junit4] 2> 142970 T786 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 142970 T786 oasc.SyncStrategy.syncToMe http://127.0.0.1:41387/collection1/ has no replicas
[junit4:junit4] 2> 142970 T786 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:41387/collection1/
[junit4:junit4] 2> 142970 T786 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 143310 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 143316 T785 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> 143316 T772 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> 143316 T765 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> 143326 T786 oasc.ZkController.register We are http://127.0.0.1:41387/collection1/ and leader is http://127.0.0.1:41387/collection1/
[junit4:junit4] 2> 143326 T786 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:41387
[junit4:junit4] 2> 143326 T786 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 143326 T786 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 143326 T786 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 143328 T786 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 143329 T743 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 143329 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 143329 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 143398 T743 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 143399 T743 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54604
[junit4:junit4] 2> 143400 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 143400 T743 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 143401 T743 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371328999969
[junit4:junit4] 2> 143401 T743 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371328999969/solr.xml
[junit4:junit4] 2> 143401 T743 oasc.CoreContainer.<init> New CoreContainer 24779280
[junit4:junit4] 2> 143402 T743 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371328999969/'
[junit4:junit4] 2> 143402 T743 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371328999969/'
[junit4:junit4] 2> 143459 T743 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 143459 T743 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 143460 T743 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 143460 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 143461 T743 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 143461 T743 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 143462 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 143462 T743 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 143462 T743 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 143463 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 143467 T743 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 143467 T743 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42724/solr
[junit4:junit4] 2> 143468 T743 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 143468 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 143470 T799 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@18b06b7 name:ZooKeeperConnection Watcher:127.0.0.1:42724 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 143470 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 143472 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 143475 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 143476 T801 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a528bc name:ZooKeeperConnection Watcher:127.0.0.1:42724/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 143476 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 143479 T743 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 144482 T743 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54604_
[junit4:junit4] 2> 144483 T743 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54604_
[junit4:junit4] 2> 144485 T765 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> 144485 T785 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> 144486 T772 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 144486 T801 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 144486 T772 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> 144487 T765 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 144488 T785 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 144491 T802 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 144491 T802 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 144821 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 144822 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:41387__collection1",
[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:41387_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41387"}
[junit4:junit4] 2> 144825 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:54604_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54604"}
[junit4:junit4] 2> 144826 T766 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 144826 T766 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 144830 T765 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> 144830 T785 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> 144830 T772 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> 144830 T801 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> 145492 T802 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371328999969/collection1
[junit4:junit4] 2> 145493 T802 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 145494 T802 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 145494 T802 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 145495 T802 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371328999969/collection1/'
[junit4:junit4] 2> 145495 T802 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371328999969/collection1/lib/README' to classloader
[junit4:junit4] 2> 145496 T802 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371328999969/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 145522 T802 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 145557 T802 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 145558 T802 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 145562 T802 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 145985 T802 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 145991 T802 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 145993 T802 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 146005 T802 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 146008 T802 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 146010 T802 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 146011 T802 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 146012 T802 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 146012 T802 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 146013 T802 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 146013 T802 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 146013 T802 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 146014 T802 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371328999969/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty2/
[junit4:junit4] 2> 146014 T802 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e3ff04
[junit4:junit4] 2> 146014 T802 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 146015 T802 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty2
[junit4:junit4] 2> 146015 T802 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty2/index/
[junit4:junit4] 2> 146015 T802 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 146015 T802 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty2/index
[junit4:junit4] 2> 146018 T802 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 146018 T802 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 146019 T802 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 146020 T802 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 146020 T802 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 146021 T802 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 146021 T802 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 146021 T802 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 146022 T802 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 146022 T802 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 146022 T802 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 146025 T802 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 146027 T802 oass.SolrIndexSearcher.<init> Opening Searcher@1fa54b main
[junit4:junit4] 2> 146028 T802 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 146028 T802 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 146033 T803 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1fa54b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 146034 T802 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 146034 T802 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54604 collection:collection1 shard:shard2
[junit4:junit4] 2> 146035 T802 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 146039 T802 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 146041 T802 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 146041 T802 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 146041 T802 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54604/collection1/
[junit4:junit4] 2> 146042 T802 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 146042 T802 oasc.SyncStrategy.syncToMe http://127.0.0.1:54604/collection1/ has no replicas
[junit4:junit4] 2> 146042 T802 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54604/collection1/
[junit4:junit4] 2> 146042 T802 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 146335 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 146343 T785 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> 146343 T772 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> 146343 T801 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> 146343 T765 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> 146396 T802 oasc.ZkController.register We are http://127.0.0.1:54604/collection1/ and leader is http://127.0.0.1:54604/collection1/
[junit4:junit4] 2> 146396 T802 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54604
[junit4:junit4] 2> 146397 T802 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 146397 T802 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 146397 T802 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 146399 T802 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 146400 T743 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 146400 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 146401 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 146470 T743 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 146472 T743 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:43398
[junit4:junit4] 2> 146473 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 146473 T743 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 146473 T743 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371329003041
[junit4:junit4] 2> 146474 T743 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371329003041/solr.xml
[junit4:junit4] 2> 146474 T743 oasc.CoreContainer.<init> New CoreContainer 4150888
[junit4:junit4] 2> 146474 T743 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371329003041/'
[junit4:junit4] 2> 146475 T743 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371329003041/'
[junit4:junit4] 2> 146524 T743 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 146524 T743 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 146525 T743 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 146525 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 146525 T743 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 146526 T743 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 146526 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 146526 T743 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 146527 T743 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 146527 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 146530 T743 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 146530 T743 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42724/solr
[junit4:junit4] 2> 146531 T743 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 146532 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 146533 T815 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@110547f name:ZooKeeperConnection Watcher:127.0.0.1:42724 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 146533 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 146535 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 146538 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 146539 T817 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16deded name:ZooKeeperConnection Watcher:127.0.0.1:42724/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 146539 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 146542 T743 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 147544 T743 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43398_
[junit4:junit4] 2> 147545 T743 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43398_
[junit4:junit4] 2> 147547 T785 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> 147547 T765 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> 147547 T801 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> 147548 T817 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 147548 T772 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 147549 T772 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> 147550 T785 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 147550 T765 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 147551 T801 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 147554 T818 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 147554 T818 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 147850 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 147851 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:54604__collection1",
[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:54604_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54604"}
[junit4:junit4] 2> 147854 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:43398_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43398"}
[junit4:junit4] 2> 147855 T766 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 147855 T766 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 147859 T817 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> 147859 T765 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> 147859 T801 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> 147859 T772 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> 147859 T785 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> 148555 T818 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371329003041/collection1
[junit4:junit4] 2> 148556 T818 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 148556 T818 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 148557 T818 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 148558 T818 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371329003041/collection1/'
[junit4:junit4] 2> 148559 T818 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371329003041/collection1/lib/README' to classloader
[junit4:junit4] 2> 148559 T818 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371329003041/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 148586 T818 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 148624 T818 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 148626 T818 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 148629 T818 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 148986 T818 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 148991 T818 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 148994 T818 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 149003 T818 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 149006 T818 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 149009 T818 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 149010 T818 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 149010 T818 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 149010 T818 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 149011 T818 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 149012 T818 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 149012 T818 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 149012 T818 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371329003041/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty3/
[junit4:junit4] 2> 149012 T818 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e3ff04
[junit4:junit4] 2> 149013 T818 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 149013 T818 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty3
[junit4:junit4] 2> 149013 T818 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty3/index/
[junit4:junit4] 2> 149014 T818 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 149014 T818 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty3/index
[junit4:junit4] 2> 149016 T818 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 149017 T818 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 149018 T818 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 149018 T818 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 149019 T818 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 149019 T818 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 149020 T818 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 149020 T818 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 149020 T818 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 149021 T818 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 149021 T818 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 149023 T818 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 149026 T818 oass.SolrIndexSearcher.<init> Opening Searcher@4dc0a8 main
[junit4:junit4] 2> 149026 T818 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 149027 T818 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 149031 T819 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4dc0a8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 149032 T818 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 149032 T818 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43398 collection:collection1 shard:shard3
[junit4:junit4] 2> 149033 T818 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4:junit4] 2> 149038 T818 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 149040 T818 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 149040 T818 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 149040 T818 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:43398/collection1/
[junit4:junit4] 2> 149040 T818 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 149041 T818 oasc.SyncStrategy.syncToMe http://127.0.0.1:43398/collection1/ has no replicas
[junit4:junit4] 2> 149041 T818 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:43398/collection1/
[junit4:junit4] 2> 149041 T818 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4:junit4] 2> 149365 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 149372 T765 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> 149372 T772 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> 149372 T785 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> 149372 T817 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> 149372 T801 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> 149396 T818 oasc.ZkController.register We are http://127.0.0.1:43398/collection1/ and leader is http://127.0.0.1:43398/collection1/
[junit4:junit4] 2> 149396 T818 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43398
[junit4:junit4] 2> 149396 T818 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 149396 T818 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 149397 T818 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 149398 T818 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 149399 T743 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 149399 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 149400 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 149465 T743 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 149467 T743 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:46109
[junit4:junit4] 2> 149468 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 149469 T743 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 149469 T743 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371329006040
[junit4:junit4] 2> 149469 T743 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371329006040/solr.xml
[junit4:junit4] 2> 149470 T743 oasc.CoreContainer.<init> New CoreContainer 10240289
[junit4:junit4] 2> 149470 T743 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371329006040/'
[junit4:junit4] 2> 149470 T743 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371329006040/'
[junit4:junit4] 2> 149516 T743 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 149516 T743 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 149517 T743 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 149517 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 149517 T743 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 149518 T743 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 149518 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 149518 T743 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 149518 T743 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 149519 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 149522 T743 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 149522 T743 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42724/solr
[junit4:junit4] 2> 149523 T743 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 149523 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 149525 T831 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11615a name:ZooKeeperConnection Watcher:127.0.0.1:42724 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 149525 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 149527 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 149530 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 149531 T833 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c6df34 name:ZooKeeperConnection Watcher:127.0.0.1:42724/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 149531 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 149535 T743 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 150537 T743 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46109_
[junit4:junit4] 2> 150539 T743 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46109_
[junit4:junit4] 2> 150540 T785 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> 150540 T801 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> 150540 T765 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> 150541 T772 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 150541 T772 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> 150541 T817 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 150542 T817 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> 150542 T833 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 150543 T785 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 150543 T801 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 150543 T765 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 150547 T834 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 150547 T834 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 150877 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 150878 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:43398__collection1",
[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:43398_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43398"}
[junit4:junit4] 2> 150882 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:46109_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46109"}
[junit4:junit4] 2> 150882 T766 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 150883 T766 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 150887 T817 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> 150887 T833 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> 150887 T772 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> 150887 T801 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> 150887 T765 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> 150887 T785 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> 151549 T834 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371329006040/collection1
[junit4:junit4] 2> 151549 T834 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 151550 T834 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 151550 T834 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 151551 T834 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371329006040/collection1/'
[junit4:junit4] 2> 151552 T834 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371329006040/collection1/lib/README' to classloader
[junit4:junit4] 2> 151552 T834 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371329006040/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 151579 T834 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 151613 T834 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 151614 T834 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 151618 T834 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 151982 T834 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 151988 T834 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 151991 T834 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 152000 T834 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 152003 T834 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 152005 T834 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 152006 T834 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 152006 T834 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 152006 T834 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 152007 T834 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 152007 T834 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 152008 T834 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 152008 T834 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371329006040/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty4/
[junit4:junit4] 2> 152008 T834 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e3ff04
[junit4:junit4] 2> 152008 T834 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 152009 T834 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty4
[junit4:junit4] 2> 152009 T834 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty4/index/
[junit4:junit4] 2> 152009 T834 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 152010 T834 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty4/index
[junit4:junit4] 2> 152012 T834 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 152012 T834 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 152013 T834 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 152014 T834 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 152014 T834 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 152015 T834 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 152015 T834 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 152015 T834 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 152016 T834 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 152016 T834 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 152016 T834 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 152019 T834 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 152021 T834 oass.SolrIndexSearcher.<init> Opening Searcher@1eafdb main
[junit4:junit4] 2> 152022 T834 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 152022 T834 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 152027 T835 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1eafdb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 152029 T834 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 152029 T834 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46109 collection:collection1 shard:shard1
[junit4:junit4] 2> 152031 T834 oasc.ZkController.register We are http://127.0.0.1:46109/collection1/ and leader is http://127.0.0.1:41387/collection1/
[junit4:junit4] 2> 152031 T834 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46109
[junit4:junit4] 2> 152031 T834 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 152031 T834 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C232 name=collection1 org.apache.solr.core.SolrCore@1ed0528 url=http://127.0.0.1:46109/collection1 node=127.0.0.1:46109_ C232_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:46109_, base_url=http://127.0.0.1:46109}
[junit4:junit4] 2> 152032 T836 C232 P46109 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 152032 T834 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 152032 T836 C232 P46109 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 152033 T836 C232 P46109 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 152033 T836 C232 P46109 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 152033 T743 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 152034 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 152034 T836 C232 P46109 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 152034 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 152040 T779 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:46109__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 152100 T743 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 152104 T743 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:56334
[junit4:junit4] 2> 152105 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 152105 T743 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 152106 T743 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371329008676
[junit4:junit4] 2> 152106 T743 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371329008676/solr.xml
[junit4:junit4] 2> 152107 T743 oasc.CoreContainer.<init> New CoreContainer 6377075
[junit4:junit4] 2> 152107 T743 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371329008676/'
[junit4:junit4] 2> 152108 T743 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371329008676/'
[junit4:junit4] 2> 152167 T743 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 152168 T743 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 152168 T743 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 152168 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 152169 T743 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 152169 T743 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 152169 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 152170 T743 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 152170 T743 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 152170 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 152173 T743 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 152174 T743 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42724/solr
[junit4:junit4] 2> 152174 T743 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 152175 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 152176 T848 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@91f2a0 name:ZooKeeperConnection Watcher:127.0.0.1:42724 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 152177 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 152178 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 152181 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 152182 T850 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10c33e7 name:ZooKeeperConnection Watcher:127.0.0.1:42724/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 152182 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 152185 T743 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 152393 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 152393 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:46109__collection1",
[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:46109_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46109"}
[junit4:junit4] 2> 152396 T817 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> 152396 T833 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> 152397 T850 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> 152396 T785 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> 152396 T765 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> 152396 T801 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> 152396 T772 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> 153040 T779 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:46109__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 153041 T779 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:46109__collection1&state=recovering&nodeName=127.0.0.1:46109_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 153187 T743 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56334_
[junit4:junit4] 2> 153188 T743 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:56334_
[junit4:junit4] 2> 153190 T765 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> 153190 T801 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> 153190 T785 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> 153190 T833 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> 153191 T817 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 153191 T817 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> 153191 T850 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> 153191 T772 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 153192 T765 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 153192 T772 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> 153193 T785 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 153193 T833 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 153193 T801 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 153194 T850 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 153198 T851 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 153198 T851 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 153902 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 153903 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:56334_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56334"}
[junit4:junit4] 2> 153903 T766 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 153903 T766 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 153906 T765 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> 153906 T833 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> 153907 T850 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> 153906 T785 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> 153906 T817 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> 153906 T772 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> 153906 T801 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> 154199 T851 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371329008676/collection1
[junit4:junit4] 2> 154199 T851 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 154200 T851 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 154200 T851 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 154201 T851 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371329008676/collection1/'
[junit4:junit4] 2> 154202 T851 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371329008676/collection1/lib/README' to classloader
[junit4:junit4] 2> 154202 T851 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371329008676/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 154239 T851 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 154282 T851 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 154283 T851 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 154288 T851 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 154657 T851 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 154663 T851 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 154670 T851 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 154680 T851 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 154683 T851 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 154686 T851 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 154687 T851 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 154687 T851 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 154687 T851 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 154688 T851 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 154688 T851 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 154689 T851 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 154689 T851 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371329008676/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty5/
[junit4:junit4] 2> 154689 T851 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e3ff04
[junit4:junit4] 2> 154689 T851 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 154690 T851 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty5
[junit4:junit4] 2> 154690 T851 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty5/index/
[junit4:junit4] 2> 154690 T851 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 154691 T851 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty5/index
[junit4:junit4] 2> 154694 T851 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 154694 T851 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 154696 T851 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 154696 T851 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 154696 T851 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 154697 T851 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 154697 T851 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 154697 T851 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 154698 T851 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 154698 T851 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 154699 T851 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 154701 T851 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 154704 T851 oass.SolrIndexSearcher.<init> Opening Searcher@1fb3222 main
[junit4:junit4] 2> 154704 T851 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 154704 T851 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 154709 T852 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1fb3222 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 154710 T851 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 154710 T851 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:56334 collection:collection1 shard:shard2
[junit4:junit4] 2> 154713 T851 oasc.ZkController.register We are http://127.0.0.1:56334/collection1/ and leader is http://127.0.0.1:54604/collection1/
[junit4:junit4] 2> 154713 T851 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56334
[junit4:junit4] 2> 154714 T851 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 154714 T851 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C233 name=collection1 org.apache.solr.core.SolrCore@11be03c url=http://127.0.0.1:56334/collection1 node=127.0.0.1:56334_ C233_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:56334_, base_url=http://127.0.0.1:56334}
[junit4:junit4] 2> 154714 T853 C233 P56334 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 154714 T851 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 154715 T853 C233 P56334 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 154715 T853 C233 P56334 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 154715 T853 C233 P56334 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 154716 T743 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 154716 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 154717 T853 C233 P56334 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 154717 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 154720 T795 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:56334__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 154790 T743 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 154791 T743 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51513
[junit4:junit4] 2> 154792 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 154793 T743 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 154793 T743 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371329011357
[junit4:junit4] 2> 154793 T743 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371329011357/solr.xml
[junit4:junit4] 2> 154794 T743 oasc.CoreContainer.<init> New CoreContainer 5366890
[junit4:junit4] 2> 154794 T743 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371329011357/'
[junit4:junit4] 2> 154795 T743 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371329011357/'
[junit4:junit4] 2> 154844 T743 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 154844 T743 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 154844 T743 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 154845 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 154845 T743 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 154846 T743 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 154846 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 154846 T743 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 154847 T743 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 154847 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 154850 T743 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 154850 T743 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42724/solr
[junit4:junit4] 2> 154851 T743 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 154852 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 154853 T865 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@bc15b4 name:ZooKeeperConnection Watcher:127.0.0.1:42724 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 154853 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 154854 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 154857 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 154858 T867 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d77b6c name:ZooKeeperConnection Watcher:127.0.0.1:42724/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 154858 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 154861 T743 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C234 name=collection1 org.apache.solr.core.SolrCore@1ed0528 url=http://127.0.0.1:46109/collection1 node=127.0.0.1:46109_ C234_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:46109_, base_url=http://127.0.0.1:46109}
[junit4:junit4] 2> 155042 T836 C234 P46109 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:41387/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 155042 T836 C234 P46109 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:46109 START replicas=[http://127.0.0.1:41387/collection1/] nUpdates=100
[junit4:junit4] 2> 155042 T836 C234 P46109 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 155043 T836 C234 P46109 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 155043 T836 C234 P46109 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 155043 T836 C234 P46109 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 155043 T836 C234 P46109 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 155044 T836 C234 P46109 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:41387/collection1/. core=collection1
[junit4:junit4] 2> 155044 T836 C234 P46109 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C235 name=collection1 org.apache.solr.core.SolrCore@1df0f73 url=http://127.0.0.1:41387/collection1 node=127.0.0.1:41387_ C235_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:41387_, base_url=http://127.0.0.1:41387, leader=true}
[junit4:junit4] 2> 155050 T779 C235 P41387 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> 155051 T778 C235 P41387 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 155053 T778 C235 P41387 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 155053 T778 C235 P41387 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 155062 T778 C235 P41387 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 155062 T778 C235 P41387 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 155063 T778 C235 P41387 oass.SolrIndexSearcher.<init> Opening Searcher@520ca realtime
[junit4:junit4] 2> 155063 T778 C235 P41387 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 155064 T778 C235 P41387 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> 155064 T836 C234 P46109 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 155065 T836 C234 P46109 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 155066 T780 C235 P41387 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 155067 T780 C235 P41387 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 155067 T836 C234 P46109 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 155067 T836 C234 P46109 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 155067 T836 C234 P46109 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 155069 T779 C235 P41387 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> 155070 T836 C234 P46109 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 155071 T836 C234 P46109 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty4/index.20130615224331707
[junit4:junit4] 2> 155071 T836 C234 P46109 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty4/index.20130615224331707 lockFactory=org.apache.lucene.store.NativeFSLockFactory@250325 fullCopy=false
[junit4:junit4] 2> 155073 T778 C235 P41387 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> 155074 T836 C234 P46109 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 155083 T836 C234 P46109 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 155083 T836 C234 P46109 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 155084 T836 C234 P46109 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty4/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 155084 T836 C234 P46109 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 155085 T836 C234 P46109 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 155085 T836 C234 P46109 oass.SolrIndexSearcher.<init> Opening Searcher@19c28ef main
[junit4:junit4] 2> 155086 T835 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19c28ef main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 155086 T836 C234 P46109 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty4/index.20130615224331707 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty4/index.20130615224331707;done=true>>]
[junit4:junit4] 2> 155087 T836 C234 P46109 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty4/index.20130615224331707
[junit4:junit4] 2> 155087 T836 C234 P46109 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty4/index.20130615224331707
[junit4:junit4] 2> 155087 T836 C234 P46109 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 155087 T836 C234 P46109 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 155088 T836 C234 P46109 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 155088 T836 C234 P46109 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 155090 T836 C234 P46109 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 155411 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 155411 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:56334__collection1",
[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:56334_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56334"}
[junit4:junit4] 2> 155414 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:46109__collection1",
[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:46109_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46109"}
[junit4:junit4] 2> 155432 T765 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> 155432 T801 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> 155432 T817 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> 155433 T850 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> 155432 T833 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> 155432 T867 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> 155432 T772 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> 155433 T785 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> 155721 T795 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:56334__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 155721 T795 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:56334__collection1&state=recovering&nodeName=127.0.0.1:56334_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 155863 T743 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51513_
[junit4:junit4] 2> 155865 T743 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51513_
[junit4:junit4] 2> 155866 T801 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> 155867 T850 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> 155867 T772 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 155867 T817 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 155867 T765 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> 155867 T785 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> 155867 T833 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> 155867 T817 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> 155867 T772 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> 155869 T850 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 155867 T867 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 155868 T801 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 155869 T867 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> 155870 T765 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 155870 T785 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 155870 T833 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 155874 T870 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 155874 T870 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 156940 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 156941 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:51513_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51513"}
[junit4:junit4] 2> 156941 T766 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 156942 T766 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 156945 T765 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> 156946 T833 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> 156946 T850 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> 156946 T801 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> 156946 T772 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> 156946 T817 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> 156946 T867 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> 156946 T785 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> C233_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:56334_, base_url=http://127.0.0.1:56334}
[junit4:junit4] 2> 157722 T853 C233 P56334 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:54604/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 157722 T853 C233 P56334 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56334 START replicas=[http://127.0.0.1:54604/collection1/] nUpdates=100
[junit4:junit4] 2> 157723 T853 C233 P56334 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 157723 T853 C233 P56334 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 157724 T853 C233 P56334 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 157724 T853 C233 P56334 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 157724 T853 C233 P56334 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 157724 T853 C233 P56334 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:54604/collection1/. core=collection1
[junit4:junit4] 2> 157724 T853 C233 P56334 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C236 name=collection1 org.apache.solr.core.SolrCore@15169b6 url=http://127.0.0.1:54604/collection1 node=127.0.0.1:54604_ C236_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:54604_, base_url=http://127.0.0.1:54604, leader=true}
[junit4:junit4] 2> 157728 T794 C236 P54604 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> 157728 T797 C236 P54604 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 157731 T797 C236 P54604 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 157731 T797 C236 P54604 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 157742 T797 C236 P54604 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 157743 T797 C236 P54604 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 157743 T797 C236 P54604 oass.SolrIndexSearcher.<init> Opening Searcher@d53eeb realtime
[junit4:junit4] 2> 157743 T797 C236 P54604 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 157744 T797 C236 P54604 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> 157744 T853 C233 P56334 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 157745 T853 C233 P56334 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 157746 T796 C236 P54604 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 157746 T796 C236 P54604 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 157747 T853 C233 P56334 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 157747 T853 C233 P56334 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 157747 T853 C233 P56334 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 157749 T794 C236 P54604 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> 157750 T853 C233 P56334 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 157750 T853 C233 P56334 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty5/index.20130615224334387
[junit4:junit4] 2> 157751 T853 C233 P56334 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty5/index.20130615224334387 lockFactory=org.apache.lucene.store.NativeFSLockFactory@194774d fullCopy=false
[junit4:junit4] 2> 157753 T797 C236 P54604 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> 157754 T853 C233 P56334 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 157763 T853 C233 P56334 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 157763 T853 C233 P56334 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 157764 T853 C233 P56334 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty5/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 157765 T853 C233 P56334 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 157765 T853 C233 P56334 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 157765 T853 C233 P56334 oass.SolrIndexSearcher.<init> Opening Searcher@f0f624 main
[junit4:junit4] 2> 157766 T852 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f0f624 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 157767 T853 C233 P56334 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty5/index.20130615224334387 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty5/index.20130615224334387;done=true>>]
[junit4:junit4] 2> 157767 T853 C233 P56334 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty5/index.20130615224334387
[junit4:junit4] 2> 157767 T853 C233 P56334 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty5/index.20130615224334387
[junit4:junit4] 2> 157768 T853 C233 P56334 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 157768 T853 C233 P56334 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 157768 T853 C233 P56334 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 157768 T853 C233 P56334 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 157770 T853 C233 P56334 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 157876 T870 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371329011357/collection1
[junit4:junit4] 2> 157877 T870 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 157878 T870 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 157878 T870 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 157879 T870 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371329011357/collection1/'
[junit4:junit4] 2> 157880 T870 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371329011357/collection1/lib/README' to classloader
[junit4:junit4] 2> 157880 T870 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371329011357/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 157915 T870 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 157951 T870 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 157953 T870 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 157957 T870 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 158330 T870 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 158336 T870 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 158339 T870 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 158348 T870 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 158351 T870 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 158354 T870 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 158355 T870 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 158355 T870 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 158355 T870 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 158356 T870 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 158356 T870 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 158356 T870 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 158357 T870 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371329011357/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty6/
[junit4:junit4] 2> 158357 T870 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e3ff04
[junit4:junit4] 2> 158357 T870 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 158358 T870 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty6
[junit4:junit4] 2> 158358 T870 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty6/index/
[junit4:junit4] 2> 158358 T870 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty6/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 158358 T870 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty6/index
[junit4:junit4] 2> 158374 T870 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 158374 T870 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 158375 T870 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 158376 T870 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 158376 T870 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 158377 T870 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 158377 T870 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 158377 T870 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 158378 T870 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 158379 T870 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 158379 T870 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 158381 T870 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 158384 T870 oass.SolrIndexSearcher.<init> Opening Searcher@87a05d main
[junit4:junit4] 2> 158385 T870 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 158385 T870 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 158391 T873 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@87a05d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 158394 T870 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 158394 T870 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51513 collection:collection1 shard:shard3
[junit4:junit4] 2> 158401 T870 oasc.ZkController.register We are http://127.0.0.1:51513/collection1/ and leader is http://127.0.0.1:43398/collection1/
[junit4:junit4] 2> 158401 T870 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51513
[junit4:junit4] 2> 158401 T870 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 158401 T870 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C237 name=collection1 org.apache.solr.core.SolrCore@166a1b2 url=http://127.0.0.1:51513/collection1 node=127.0.0.1:51513_ C237_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:51513_, base_url=http://127.0.0.1:51513}
[junit4:junit4] 2> 158402 T874 C237 P51513 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 158403 T870 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 158403 T874 C237 P51513 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 158403 T874 C237 P51513 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> ASYNC NEW_CORE C238 name=collection1 org.apache.solr.core.SolrCore@166a1b2 url=http://127.0.0.1:51513/collection1 node=127.0.0.1:51513_ C238_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:51513_, base_url=http://127.0.0.1:51513}
[junit4:junit4] 2> 158413 T874 C238 P51513 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 158414 T743 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 158414 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 158415 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 158416 T874 C238 P51513 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 158419 T811 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:51513__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 158451 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 158451 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:56334__collection1",
[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:56334_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56334"}
[junit4:junit4] 2> 158454 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:51513__collection1",
[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:51513_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51513"}
[junit4:junit4] 2> 158458 T765 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> 158458 T867 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> 158458 T833 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> 158458 T817 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> 158458 T801 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> 158458 T772 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> 158458 T785 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> 158458 T850 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> 158481 T743 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 158482 T743 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55489
[junit4:junit4] 2> 158483 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 158483 T743 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 158484 T743 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371329015055
[junit4:junit4] 2> 158484 T743 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371329015055/solr.xml
[junit4:junit4] 2> 158484 T743 oasc.CoreContainer.<init> New CoreContainer 3280022
[junit4:junit4] 2> 158485 T743 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371329015055/'
[junit4:junit4] 2> 158485 T743 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371329015055/'
[junit4:junit4] 2> 158531 T743 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 158532 T743 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 158532 T743 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 158532 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 158533 T743 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 158533 T743 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 158533 T743 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 158534 T743 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 158534 T743 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 158534 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 158537 T743 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 158538 T743 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42724/solr
[junit4:junit4] 2> 158538 T743 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 158539 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 158540 T886 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b0c727 name:ZooKeeperConnection Watcher:127.0.0.1:42724 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 158540 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 158542 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 158545 T743 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 158546 T888 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@662f8b name:ZooKeeperConnection Watcher:127.0.0.1:42724/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 158546 T743 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 158550 T743 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 159420 T811 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:51513__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 159420 T811 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:51513__collection1&state=recovering&nodeName=127.0.0.1:51513_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 159552 T743 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55489_
[junit4:junit4] 2> 159554 T743 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55489_
[junit4:junit4] 2> 159556 T765 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> 159556 T801 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> 159557 T850 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> 159556 T833 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> 159557 T817 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 159558 T817 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> 159557 T785 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> 159558 T772 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 159559 T772 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> 159559 T888 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 159559 T867 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 159560 T867 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> 159561 T850 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 159561 T785 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 159562 T833 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 159562 T765 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 159562 T801 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 159566 T889 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 159567 T889 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 159965 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 159966 T766 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:55489_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55489"}
[junit4:junit4] 2> 159966 T766 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 159966 T766 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 159970 T867 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> 159970 T785 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> 159970 T833 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> 159970 T772 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> 159970 T801 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> 159970 T850 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> 159970 T888 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> 159970 T765 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> 159970 T817 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> 160568 T889 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371329015055/collection1
[junit4:junit4] 2> 160568 T889 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 160569 T889 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 160569 T889 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 160571 T889 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371329015055/collection1/'
[junit4:junit4] 2> 160571 T889 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371329015055/collection1/lib/README' to classloader
[junit4:junit4] 2> 160571 T889 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371329015055/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 160598 T889 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 160632 T889 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 160633 T889 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 160637 T889 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 160999 T889 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 161005 T889 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 161007 T889 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 161018 T889 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 161023 T889 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 161027 T889 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 161028 T889 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 161029 T889 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 161029 T889 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 161030 T889 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 161030 T889 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 161030 T889 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 161031 T889 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371329015055/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty7/
[junit4:junit4] 2> 161031 T889 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e3ff04
[junit4:junit4] 2> 161032 T889 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 161033 T889 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty7
[junit4:junit4] 2> 161033 T889 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty7/index/
[junit4:junit4] 2> 161033 T889 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty7/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 161034 T889 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty7/index
[junit4:junit4] 2> 161037 T889 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty7/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 161037 T889 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 161038 T889 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 161039 T889 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 161039 T889 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 161040 T889 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 161040 T889 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 161040 T889 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 161041 T889 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 161041 T889 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 161042 T889 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 161044 T889 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 161048 T889 oass.SolrIndexSearcher.<init> Opening Searcher@15871 main
[junit4:junit4] 2> 161049 T889 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 161049 T889 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 161053 T890 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@15871 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 161055 T889 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 161055 T889 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55489 collection:collection1 shard:shard1
[junit4:junit4] 2> 161058 T889 oasc.ZkController.register We are http://127.0.0.1:55489/collection1/ and leader is http://127.0.0.1:41387/collection1/
[junit4:junit4] 2> 161058 T889 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55489
[junit4:junit4] 2> 161059 T889 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 161059 T889 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C239 name=collection1 org.apache.solr.core.SolrCore@12c43f7 url=http://127.0.0.1:55489/collection1 node=127.0.0.1:55489_ C239_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:55489_, base_url=http://127.0.0.1:55489}
[junit4:junit4] 2> 161059 T891 C239 P55489 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 161060 T891 C239 P55489 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 161060 T891 C239 P55489 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 161060 T891 C239 P55489 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 161060 T889 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 161061 T891 C239 P55489 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 161062 T743 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 161062 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 161063 T743 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 161065 T781 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:55489__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 161137 T743 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 161139 T743 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:56880
[junit4:junit4] 2> 161139 T743 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 161140 T743 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 161140 T743 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty8-1371329017703
[junit4:junit4] 2> 161140 T743 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty8-1371329017703/solr.xml
[junit4:junit4] 2> 161141 T743 oasc.CoreContainer.<init> New CoreContainer 27488220
[junit4:junit4] 2> 161141 T743 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty8-1371329017703/'
[junit4:junit4] 2> 161141 T743 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/L
[...truncated too long message...]
unit4] 2> 333732 T743 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 333732 T743 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 333732 T743 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 333733 T743 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 333733 T743 oasc.CachingDirectoryFactory.close Closing StandardDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 333734 T743 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty11 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty11;done=false>>]
[junit4:junit4] 2> 333734 T743 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty11
[junit4:junit4] 2> 333734 T743 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty11/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty11/index;done=false>>]
[junit4:junit4] 2> 333735 T743 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371328993600/jetty11/index
[junit4:junit4] 2> 333736 T1036 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> 333736 T1092 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> 333737 T1092 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 333737 T1092 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 333738 T1036 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4:junit4] 2> 333759 T743 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 333810 T743 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 55107
[junit4:junit4] 2> 333811 T743 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=19708473
[junit4:junit4] 2> 334169 T1158 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 334170 T1158 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:47031__collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:47031_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47031"}
[junit4:junit4] 2> 334174 T1158 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:47031__collection1",
[junit4:junit4] 2> "numShards":null,
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:47031_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47031"}
[junit4:junit4] 2> 334177 T1036 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> 334813 T1158 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89871416924897310-127.0.0.1:55107_-n_0000000013) am no longer a leader.
[junit4:junit4] 2> 334814 T1036 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> 334814 T1036 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 334815 T1036 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 334837 T743 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 334912 T743 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 334913 T743 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:42724 42724
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 1> safe stop:
[junit4:junit4] 1> safe stop:
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeySafeLeaderTest -Dtests.method=testDistribSearch -Dtests.seed=FA14D7FDC17C949D -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=mt -Dtests.timezone=Europe/Vienna -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 198s J1 | ChaosMonkeySafeLeaderTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard2 is not consistent. Got 176 from http://127.0.0.1:54604/collection1lastClient and got 43 from http://127.0.0.1:56880/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([FA14D7FDC17C949D:7BF259E5B623F4A1]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 334950 T743 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 197994 T742 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=Direct), text=PostingsFormat(name=TestBloomFilteredLucene41Postings), _version_=Lucene41(blocksize=128), rnd_b=PostingsFormat(name=Memory doPackFST= true), intDefault=Lucene41(blocksize=128), timestamp=PostingsFormat(name=Direct), id=PostingsFormat(name=Memory doPackFST= true), a_t=PostingsFormat(name=Direct), range_facet_sl=PostingsFormat(name=Memory doPackFST= true), range_facet_si=PostingsFormat(name=Direct), other_tl1=Lucene41(blocksize=128), multiDefault=PostingsFormat(name=Direct), a_si=Lucene41(blocksize=128)}, docValues:{timestamp=DocValuesFormat(name=CheapBastard)}, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=mt, timezone=Europe/Vienna
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic i386/Oracle Corporation 1.7.0_21 (32-bit)/cpus=8,threads=2,free=165913096,total=246415360
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestSystemIdResolver, PathHierarchyTokenizerFactoryTest, CoreContainerCoreInitFailuresTest, CurrencyFieldOpenExchangeTest, FullSolrCloudDistribCmdsTest, TestReload, TestPartialUpdateDeduplication, TestIndexingPerformance, PreAnalyzedUpdateProcessorTest, TestFieldResource, TestAddFieldRealTimeGet, StandardRequestHandlerTest, TestSolrQueryParserDefaultOperatorResource, URLClassifyProcessorTest, TestDefaultSearchFieldResource, TestIndexSearcher, TestBinaryResponseWriter, SolrCmdDistributorTest, ClusterStateTest, DirectUpdateHandlerTest, TestAnalyzedSuggestions, TestSolrXml, TestStressReorder, RequestHandlersTest, EchoParamsTest, TestManagedSchemaFieldResource, TestLazyCores, StatsComponentTest, TestHashPartitioner, ChaosMonkeySafeLeaderTest]
[junit4:junit4] Completed on J1 in 198.52s, 1 test, 1 failure <<< FAILURES!
[...truncated 666 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:386: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:366: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1243: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:887: There were test failures: 296 suites, 1243 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 39 minutes 7 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_21 -client -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure