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/23 04:35:52 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.8.0-ea-b93) - Build #
6264 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/6264/
Java: 32bit/jdk1.8.0-ea-b93 -server -XX:+UseG1GC
1 tests failed.
FAILED: junit.framework.TestSuite.org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
Error Message:
ERROR: SolrIndexSearcher opens=47 closes=46
Stack Trace:
java.lang.AssertionError: ERROR: SolrIndexSearcher opens=47 closes=46
at __randomizedtesting.SeedInfo.seed([96A2A274AD65FF78]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.SolrTestCaseJ4.endTrackingSearchers(SolrTestCaseJ4.java:257)
at org.apache.solr.SolrTestCaseJ4.afterClass(SolrTestCaseJ4.java:104)
at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:491)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:700)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Build Log:
[...truncated 9640 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
[junit4:junit4] 2> 635647 T2598 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 635652 T2598 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-ChaosMonkeySafeLeaderTest-1371954494368
[junit4:junit4] 2> 635652 T2598 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 635653 T2599 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 635753 T2598 oasc.ZkTestServer.run start zk server on port:38072
[junit4:junit4] 2> 635755 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 636009 T2605 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19bd4a0 name:ZooKeeperConnection Watcher:127.0.0.1:38072 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 636009 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 636010 T2598 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 636014 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 636015 T2607 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15c24e3 name:ZooKeeperConnection Watcher:127.0.0.1:38072/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 636015 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 636016 T2598 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 636018 T2598 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 636020 T2598 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 636023 T2598 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 636027 T2598 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> 636028 T2598 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 636033 T2598 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> 636033 T2598 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 636036 T2598 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> 636036 T2598 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 636038 T2598 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> 636039 T2598 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 636041 T2598 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> 636041 T2598 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 636043 T2598 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> 636044 T2598 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 636046 T2598 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> 636046 T2598 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 636049 T2598 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> 636049 T2598 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 636052 T2598 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> 636052 T2598 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 636143 T2598 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 636146 T2598 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:44345
[junit4:junit4] 2> 636146 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 636147 T2598 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 636147 T2598 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371954494771
[junit4:junit4] 2> 636147 T2598 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371954494771/solr.xml
[junit4:junit4] 2> 636148 T2598 oasc.CoreContainer.<init> New CoreContainer 32388508
[junit4:junit4] 2> 636148 T2598 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371954494771/'
[junit4:junit4] 2> 636148 T2598 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371954494771/'
[junit4:junit4] 2> 636195 T2598 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 636196 T2598 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 636196 T2598 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 636197 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 636197 T2598 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 636198 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 636198 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 636198 T2598 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 636199 T2598 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 636199 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 636203 T2598 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 636203 T2598 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38072/solr
[junit4:junit4] 2> 636204 T2598 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 636204 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 636206 T2618 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1afe68d name:ZooKeeperConnection Watcher:127.0.0.1:38072 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 636206 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 636208 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 636211 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 636213 T2620 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@770dd0 name:ZooKeeperConnection Watcher:127.0.0.1:38072/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 636213 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 636214 T2598 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 636216 T2598 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 636219 T2598 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 636220 T2598 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44345_
[junit4:junit4] 2> 636221 T2598 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:44345_
[junit4:junit4] 2> 636223 T2598 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 636228 T2598 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 636231 T2598 oasc.Overseer.start Overseer (id=89912409743032323-127.0.0.1:44345_-n_0000000000) starting
[junit4:junit4] 2> 636237 T2598 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 636243 T2622 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 636244 T2598 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 636248 T2598 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 636251 T2598 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 636255 T2621 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 636260 T2623 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 636260 T2623 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 637759 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 637759 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44345",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44345_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":null}
[junit4:junit4] 2> 637760 T2621 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 637760 T2621 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 637763 T2620 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> 638262 T2623 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371954494771/collection1
[junit4:junit4] 2> 638262 T2623 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 638263 T2623 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 638263 T2623 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 638264 T2623 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371954494771/collection1/'
[junit4:junit4] 2> 638264 T2623 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371954494771/collection1/lib/README' to classloader
[junit4:junit4] 2> 638265 T2623 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371954494771/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 638289 T2623 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 638340 T2623 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 638344 T2623 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 638349 T2623 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 638689 T2623 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 638694 T2623 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 638697 T2623 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 638707 T2623 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 638709 T2623 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 638712 T2623 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 638712 T2623 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 638713 T2623 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 638713 T2623 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 638713 T2623 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 638714 T2623 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 638714 T2623 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 638714 T2623 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371954494771/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/control/data/
[junit4:junit4] 2> 638714 T2623 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@144ee4d
[junit4:junit4] 2> 638715 T2623 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 638715 T2623 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/control/data
[junit4:junit4] 2> 638715 T2623 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/control/data/index/
[junit4:junit4] 2> 638716 T2623 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 638716 T2623 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/control/data/index
[junit4:junit4] 2> 638730 T2623 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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 638730 T2623 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 638731 T2623 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 638732 T2623 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 638732 T2623 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 638733 T2623 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 638733 T2623 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 638733 T2623 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 638733 T2623 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 638734 T2623 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 638734 T2623 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 638735 T2623 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 638738 T2623 oass.SolrIndexSearcher.<init> Opening Searcher@1b8dbd9 main
[junit4:junit4] 2> 638739 T2623 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 638739 T2623 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 638742 T2624 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b8dbd9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 638743 T2623 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 638744 T2623 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:44345 collection:control_collection shard:shard1
[junit4:junit4] 2> 638744 T2623 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 638750 T2623 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 638752 T2623 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 638752 T2623 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 638752 T2623 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:44345/collection1/
[junit4:junit4] 2> 638752 T2623 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 638752 T2623 oasc.SyncStrategy.syncToMe http://127.0.0.1:44345/collection1/ has no replicas
[junit4:junit4] 2> 638753 T2623 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:44345/collection1/
[junit4:junit4] 2> 638753 T2623 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 639266 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 639271 T2620 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> 639315 T2623 oasc.ZkController.register We are http://127.0.0.1:44345/collection1/ and leader is http://127.0.0.1:44345/collection1/
[junit4:junit4] 2> 639316 T2623 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44345
[junit4:junit4] 2> 639316 T2623 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 639316 T2623 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 639316 T2623 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 639318 T2623 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 639318 T2598 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 639319 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 639319 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 639324 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 639325 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 639327 T2627 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7df757 name:ZooKeeperConnection Watcher:127.0.0.1:38072/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 639327 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 639328 T2598 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 639330 T2598 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 639402 T2598 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 639404 T2598 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:35839
[junit4:junit4] 2> 639405 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 639405 T2598 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 639405 T2598 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371954498046
[junit4:junit4] 2> 639406 T2598 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371954498046/solr.xml
[junit4:junit4] 2> 639406 T2598 oasc.CoreContainer.<init> New CoreContainer 22169193
[junit4:junit4] 2> 639406 T2598 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371954498046/'
[junit4:junit4] 2> 639407 T2598 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371954498046/'
[junit4:junit4] 2> 639450 T2598 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 639450 T2598 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 639451 T2598 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 639451 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 639451 T2598 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 639452 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 639452 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 639453 T2598 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 639453 T2598 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 639454 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 639464 T2598 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 639464 T2598 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38072/solr
[junit4:junit4] 2> 639465 T2598 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 639466 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 639467 T2638 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15a36f0 name:ZooKeeperConnection Watcher:127.0.0.1:38072 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 639467 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 639469 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 639472 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 639473 T2640 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1046df4 name:ZooKeeperConnection Watcher:127.0.0.1:38072/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 639473 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 639476 T2598 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 640479 T2598 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35839_
[junit4:junit4] 2> 640481 T2598 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:35839_
[junit4:junit4] 2> 640483 T2620 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> 640485 T2640 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 640485 T2627 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 640486 T2620 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 640489 T2641 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 640490 T2641 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 640776 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 640777 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44345",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:44345__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:44345_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":"shard1"}
[junit4:junit4] 2> 640782 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35839",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:35839_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":null}
[junit4:junit4] 2> 640783 T2621 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 3
[junit4:junit4] 2> 640783 T2621 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 640789 T2627 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> 640789 T2620 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> 640789 T2640 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> 641491 T2641 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371954498046/collection1
[junit4:junit4] 2> 641492 T2641 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 641492 T2641 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 641493 T2641 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 641493 T2641 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371954498046/collection1/'
[junit4:junit4] 2> 641494 T2641 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371954498046/collection1/lib/README' to classloader
[junit4:junit4] 2> 641494 T2641 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371954498046/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 641519 T2641 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 641551 T2641 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 641552 T2641 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 641556 T2641 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 641922 T2641 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 641928 T2641 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 641930 T2641 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 641940 T2641 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 641944 T2641 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 641948 T2641 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 641949 T2641 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 641949 T2641 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 641950 T2641 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 641951 T2641 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 641951 T2641 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 641951 T2641 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 641951 T2641 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371954498046/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty1/
[junit4:junit4] 2> 641951 T2641 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@144ee4d
[junit4:junit4] 2> 641952 T2641 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 641953 T2641 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty1
[junit4:junit4] 2> 641953 T2641 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty1/index/
[junit4:junit4] 2> 641953 T2641 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 641954 T2641 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty1/index
[junit4:junit4] 2> 641970 T2641 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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 641970 T2641 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 641973 T2641 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 641973 T2641 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 641974 T2641 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 641976 T2641 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 641977 T2641 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 641977 T2641 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 641978 T2641 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 641979 T2641 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 641980 T2641 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 641985 T2641 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 641994 T2641 oass.SolrIndexSearcher.<init> Opening Searcher@6eca0d main
[junit4:junit4] 2> 641995 T2641 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 641995 T2641 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 642007 T2642 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6eca0d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 642009 T2641 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 642009 T2641 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:35839 collection:collection1 shard:shard2
[junit4:junit4] 2> 642010 T2641 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 642015 T2641 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 642016 T2641 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 642016 T2641 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 642017 T2641 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:35839/collection1/
[junit4:junit4] 2> 642017 T2641 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 642017 T2641 oasc.SyncStrategy.syncToMe http://127.0.0.1:35839/collection1/ has no replicas
[junit4:junit4] 2> 642017 T2641 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:35839/collection1/
[junit4:junit4] 2> 642017 T2641 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 642296 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 642304 T2627 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> 642304 T2640 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> 642304 T2620 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> 642322 T2641 oasc.ZkController.register We are http://127.0.0.1:35839/collection1/ and leader is http://127.0.0.1:35839/collection1/
[junit4:junit4] 2> 642322 T2641 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35839
[junit4:junit4] 2> 642323 T2641 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 642323 T2641 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 642324 T2641 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 642326 T2641 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 642328 T2598 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 642329 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 642330 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 642423 T2598 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 642425 T2598 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50778
[junit4:junit4] 2> 642425 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 642426 T2598 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 642426 T2598 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371954501053
[junit4:junit4] 2> 642427 T2598 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371954501053/solr.xml
[junit4:junit4] 2> 642427 T2598 oasc.CoreContainer.<init> New CoreContainer 26577907
[junit4:junit4] 2> 642427 T2598 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371954501053/'
[junit4:junit4] 2> 642428 T2598 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371954501053/'
[junit4:junit4] 2> 642473 T2598 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 642474 T2598 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 642474 T2598 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 642475 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 642475 T2598 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 642475 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 642476 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 642476 T2598 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 642476 T2598 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 642477 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 642480 T2598 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 642481 T2598 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38072/solr
[junit4:junit4] 2> 642481 T2598 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 642482 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 642484 T2654 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@68fedb name:ZooKeeperConnection Watcher:127.0.0.1:38072 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 642484 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 642485 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 642489 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 642490 T2656 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@412fe3 name:ZooKeeperConnection Watcher:127.0.0.1:38072/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 642490 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 642494 T2598 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 643497 T2598 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50778_
[junit4:junit4] 2> 643498 T2598 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50778_
[junit4:junit4] 2> 643500 T2627 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 643501 T2627 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> 643501 T2640 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 643502 T2620 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 643502 T2640 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> 643502 T2656 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 643502 T2620 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> 643506 T2657 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 643506 T2657 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 643810 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 643811 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35839",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:35839__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:35839_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":"shard2"}
[junit4:junit4] 2> 643815 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50778",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:50778_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":null}
[junit4:junit4] 2> 643816 T2621 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 643816 T2621 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 643818 T2640 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> 643819 T2627 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> 643819 T2656 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> 643819 T2620 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> 644507 T2657 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371954501053/collection1
[junit4:junit4] 2> 644507 T2657 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 644508 T2657 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 644508 T2657 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 644509 T2657 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371954501053/collection1/'
[junit4:junit4] 2> 644510 T2657 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371954501053/collection1/lib/README' to classloader
[junit4:junit4] 2> 644510 T2657 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371954501053/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 644539 T2657 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 644575 T2657 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 644576 T2657 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 644580 T2657 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 644941 T2657 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 644947 T2657 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 644949 T2657 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 644958 T2657 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 644961 T2657 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 644964 T2657 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 644964 T2657 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 644965 T2657 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 644965 T2657 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 644976 T2657 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 644976 T2657 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 644977 T2657 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 644977 T2657 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371954501053/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty2/
[junit4:junit4] 2> 644977 T2657 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@144ee4d
[junit4:junit4] 2> 644978 T2657 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 644978 T2657 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty2
[junit4:junit4] 2> 644979 T2657 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty2/index/
[junit4:junit4] 2> 644979 T2657 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 644980 T2657 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty2/index
[junit4:junit4] 2> 644989 T2657 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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 644990 T2657 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 644992 T2657 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 644992 T2657 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 644993 T2657 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 644993 T2657 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 644994 T2657 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 644994 T2657 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 644994 T2657 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 644995 T2657 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 644995 T2657 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 644997 T2657 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 645005 T2657 oass.SolrIndexSearcher.<init> Opening Searcher@a96f0f main
[junit4:junit4] 2> 645006 T2657 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 645006 T2657 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 645012 T2658 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@a96f0f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 645014 T2657 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 645014 T2657 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50778 collection:collection1 shard:shard1
[junit4:junit4] 2> 645015 T2657 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 645019 T2657 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 645020 T2657 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 645021 T2657 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 645021 T2657 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50778/collection1/
[junit4:junit4] 2> 645021 T2657 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 645021 T2657 oasc.SyncStrategy.syncToMe http://127.0.0.1:50778/collection1/ has no replicas
[junit4:junit4] 2> 645021 T2657 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50778/collection1/
[junit4:junit4] 2> 645022 T2657 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 645322 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 645327 T2656 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> 645327 T2627 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> 645327 T2640 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> 645327 T2620 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> 645376 T2657 oasc.ZkController.register We are http://127.0.0.1:50778/collection1/ and leader is http://127.0.0.1:50778/collection1/
[junit4:junit4] 2> 645376 T2657 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50778
[junit4:junit4] 2> 645376 T2657 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 645377 T2657 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 645377 T2657 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 645378 T2657 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 645379 T2598 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 645379 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 645380 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 645459 T2598 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 645461 T2598 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:44616
[junit4:junit4] 2> 645461 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 645462 T2598 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 645462 T2598 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371954504099
[junit4:junit4] 2> 645462 T2598 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371954504099/solr.xml
[junit4:junit4] 2> 645463 T2598 oasc.CoreContainer.<init> New CoreContainer 23698439
[junit4:junit4] 2> 645463 T2598 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371954504099/'
[junit4:junit4] 2> 645464 T2598 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371954504099/'
[junit4:junit4] 2> 645516 T2598 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 645516 T2598 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 645517 T2598 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 645517 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 645518 T2598 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 645518 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 645518 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 645519 T2598 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 645519 T2598 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 645520 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 645525 T2598 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 645525 T2598 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38072/solr
[junit4:junit4] 2> 645526 T2598 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 645526 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 645528 T2670 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1e854ee name:ZooKeeperConnection Watcher:127.0.0.1:38072 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 645528 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 645709 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 645712 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 645715 T2672 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b7d46d name:ZooKeeperConnection Watcher:127.0.0.1:38072/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 645715 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 645718 T2598 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 646721 T2598 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44616_
[junit4:junit4] 2> 646722 T2598 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:44616_
[junit4:junit4] 2> 646724 T2640 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> 646724 T2620 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> 646725 T2672 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 646725 T2656 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 646725 T2627 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 646725 T2656 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> 646725 T2627 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> 646730 T2640 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 646730 T2620 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 646755 T2673 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 646755 T2673 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 646831 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 646832 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50778",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50778__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:50778_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":"shard1"}
[junit4:junit4] 2> 646835 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44616",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44616_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":null}
[junit4:junit4] 2> 646835 T2621 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 646835 T2621 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 646838 T2656 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> 646838 T2640 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> 646838 T2672 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> 646838 T2627 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> 646838 T2620 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> 647756 T2673 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371954504099/collection1
[junit4:junit4] 2> 647757 T2673 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 647758 T2673 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 647758 T2673 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 647759 T2673 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371954504099/collection1/'
[junit4:junit4] 2> 647759 T2673 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371954504099/collection1/lib/README' to classloader
[junit4:junit4] 2> 647760 T2673 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371954504099/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 647806 T2673 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 647846 T2673 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 647848 T2673 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 647851 T2673 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 648215 T2673 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 648220 T2673 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 648223 T2673 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 648233 T2673 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 648235 T2673 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 648238 T2673 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 648239 T2673 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 648239 T2673 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 648239 T2673 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 648240 T2673 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 648240 T2673 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 648240 T2673 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 648241 T2673 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371954504099/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty3/
[junit4:junit4] 2> 648241 T2673 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@144ee4d
[junit4:junit4] 2> 648241 T2673 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 648242 T2673 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty3
[junit4:junit4] 2> 648242 T2673 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty3/index/
[junit4:junit4] 2> 648242 T2673 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 648243 T2673 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty3/index
[junit4:junit4] 2> 648246 T2673 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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 648247 T2673 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 648249 T2673 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 648249 T2673 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 648250 T2673 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 648250 T2673 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 648251 T2673 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 648251 T2673 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 648251 T2673 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 648252 T2673 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 648252 T2673 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 648254 T2673 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 648258 T2673 oass.SolrIndexSearcher.<init> Opening Searcher@ba2a78 main
[junit4:junit4] 2> 648258 T2673 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 648259 T2673 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 648264 T2673 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 648265 T2673 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:44616 collection:collection1 shard:shard3
[junit4:junit4] 2> 648265 T2673 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4:junit4] 2> 648266 T2674 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ba2a78 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 648272 T2673 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 648274 T2673 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 648275 T2673 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 648275 T2673 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:44616/collection1/
[junit4:junit4] 2> 648275 T2673 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 648275 T2673 oasc.SyncStrategy.syncToMe http://127.0.0.1:44616/collection1/ has no replicas
[junit4:junit4] 2> 648276 T2673 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:44616/collection1/
[junit4:junit4] 2> 648276 T2673 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4:junit4] 2> 648343 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 648348 T2640 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> 648348 T2620 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> 648348 T2656 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> 648348 T2627 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> 648348 T2672 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> 648381 T2673 oasc.ZkController.register We are http://127.0.0.1:44616/collection1/ and leader is http://127.0.0.1:44616/collection1/
[junit4:junit4] 2> 648382 T2673 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44616
[junit4:junit4] 2> 648382 T2673 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 648382 T2673 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 648382 T2673 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 648384 T2673 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 648385 T2598 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 648385 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 648386 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 648456 T2598 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 648462 T2598 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52657
[junit4:junit4] 2> 648462 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 648463 T2598 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 648463 T2598 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371954507105
[junit4:junit4] 2> 648464 T2598 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371954507105/solr.xml
[junit4:junit4] 2> 648464 T2598 oasc.CoreContainer.<init> New CoreContainer 29245170
[junit4:junit4] 2> 648465 T2598 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371954507105/'
[junit4:junit4] 2> 648465 T2598 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371954507105/'
[junit4:junit4] 2> 648513 T2598 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 648514 T2598 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 648514 T2598 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 648515 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 648515 T2598 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 648515 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 648516 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 648516 T2598 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 648516 T2598 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 648517 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 648520 T2598 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 648521 T2598 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38072/solr
[junit4:junit4] 2> 648521 T2598 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 648522 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 648526 T2686 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c59344 name:ZooKeeperConnection Watcher:127.0.0.1:38072 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 648526 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 648529 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 648533 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 648534 T2688 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f84afa name:ZooKeeperConnection Watcher:127.0.0.1:38072/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 648534 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 648537 T2598 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 649540 T2598 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52657_
[junit4:junit4] 2> 649541 T2598 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52657_
[junit4:junit4] 2> 649543 T2656 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> 649543 T2672 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> 649545 T2688 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 649545 T2627 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 649545 T2627 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> 649543 T2620 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> 649545 T2640 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 649546 T2640 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> 649546 T2656 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 649547 T2672 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 649548 T2620 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 649552 T2689 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 649552 T2689 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 649853 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 649854 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44616",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:44616__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:44616_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":"shard3"}
[junit4:junit4] 2> 649856 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52657",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:52657_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":null}
[junit4:junit4] 2> 649857 T2621 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 649857 T2621 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 649859 T2672 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> 649859 T2620 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> 649859 T2640 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> 649859 T2656 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> 649859 T2627 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> 649859 T2688 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> 650554 T2689 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371954507105/collection1
[junit4:junit4] 2> 650554 T2689 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 650555 T2689 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 650555 T2689 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 650556 T2689 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371954507105/collection1/'
[junit4:junit4] 2> 650556 T2689 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371954507105/collection1/lib/README' to classloader
[junit4:junit4] 2> 650557 T2689 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371954507105/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 650592 T2689 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 650631 T2689 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 650633 T2689 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 650638 T2689 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 650975 T2689 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 650980 T2689 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 650983 T2689 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 650992 T2689 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 650995 T2689 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 650998 T2689 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 650999 T2689 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 650999 T2689 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 650999 T2689 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 651000 T2689 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 651000 T2689 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 651001 T2689 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 651001 T2689 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371954507105/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty4/
[junit4:junit4] 2> 651001 T2689 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@144ee4d
[junit4:junit4] 2> 651002 T2689 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 651002 T2689 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty4
[junit4:junit4] 2> 651003 T2689 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty4/index/
[junit4:junit4] 2> 651003 T2689 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 651003 T2689 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty4/index
[junit4:junit4] 2> 651007 T2689 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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 651007 T2689 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 651009 T2689 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 651009 T2689 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 651010 T2689 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 651010 T2689 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 651011 T2689 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 651011 T2689 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 651011 T2689 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 651012 T2689 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 651012 T2689 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 651014 T2689 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 651017 T2689 oass.SolrIndexSearcher.<init> Opening Searcher@16f73c9 main
[junit4:junit4] 2> 651017 T2689 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 651017 T2689 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 651022 T2690 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@16f73c9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 651025 T2689 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 651025 T2689 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52657 collection:collection1 shard:shard2
[junit4:junit4] 2> 651028 T2689 oasc.ZkController.register We are http://127.0.0.1:52657/collection1/ and leader is http://127.0.0.1:35839/collection1/
[junit4:junit4] 2> 651028 T2689 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52657
[junit4:junit4] 2> 651028 T2689 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 651028 T2689 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1574 name=collection1 org.apache.solr.core.SolrCore@3e9a7f url=http://127.0.0.1:52657/collection1 node=127.0.0.1:52657_ C1574_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:52657, collection=collection1, node_name=127.0.0.1:52657_, core=collection1}
[junit4:junit4] 2> 651029 T2691 C1574 P52657 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 651029 T2689 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 651029 T2691 C1574 P52657 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 651030 T2691 C1574 P52657 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 651030 T2691 C1574 P52657 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 651031 T2598 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 651031 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 651032 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 651041 T2691 C1574 P52657 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 651045 T2634 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:52657__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 651124 T2598 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 651125 T2598 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54798
[junit4:junit4] 2> 651126 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 651126 T2598 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 651127 T2598 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371954509753
[junit4:junit4] 2> 651127 T2598 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371954509753/solr.xml
[junit4:junit4] 2> 651127 T2598 oasc.CoreContainer.<init> New CoreContainer 10792231
[junit4:junit4] 2> 651128 T2598 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371954509753/'
[junit4:junit4] 2> 651128 T2598 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371954509753/'
[junit4:junit4] 2> 651175 T2598 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 651176 T2598 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 651176 T2598 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 651176 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 651177 T2598 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 651177 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 651177 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 651178 T2598 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 651178 T2598 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 651178 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 651182 T2598 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 651183 T2598 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38072/solr
[junit4:junit4] 2> 651183 T2598 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 651185 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 651186 T2703 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@126202b name:ZooKeeperConnection Watcher:127.0.0.1:38072 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 651187 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 651189 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 651193 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 651194 T2705 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@52ce2f name:ZooKeeperConnection Watcher:127.0.0.1:38072/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 651194 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 651197 T2598 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 651364 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 651365 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52657",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:52657__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52657_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":"shard2"}
[junit4:junit4] 2> 651368 T2640 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> 651368 T2688 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> 651368 T2627 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> 651368 T2656 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> 651368 T2620 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> 651368 T2705 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> 651368 T2672 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> 652046 T2634 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:52657__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 652046 T2634 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&coreNodeName=127.0.0.1:52657__collection1&wt=javabin&action=PREPRECOVERY&version=2&onlyIfLeader=true&nodeName=127.0.0.1:52657_&core=collection1&checkLive=true} status=0 QTime=1001
[junit4:junit4] 2> 652200 T2598 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54798_
[junit4:junit4] 2> 652201 T2598 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54798_
[junit4:junit4] 2> 652203 T2688 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> 652203 T2640 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 652203 T2627 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 652203 T2656 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> 652204 T2620 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 652203 T2705 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> 652204 T2620 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> 652204 T2627 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> 652204 T2640 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> 652204 T2672 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 652205 T2688 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 652205 T2672 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> 652206 T2656 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 652206 T2705 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 652209 T2706 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 652209 T2706 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 652873 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 652874 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54798",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54798_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":null}
[junit4:junit4] 2> 652874 T2621 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 652874 T2621 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 652877 T2672 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> 652877 T2620 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> 652877 T2688 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> 652877 T2656 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> 652877 T2627 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> 652877 T2640 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> 652877 T2705 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> 653211 T2706 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371954509753/collection1
[junit4:junit4] 2> 653211 T2706 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 653212 T2706 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 653212 T2706 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 653213 T2706 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371954509753/collection1/'
[junit4:junit4] 2> 653214 T2706 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371954509753/collection1/lib/README' to classloader
[junit4:junit4] 2> 653214 T2706 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371954509753/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 653238 T2706 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 653270 T2706 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 653271 T2706 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 653274 T2706 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 653624 T2706 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 653629 T2706 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 653632 T2706 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 653642 T2706 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 653646 T2706 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 653649 T2706 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 653650 T2706 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 653650 T2706 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 653651 T2706 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 653651 T2706 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 653652 T2706 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 653652 T2706 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 653652 T2706 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371954509753/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty5/
[junit4:junit4] 2> 653653 T2706 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@144ee4d
[junit4:junit4] 2> 653653 T2706 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 653653 T2706 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty5
[junit4:junit4] 2> 653654 T2706 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty5/index/
[junit4:junit4] 2> 653654 T2706 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 653654 T2706 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty5/index
[junit4:junit4] 2> 653657 T2706 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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 653658 T2706 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 653660 T2706 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 653660 T2706 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 653661 T2706 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 653661 T2706 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 653662 T2706 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 653662 T2706 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 653662 T2706 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 653663 T2706 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 653663 T2706 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 653665 T2706 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 653668 T2706 oass.SolrIndexSearcher.<init> Opening Searcher@5dec8f main
[junit4:junit4] 2> 653669 T2706 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 653669 T2706 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 653673 T2707 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5dec8f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 653674 T2706 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 653674 T2706 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54798 collection:collection1 shard:shard1
[junit4:junit4] 2> 653677 T2706 oasc.ZkController.register We are http://127.0.0.1:54798/collection1/ and leader is http://127.0.0.1:50778/collection1/
[junit4:junit4] 2> 653677 T2706 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54798
[junit4:junit4] 2> 653677 T2706 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 653677 T2706 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1575 name=collection1 org.apache.solr.core.SolrCore@1316564 url=http://127.0.0.1:54798/collection1 node=127.0.0.1:54798_ C1575_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:54798, collection=collection1, node_name=127.0.0.1:54798_, core=collection1}
[junit4:junit4] 2> 653678 T2708 C1575 P54798 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 653678 T2706 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 653678 T2708 C1575 P54798 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 653678 T2708 C1575 P54798 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 653679 T2708 C1575 P54798 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 653679 T2598 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 653680 T2708 C1575 P54798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 653680 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 653680 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 653688 T2649 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:54798__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 653756 T2598 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 653758 T2598 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59054
[junit4:junit4] 2> 653758 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 653759 T2598 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 653759 T2598 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371954512400
[junit4:junit4] 2> 653759 T2598 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371954512400/solr.xml
[junit4:junit4] 2> 653760 T2598 oasc.CoreContainer.<init> New CoreContainer 3402420
[junit4:junit4] 2> 653760 T2598 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371954512400/'
[junit4:junit4] 2> 653760 T2598 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371954512400/'
[junit4:junit4] 2> 653805 T2598 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 653806 T2598 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 653806 T2598 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 653807 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 653807 T2598 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 653807 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 653808 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 653808 T2598 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 653808 T2598 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 653809 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 653812 T2598 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 653813 T2598 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38072/solr
[junit4:junit4] 2> 653813 T2598 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 653814 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 653816 T2720 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@161bab4 name:ZooKeeperConnection Watcher:127.0.0.1:38072 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 653816 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 653817 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 653821 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 653823 T2722 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@26fd79 name:ZooKeeperConnection Watcher:127.0.0.1:38072/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 653823 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 653827 T2598 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C1576 name=collection1 org.apache.solr.core.SolrCore@3e9a7f url=http://127.0.0.1:52657/collection1 node=127.0.0.1:52657_ C1576_STATE=coll:collection1 core:collection1 props:{state=recovering, base_url=http://127.0.0.1:52657, collection=collection1, node_name=127.0.0.1:52657_, core=collection1, shard=shard2}
[junit4:junit4] 2> 654047 T2691 C1576 P52657 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:35839/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 654047 T2691 C1576 P52657 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52657 START replicas=[http://127.0.0.1:35839/collection1/] nUpdates=100
[junit4:junit4] 2> 654048 T2691 C1576 P52657 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 654048 T2691 C1576 P52657 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 654048 T2691 C1576 P52657 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 654048 T2691 C1576 P52657 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 654048 T2691 C1576 P52657 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 654048 T2691 C1576 P52657 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:35839/collection1/. core=collection1
[junit4:junit4] 2> 654049 T2691 C1576 P52657 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1577 name=collection1 org.apache.solr.core.SolrCore@1509284 url=http://127.0.0.1:35839/collection1 node=127.0.0.1:35839_ C1577_STATE=coll:collection1 core:collection1 props:{state=active, base_url=http://127.0.0.1:35839, collection=collection1, node_name=127.0.0.1:35839_, core=collection1, shard=shard2, leader=true}
[junit4:junit4] 2> 654055 T2635 C1577 P35839 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&distrib=false&qt=/get&getVersions=100&version=2} status=0 QTime=0
[junit4:junit4] 2> 654057 T2634 C1577 P35839 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 654059 T2634 C1577 P35839 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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 654059 T2634 C1577 P35839 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 654068 T2634 C1577 P35839 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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 654069 T2634 C1577 P35839 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 654070 T2634 C1577 P35839 oass.SolrIndexSearcher.<init> Opening Searcher@a398d8 realtime
[junit4:junit4] 2> 654070 T2634 C1577 P35839 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 654070 T2634 C1577 P35839 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&wt=javabin&softCommit=false&openSearcher=false&version=2&commit=true&commit_end_point=true} {commit=} 0 13
[junit4:junit4] 2> 654071 T2691 C1576 P52657 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 654072 T2691 C1576 P52657 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 654073 T2636 C1577 P35839 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 654073 T2636 C1577 P35839 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=javabin&qt=/replication&command=indexversion&version=2} status=0 QTime=1
[junit4:junit4] 2> 654074 T2691 C1576 P52657 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 654074 T2691 C1576 P52657 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 654074 T2691 C1576 P52657 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 654076 T2635 C1577 P35839 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=javabin&generation=2&qt=/replication&command=filelist&version=2} status=0 QTime=0
[junit4:junit4] 2> 654077 T2691 C1576 P52657 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 654077 T2691 C1576 P52657 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty4/index.20130623042832793
[junit4:junit4] 2> 654078 T2691 C1576 P52657 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty4/index.20130623042832793 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cc028f fullCopy=false
[junit4:junit4] 2> 654080 T2634 C1577 P35839 oasc.SolrCore.execute [collection1] webapp= path=/replication params={checksum=true&wt=filestream&generation=2&qt=/replication&command=filecontent&file=segments_2} status=0 QTime=0
[junit4:junit4] 2> 654081 T2691 C1576 P52657 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 654089 T2691 C1576 P52657 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 654089 T2691 C1576 P52657 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 654091 T2691 C1576 P52657 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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty4/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 654091 T2691 C1576 P52657 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 654091 T2691 C1576 P52657 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 654092 T2691 C1576 P52657 oass.SolrIndexSearcher.<init> Opening Searcher@10f24fb main
[junit4:junit4] 2> 654093 T2690 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10f24fb main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 654093 T2691 C1576 P52657 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty4/index.20130623042832793 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty4/index.20130623042832793;done=true>>]
[junit4:junit4] 2> 654093 T2691 C1576 P52657 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty4/index.20130623042832793
[junit4:junit4] 2> 654093 T2691 C1576 P52657 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty4/index.20130623042832793
[junit4:junit4] 2> 654094 T2691 C1576 P52657 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 654094 T2691 C1576 P52657 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 654094 T2691 C1576 P52657 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 654094 T2691 C1576 P52657 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 654096 T2691 C1576 P52657 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 654381 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 654382 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54798",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:54798__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:54798_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":"shard1"}
[junit4:junit4] 2> 654385 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52657",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:52657__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52657_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":"shard2"}
[junit4:junit4] 2> 654387 T2705 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> 654388 T2627 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> 654388 T2640 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> 654388 T2688 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> 654388 T2656 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> 654388 T2620 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> 654387 T2672 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> 654387 T2722 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> 654689 T2649 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:54798__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 654689 T2649 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&coreNodeName=127.0.0.1:54798__collection1&wt=javabin&action=PREPRECOVERY&version=2&onlyIfLeader=true&nodeName=127.0.0.1:54798_&core=collection1&checkLive=true} status=0 QTime=1001
[junit4:junit4] 2> 654829 T2598 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59054_
[junit4:junit4] 2> 654849 T2598 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59054_
[junit4:junit4] 2> 654851 T2620 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> 654852 T2640 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> 654851 T2672 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> 654852 T2705 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 654852 T2688 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 654852 T2627 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 654852 T2688 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> 654852 T2705 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> 654852 T2656 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 654853 T2656 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> 654853 T2722 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 654854 T2722 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> 654853 T2627 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> 654855 T2672 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 654855 T2620 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 654855 T2640 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 654859 T2725 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 654859 T2725 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 655892 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 655893 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59054",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59054_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":null}
[junit4:junit4] 2> 655893 T2621 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 655894 T2621 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 655896 T2620 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> 655897 T2640 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> 655897 T2688 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> 655897 T2656 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> 655896 T2627 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> 655896 T2722 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> 655896 T2705 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> 655896 T2672 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> C1575_STATE=coll:collection1 core:collection1 props:{state=recovering, base_url=http://127.0.0.1:54798, collection=collection1, node_name=127.0.0.1:54798_, core=collection1, shard=shard1}
[junit4:junit4] 2> 656690 T2708 C1575 P54798 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50778/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 656690 T2708 C1575 P54798 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:54798 START replicas=[http://127.0.0.1:50778/collection1/] nUpdates=100
[junit4:junit4] 2> 656691 T2708 C1575 P54798 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 656691 T2708 C1575 P54798 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 656691 T2708 C1575 P54798 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 656691 T2708 C1575 P54798 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 656691 T2708 C1575 P54798 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 656692 T2708 C1575 P54798 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50778/collection1/. core=collection1
[junit4:junit4] 2> 656692 T2708 C1575 P54798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1578 name=collection1 org.apache.solr.core.SolrCore@206b31 url=http://127.0.0.1:50778/collection1 node=127.0.0.1:50778_ C1578_STATE=coll:collection1 core:collection1 props:{state=active, base_url=http://127.0.0.1:50778, collection=collection1, node_name=127.0.0.1:50778_, core=collection1, shard=shard1, leader=true}
[junit4:junit4] 2> 656696 T2650 C1578 P50778 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&distrib=false&qt=/get&getVersions=100&version=2} status=0 QTime=1
[junit4:junit4] 2> 656697 T2651 C1578 P50778 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 656699 T2651 C1578 P50778 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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 656700 T2651 C1578 P50778 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 656708 T2651 C1578 P50778 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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 656709 T2651 C1578 P50778 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 656710 T2651 C1578 P50778 oass.SolrIndexSearcher.<init> Opening Searcher@2bffd3 realtime
[junit4:junit4] 2> 656710 T2651 C1578 P50778 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 656710 T2651 C1578 P50778 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&wt=javabin&softCommit=false&openSearcher=false&version=2&commit=true&commit_end_point=true} {commit=} 0 13
[junit4:junit4] 2> 656711 T2708 C1575 P54798 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 656711 T2708 C1575 P54798 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 656713 T2649 C1578 P50778 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 656713 T2649 C1578 P50778 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=javabin&qt=/replication&command=indexversion&version=2} status=0 QTime=1
[junit4:junit4] 2> 656714 T2708 C1575 P54798 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 656714 T2708 C1575 P54798 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 656714 T2708 C1575 P54798 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 656716 T2650 C1578 P50778 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=javabin&generation=2&qt=/replication&command=filelist&version=2} status=0 QTime=0
[junit4:junit4] 2> 656716 T2708 C1575 P54798 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 656717 T2708 C1575 P54798 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty5/index.20130623042835433
[junit4:junit4] 2> 656717 T2708 C1575 P54798 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty5/index.20130623042835433 lockFactory=org.apache.lucene.store.NativeFSLockFactory@19c4650 fullCopy=false
[junit4:junit4] 2> ASYNC NEW_CORE C1579 name=collection1 org.apache.solr.core.SolrCore@206b31 url=http://127.0.0.1:50778/collection1 node=127.0.0.1:50778_ C1579_STATE=coll:collection1 core:collection1 props:{state=active, base_url=http://127.0.0.1:50778, collection=collection1, node_name=127.0.0.1:50778_, core=collection1, shard=shard1, leader=true}
[junit4:junit4] 2> 656731 T2651 C1579 P50778 oasc.SolrCore.execute [collection1] webapp= path=/replication params={checksum=true&wt=filestream&generation=2&qt=/replication&command=filecontent&file=segments_2} status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C1580 name=collection1 org.apache.solr.core.SolrCore@1316564 url=http://127.0.0.1:54798/collection1 node=127.0.0.1:54798_ C1580_STATE=coll:collection1 core:collection1 props:{state=recovering, base_url=http://127.0.0.1:54798, collection=collection1, node_name=127.0.0.1:54798_, core=collection1, shard=shard1}
[junit4:junit4] 2> 656733 T2708 C1580 P54798 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 656739 T2708 C1580 P54798 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 656739 T2708 C1580 P54798 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 656741 T2708 C1580 P54798 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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty5/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 656742 T2708 C1580 P54798 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 656742 T2708 C1580 P54798 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 656743 T2708 C1580 P54798 oass.SolrIndexSearcher.<init> Opening Searcher@a74c12 main
[junit4:junit4] 2> 656744 T2707 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@a74c12 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 656744 T2708 C1580 P54798 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty5/index.20130623042835433 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty5/index.20130623042835433;done=true>>]
[junit4:junit4] 2> 656744 T2708 C1580 P54798 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty5/index.20130623042835433
[junit4:junit4] 2> 656745 T2708 C1580 P54798 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty5/index.20130623042835433
[junit4:junit4] 2> 656745 T2708 C1580 P54798 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 656746 T2708 C1580 P54798 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 656746 T2708 C1580 P54798 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 656746 T2708 C1580 P54798 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 656769 T2708 C1580 P54798 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 656860 T2725 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371954512400/collection1
[junit4:junit4] 2> 656861 T2725 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 656861 T2725 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 656862 T2725 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 656863 T2725 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371954512400/collection1/'
[junit4:junit4] 2> 656863 T2725 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371954512400/collection1/lib/README' to classloader
[junit4:junit4] 2> 656863 T2725 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371954512400/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 656892 T2725 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 656930 T2725 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 656931 T2725 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 656935 T2725 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 657296 T2725 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 657301 T2725 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 657304 T2725 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 657316 T2725 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 657320 T2725 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 657324 T2725 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 657325 T2725 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 657325 T2725 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 657325 T2725 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 657326 T2725 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 657327 T2725 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 657327 T2725 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 657327 T2725 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371954512400/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty6/
[junit4:junit4] 2> 657327 T2725 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@144ee4d
[junit4:junit4] 2> 657328 T2725 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 657328 T2725 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty6
[junit4:junit4] 2> 657329 T2725 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty6/index/
[junit4:junit4] 2> 657329 T2725 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty6/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 657329 T2725 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty6/index
[junit4:junit4] 2> 657333 T2725 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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 657333 T2725 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 657335 T2725 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 657335 T2725 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 657336 T2725 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 657337 T2725 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 657337 T2725 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 657337 T2725 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 657339 T2725 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 657339 T2725 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 657340 T2725 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 657342 T2725 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 657345 T2725 oass.SolrIndexSearcher.<init> Opening Searcher@9f9c37 main
[junit4:junit4] 2> 657346 T2725 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 657346 T2725 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 657350 T2728 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9f9c37 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 657352 T2725 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 657352 T2725 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59054 collection:collection1 shard:shard3
[junit4:junit4] 2> 657356 T2725 oasc.ZkController.register We are http://127.0.0.1:59054/collection1/ and leader is http://127.0.0.1:44616/collection1/
[junit4:junit4] 2> 657356 T2725 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59054
[junit4:junit4] 2> 657356 T2725 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 657356 T2725 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1581 name=collection1 org.apache.solr.core.SolrCore@67f2be url=http://127.0.0.1:59054/collection1 node=127.0.0.1:59054_ C1581_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:59054, collection=collection1, node_name=127.0.0.1:59054_, core=collection1}
[junit4:junit4] 2> 657357 T2729 C1581 P59054 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 657357 T2725 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 657358 T2729 C1581 P59054 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 657358 T2729 C1581 P59054 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 657358 T2729 C1581 P59054 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 657359 T2598 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 657359 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 657359 T2729 C1581 P59054 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 657359 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 657364 T2666 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:59054__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 657401 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 657401 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54798",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:54798__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:54798_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":"shard1"}
[junit4:junit4] 2> 657404 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59054",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59054__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59054_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":"shard3"}
[junit4:junit4] 2> 657407 T2705 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> 657407 T2722 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> 657407 T2656 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> 657407 T2688 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> 657407 T2620 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> 657407 T2627 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> 657407 T2672 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> 657407 T2640 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> 657436 T2598 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 657437 T2598 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:42571
[junit4:junit4] 2> 657438 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 657438 T2598 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 657438 T2598 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371954516079
[junit4:junit4] 2> 657439 T2598 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371954516079/solr.xml
[junit4:junit4] 2> 657439 T2598 oasc.CoreContainer.<init> New CoreContainer 16125445
[junit4:junit4] 2> 657439 T2598 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371954516079/'
[junit4:junit4] 2> 657440 T2598 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371954516079/'
[junit4:junit4] 2> 657494 T2598 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 657494 T2598 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 657495 T2598 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 657495 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 657495 T2598 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 657496 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 657496 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 657496 T2598 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 657497 T2598 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 657497 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 657500 T2598 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 657501 T2598 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38072/solr
[junit4:junit4] 2> 657501 T2598 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 657502 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 657504 T2741 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10dbee2 name:ZooKeeperConnection Watcher:127.0.0.1:38072 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 657504 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 657505 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 657509 T2598 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 657510 T2743 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12e2d7a name:ZooKeeperConnection Watcher:127.0.0.1:38072/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 657510 T2598 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 657513 T2598 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 658364 T2666 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:59054__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 658365 T2666 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&coreNodeName=127.0.0.1:59054__collection1&wt=javabin&action=PREPRECOVERY&version=2&onlyIfLeader=true&nodeName=127.0.0.1:59054_&core=collection1&checkLive=true} status=0 QTime=1002
[junit4:junit4] 2> 658516 T2598 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42571_
[junit4:junit4] 2> 658517 T2598 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42571_
[junit4:junit4] 2> 658519 T2705 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> 658519 T2672 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> 658520 T2688 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> 658520 T2722 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> 658520 T2640 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 658520 T2656 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 658520 T2620 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 658520 T2640 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> 658520 T2743 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 658520 T2627 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 658521 T2705 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 658521 T2627 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> 658522 T2672 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 658521 T2620 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> 658521 T2656 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> 658522 T2688 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 658522 T2722 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 658526 T2744 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 658526 T2744 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 658912 T2621 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 658913 T2621 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42571",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:42571_",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard":null}
[junit4:junit4] 2> 658913 T2621 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 658913 T2621 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 658928 T2620 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> 658928 T2722 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> 658928 T2705 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> 658928 T2640 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> 658928 T2743 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> 658928 T2672 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> 658928 T2688 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> 658928 T2656 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> 658928 T2627 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> 659528 T2744 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371954516079/collection1
[junit4:junit4] 2> 659528 T2744 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 659529 T2744 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 659529 T2744 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 659530 T2744 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371954516079/collection1/'
[junit4:junit4] 2> 659530 T2744 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371954516079/collection1/lib/README' to classloader
[junit4:junit4] 2> 659531 T2744 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371954516079/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 659555 T2744 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 659586 T2744 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 659588 T2744 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 659591 T2744 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 659927 T2744 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 659934 T2744 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 659936 T2744 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 659945 T2744 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 659949 T2744 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 659953 T2744 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 659954 T2744 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 659954 T2744 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 659955 T2744 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 659955 T2744 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 659956 T2744 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 659956 T2744 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 659956 T2744 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371954516079/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty7/
[junit4:junit4] 2> 659957 T2744 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@144ee4d
[junit4:junit4] 2> 659957 T2744 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 659958 T2744 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty7
[junit4:junit4] 2> 659958 T2744 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty7/index/
[junit4:junit4] 2> 659958 T2744 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty7/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 659959 T2744 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty7/index
[junit4:junit4] 2> 659962 T2744 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/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty7/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 659963 T2744 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 659965 T2744 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 659965 T2744 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 659965 T2744 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 659966 T2744 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 659966 T2744 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 659967 T2744 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 659967 T2744 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 659967 T2744 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 659968 T2744 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 659969 T2744 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 659972 T2744 oass.SolrIndexSearcher.<init> Opening Searcher@1b41734 main
[junit4:junit4] 2> 659973 T2744 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 659973 T2744 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 659977 T2745 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b41734 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 659978 T2744 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 659978 T2744 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42571 collection:collection1 shard:shard2
[junit4:junit4] 2> 659981 T2744 oasc.ZkController.register We are http://127.0.0.1:42571/collection1/ and leader is http://127.0.0.1:35839/collection1/
[junit4:junit4] 2> 659981 T2744 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42571
[junit4:junit4] 2> 659981 T2744 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 659981 T2744 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1582 name=collection1 org.apache.solr.core.SolrCore@f824e1 url=http://127.0.0.1:42571/collection1 node=127.0.0.1:42571_ C1582_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:42571, collection=collection1, node_name=127.0.0.1:42571_, core=collection1}
[junit4:junit4] 2> 659982 T2746 C1582 P42571 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 659982 T2744 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 659982 T2746 C1582 P42571 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 659983 T2746 C1582 P42571 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 659983 T2746 C1582 P42571 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 659983 T2598 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 659984 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 659984 T2746 C1582 P42571 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 659984 T2598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 659989 T2635 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:42571__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 660059 T2598 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 660061 T2598 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54293
[junit4:junit4] 2> 660062 T2598 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 660063 T2598 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 660063 T2598 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty8-1371954518704
[junit4:junit4] 2> 660064 T2598 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty8-1371954518704/solr.xml
[junit4:junit4] 2> 660064 T2598 oasc.CoreContainer.<init> New CoreContainer 26751337
[junit4:junit4] 2> 660065 T2598 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty8-1371954518704/'
[junit4:junit4] 2> 660066 T2598 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty8-1371954518704/'
[junit4:junit4] 2> 660127 T2598 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 660128 T2598 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 660128 T2598 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 660129 T2598 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 660129 T2598
[...truncated too long message...]
T2598 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 741256 T2598 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 32802
[junit4:junit4] 2> 741257 T2598 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1375901
[junit4:junit4] 2> 741397 T2779 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 741397 T2779 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> 741398 T2779 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 742259 T2598 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 742260 T2598 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 742262 T2598 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@e97b9e
[junit4:junit4] 2> 742264 T2598 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=4,autocommit maxTime=5000ms,autocommits=3,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=57,cumulative_deletesById=29,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 742266 T2598 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 742266 T2598 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 742267 T2598 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 742269 T2598 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 742270 T2598 oasc.CachingDirectoryFactory.close Closing StandardDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 742270 T2598 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty11 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty11;done=false>>]
[junit4:junit4] 2> 742271 T2598 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty11
[junit4:junit4] 2> 742271 T2598 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty11/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty11/index;done=false>>]
[junit4:junit4] 2> 742272 T2598 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371954494368/jetty11/index
[junit4:junit4] 2> 742273 T2943 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89912409743032346-127.0.0.1:32802_-n_0000000011) am no longer a leader.
[junit4:junit4] 2> 742275 T2627 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> 742277 T2627 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4:junit4] 2> 742296 T2598 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 742349 T2598 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 51729
[junit4:junit4] 2> 742351 T2600 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f6edc3ba20004, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 742352 T2598 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 44345
[junit4:junit4] 2> 742391 T2598 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 742393 T2598 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:38072 38072
[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> 742396 T2598 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 743575 T2817 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 743575 T2817 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> 743575 T2817 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 863410 T2598 oas.SolrTestCaseJ4.endTrackingSearchers ERROR ERROR: SolrIndexSearcher opens=47 closes=46
[junit4:junit4] 2> NOTE: test params are: codec=DummyCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=DUMMY, chunkSize=351), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=DUMMY, chunkSize=351)), sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=ja_JP_JP_#u-ca-japanese, timezone=Africa/Kigali
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=2,free=53157656,total=297795584
[junit4:junit4] 2> NOTE: All tests run in this JVM: [AlternateDirectoryTest, TestSolrCoreProperties, TestFuzzyAnalyzedSuggestions, PreAnalyzedFieldTest, TestReplicationHandler, LukeRequestHandlerTest, TestPseudoReturnFields, TestPhraseSuggestions, TestWriterPerf, SimpleFacetsTest, DistributedQueryElevationComponentTest, TestCloudManagedSchemaAddField, TestDocumentBuilder, IndexSchemaTest, SolrTestCaseJ4Test, TestSearchPerf, PolyFieldTest, UpdateRequestProcessorFactoryTest, QueryParsingTest, TestCopyFieldCollectionResource, TestStressVersions, TestFieldTypeCollectionResource, TestSerializedLuceneMatchVersion, SOLR749Test, ReturnFieldsTest, PeerSyncTest, TestCloudManagedSchema, SyncSliceTest, TestSort, TestBadConfig, TestIBSimilarityFactory, TestReversedWildcardFilterFactory, BinaryUpdateRequestHandlerTest, PreAnalyzedUpdateProcessorTest, TestRemoteStreaming, TestJoin, TestClassNameShortening, TestGroupingSearch, CacheHeaderTest, SolrCoreTest, SynonymTokenizerTest, TestSolrIndexConfig, LoggingHandlerTest, ShowFileRequestHandlerTest, TestCharFilters, JsonLoaderTest, BasicFunctionalityTest, SuggesterFSTTest, TestLFUCache, TestConfig, TestSchemaVersionResource, TestSurroundQueryParser, CoreAdminHandlerTest, ResponseLogComponentTest, FastVectorHighlighterTest, UnloadDistributedZkTest, TestRandomDVFaceting, ClusterStateUpdateTest, SolrInfoMBeanTest, SoftAutoCommitTest, TestValueSourceCache, DocumentBuilderTest, TestDefaultSearchFieldResource, TestSolrQueryParserResource, TestExtendedDismaxParser, DirectSolrConnectionTest, AutoCommitTest, SliceStateUpdateTest, ResourceLoaderTest, SpellingQueryConverterTest, WordBreakSolrSpellCheckerTest, ChaosMonkeyNothingIsSafeTest, BasicDistributedZkTest, ChaosMonkeySafeLeaderTest]
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeySafeLeaderTest -Dtests.seed=96A2A274AD65FF78 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ja_JP_JP_#u-ca-japanese -Dtests.timezone=Africa/Kigali -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR 0.00s J0 | ChaosMonkeySafeLeaderTest (suite) <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: ERROR: SolrIndexSearcher opens=47 closes=46
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([96A2A274AD65FF78]:0)
[junit4:junit4] > at org.apache.solr.SolrTestCaseJ4.endTrackingSearchers(SolrTestCaseJ4.java:257)
[junit4:junit4] > at org.apache.solr.SolrTestCaseJ4.afterClass(SolrTestCaseJ4.java:104)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] Completed on J0 in 227.80s, 1 test, 1 failure <<< FAILURES!
[...truncated 441 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: 297 suites, 1253 tests, 1 suite-level error, 16 ignored (7 assumptions)
Total time: 37 minutes 22 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.8.0-ea-b93 -server -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure