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/25 04:40:16 UTC
[JENKINS] Lucene-Solr-trunk-Linux (64bit/jdk1.8.0-ea-b93) - Build #
6297 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/6297/
Java: 64bit/jdk1.8.0-ea-b93 -XX:+UseCompressedOops -XX:+UseG1GC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.testDistribSearch
Error Message:
shard3 is not consistent. Got 100 from http://127.0.0.1:58326/collection1lastClient and got 59 from http://127.0.0.1:39692/collection1
Stack Trace:
java.lang.AssertionError: shard3 is not consistent. Got 100 from http://127.0.0.1:58326/collection1lastClient and got 59 from http://127.0.0.1:39692/collection1
at __randomizedtesting.SeedInfo.seed([379D4B486BE43D7F:B67BC5501CBB5D43]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:491)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Build Log:
[...truncated 9651 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
[junit4:junit4] 2> 510494 T2055 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 510499 T2055 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-1372127487851
[junit4:junit4] 2> 510499 T2055 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 510500 T2056 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 510600 T2055 oasc.ZkTestServer.run start zk server on port:52063
[junit4:junit4] 2> 510601 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 510679 T2062 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4e35c68c name:ZooKeeperConnection Watcher:127.0.0.1:52063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 510680 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 510680 T2055 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 510684 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 510685 T2064 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@40f2313a name:ZooKeeperConnection Watcher:127.0.0.1:52063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 510685 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 510686 T2055 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 510688 T2055 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 510690 T2055 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 510692 T2055 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 510694 T2055 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> 510694 T2055 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 510697 T2055 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> 510698 T2055 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 510700 T2055 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> 510700 T2055 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 510702 T2055 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> 510703 T2055 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 510704 T2055 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> 510705 T2055 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 510707 T2055 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> 510707 T2055 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 510709 T2055 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> 510710 T2055 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 510712 T2055 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> 510713 T2055 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 510715 T2055 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> 510715 T2055 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 510787 T2055 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 510790 T2055 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40186
[junit4:junit4] 2> 510790 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 510791 T2055 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 510791 T2055 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-1372127488072
[junit4:junit4] 2> 510791 T2055 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-1372127488072/solr.xml
[junit4:junit4] 2> 510791 T2055 oasc.CoreContainer.<init> New CoreContainer 420475741
[junit4:junit4] 2> 510792 T2055 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-1372127488072/'
[junit4:junit4] 2> 510792 T2055 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-1372127488072/'
[junit4:junit4] 2> 510832 T2055 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 510832 T2055 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 510832 T2055 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 510833 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 510833 T2055 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 510833 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 510833 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 510834 T2055 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 510834 T2055 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 510834 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 510838 T2055 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 510838 T2055 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52063/solr
[junit4:junit4] 2> 510838 T2055 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 510839 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 510841 T2075 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@64d8cb76 name:ZooKeeperConnection Watcher:127.0.0.1:52063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 510842 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 510843 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 510847 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 510848 T2077 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4d0f6bd9 name:ZooKeeperConnection Watcher:127.0.0.1:52063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 510849 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 510850 T2055 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 510852 T2055 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 510855 T2055 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 510856 T2055 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40186_
[junit4:junit4] 2> 510857 T2055 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40186_
[junit4:junit4] 2> 510859 T2055 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 510862 T2055 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 510864 T2055 oasc.Overseer.start Overseer (id=89923747044065283-127.0.0.1:40186_-n_0000000000) starting
[junit4:junit4] 2> 510867 T2055 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 510870 T2079 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 510870 T2055 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 510873 T2055 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 510875 T2055 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 510877 T2078 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 510879 T2080 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 510879 T2080 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 512380 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 512381 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40186",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:40186_",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 512381 T2078 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 512381 T2078 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 512385 T2077 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> 512881 T2080 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-1372127488072/collection1
[junit4:junit4] 2> 512881 T2080 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 512882 T2080 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 512882 T2080 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 512883 T2080 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-1372127488072/collection1/'
[junit4:junit4] 2> 512884 T2080 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-1372127488072/collection1/lib/README' to classloader
[junit4:junit4] 2> 512884 T2080 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-1372127488072/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 512921 T2080 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 512965 T2080 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 512967 T2080 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 512972 T2080 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 513473 T2080 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 513478 T2080 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 513481 T2080 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 513492 T2080 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 513496 T2080 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 513500 T2080 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 513501 T2080 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 513501 T2080 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 513501 T2080 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 513502 T2080 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 513503 T2080 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 513503 T2080 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 513503 T2080 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-1372127488072/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/control/data/
[junit4:junit4] 2> 513504 T2080 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@127e2024
[junit4:junit4] 2> 513504 T2080 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 513504 T2080 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-1372127487851/control/data
[junit4:junit4] 2> 513505 T2080 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/control/data/index/
[junit4:junit4] 2> 513505 T2080 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 513506 T2080 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-1372127487851/control/data/index
[junit4:junit4] 2> 513509 T2080 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-1372127487851/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 513510 T2080 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 513512 T2080 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 513513 T2080 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 513513 T2080 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 513514 T2080 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 513514 T2080 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 513515 T2080 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 513515 T2080 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 513515 T2080 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 513516 T2080 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 513518 T2080 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 513521 T2080 oass.SolrIndexSearcher.<init> Opening Searcher@5c7534a7 main
[junit4:junit4] 2> 513521 T2080 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 513521 T2080 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 513525 T2081 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5c7534a7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 513526 T2080 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 513526 T2080 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40186 collection:control_collection shard:shard1
[junit4:junit4] 2> 513527 T2080 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 513532 T2080 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 513534 T2080 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 513534 T2080 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 513534 T2080 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:40186/collection1/
[junit4:junit4] 2> 513534 T2080 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 513535 T2080 oasc.SyncStrategy.syncToMe http://127.0.0.1:40186/collection1/ has no replicas
[junit4:junit4] 2> 513535 T2080 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:40186/collection1/
[junit4:junit4] 2> 513535 T2080 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 513888 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 513895 T2077 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> 513939 T2080 oasc.ZkController.register We are http://127.0.0.1:40186/collection1/ and leader is http://127.0.0.1:40186/collection1/
[junit4:junit4] 2> 513940 T2080 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40186
[junit4:junit4] 2> 513940 T2080 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 513940 T2080 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 513940 T2080 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 513942 T2080 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 513943 T2055 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 513943 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 513944 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 513948 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 513949 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 513951 T2084 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3ec33e3d name:ZooKeeperConnection Watcher:127.0.0.1:52063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 513951 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 513952 T2055 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 513953 T2055 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 514020 T2055 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 514023 T2055 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:33978
[junit4:junit4] 2> 514023 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 514023 T2055 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 514024 T2055 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-1372127491306
[junit4:junit4] 2> 514024 T2055 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-1372127491306/solr.xml
[junit4:junit4] 2> 514024 T2055 oasc.CoreContainer.<init> New CoreContainer 813458715
[junit4:junit4] 2> 514024 T2055 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-1372127491306/'
[junit4:junit4] 2> 514025 T2055 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-1372127491306/'
[junit4:junit4] 2> 514066 T2055 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 514066 T2055 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 514066 T2055 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 514067 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 514067 T2055 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 514067 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 514067 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 514067 T2055 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 514068 T2055 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 514068 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 514071 T2055 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 514072 T2055 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52063/solr
[junit4:junit4] 2> 514072 T2055 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 514073 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 514074 T2095 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@22ded67d name:ZooKeeperConnection Watcher:127.0.0.1:52063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 514075 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 514076 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 514079 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 514081 T2097 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4dd6a4b9 name:ZooKeeperConnection Watcher:127.0.0.1:52063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 514081 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 514083 T2055 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 515086 T2055 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33978_
[junit4:junit4] 2> 515087 T2055 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:33978_
[junit4:junit4] 2> 515090 T2077 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> 515090 T2097 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 515091 T2084 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 515091 T2077 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 515095 T2098 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 515095 T2098 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 515399 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 515400 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40186",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:40186_",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 515403 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:33978",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:33978_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 515403 T2078 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 3
[junit4:junit4] 2> 515403 T2078 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 515407 T2084 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> 515407 T2097 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> 515407 T2077 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> 516097 T2098 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-1372127491306/collection1
[junit4:junit4] 2> 516097 T2098 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 516098 T2098 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 516098 T2098 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 516099 T2098 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-1372127491306/collection1/'
[junit4:junit4] 2> 516099 T2098 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-1372127491306/collection1/lib/README' to classloader
[junit4:junit4] 2> 516100 T2098 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-1372127491306/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 516124 T2098 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 516152 T2098 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 516154 T2098 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 516157 T2098 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 516475 T2098 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 516480 T2098 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 516483 T2098 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 516494 T2098 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 516498 T2098 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 516500 T2098 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 516502 T2098 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 516502 T2098 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 516502 T2098 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 516503 T2098 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 516503 T2098 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 516504 T2098 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 516504 T2098 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-1372127491306/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty1/
[junit4:junit4] 2> 516504 T2098 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@127e2024
[junit4:junit4] 2> 516504 T2098 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 516505 T2098 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-1372127487851/jetty1
[junit4:junit4] 2> 516505 T2098 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty1/index/
[junit4:junit4] 2> 516505 T2098 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 516505 T2098 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-1372127487851/jetty1/index
[junit4:junit4] 2> 516508 T2098 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-1372127487851/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 516508 T2098 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 516510 T2098 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 516510 T2098 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 516511 T2098 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 516511 T2098 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 516512 T2098 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 516512 T2098 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 516512 T2098 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 516513 T2098 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 516513 T2098 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 516514 T2098 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 516517 T2098 oass.SolrIndexSearcher.<init> Opening Searcher@6939468f main
[junit4:junit4] 2> 516518 T2098 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 516518 T2098 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 516521 T2099 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6939468f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 516523 T2098 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 516523 T2098 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:33978 collection:collection1 shard:shard2
[junit4:junit4] 2> 516524 T2098 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 516529 T2098 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 516531 T2098 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 516531 T2098 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 516531 T2098 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:33978/collection1/
[junit4:junit4] 2> 516531 T2098 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 516531 T2098 oasc.SyncStrategy.syncToMe http://127.0.0.1:33978/collection1/ has no replicas
[junit4:junit4] 2> 516532 T2098 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:33978/collection1/
[junit4:junit4] 2> 516532 T2098 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 516912 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 516918 T2084 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> 516918 T2077 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> 516918 T2097 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> 516937 T2098 oasc.ZkController.register We are http://127.0.0.1:33978/collection1/ and leader is http://127.0.0.1:33978/collection1/
[junit4:junit4] 2> 516937 T2098 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:33978
[junit4:junit4] 2> 516938 T2098 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 516938 T2098 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 516938 T2098 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 516940 T2098 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 516941 T2055 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 516942 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 516942 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 517049 T2055 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 517052 T2055 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58326
[junit4:junit4] 2> 517053 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 517053 T2055 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 517054 T2055 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-1372127494299
[junit4:junit4] 2> 517054 T2055 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-1372127494299/solr.xml
[junit4:junit4] 2> 517054 T2055 oasc.CoreContainer.<init> New CoreContainer 1842951246
[junit4:junit4] 2> 517055 T2055 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-1372127494299/'
[junit4:junit4] 2> 517055 T2055 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-1372127494299/'
[junit4:junit4] 2> 517127 T2055 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 517127 T2055 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 517127 T2055 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 517128 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 517128 T2055 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 517128 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 517128 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 517129 T2055 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 517129 T2055 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 517129 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 517132 T2055 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 517133 T2055 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52063/solr
[junit4:junit4] 2> 517133 T2055 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 517134 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 517135 T2111 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d39bdcd name:ZooKeeperConnection Watcher:127.0.0.1:52063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 517136 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 517137 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 517141 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 517142 T2113 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5cad7336 name:ZooKeeperConnection Watcher:127.0.0.1:52063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 517142 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 517145 T2055 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 518147 T2055 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58326_
[junit4:junit4] 2> 518148 T2055 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58326_
[junit4:junit4] 2> 518150 T2077 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 518150 T2097 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 518151 T2084 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 518151 T2084 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> 518153 T2077 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 518154 T2097 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 518154 T2113 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 518159 T2114 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 518160 T2114 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 518425 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 518426 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:33978",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:33978_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 518429 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58326",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:58326_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 518429 T2078 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 518429 T2078 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 518432 T2077 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> 518432 T2097 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> 518432 T2084 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> 518432 T2113 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> 519161 T2114 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-1372127494299/collection1
[junit4:junit4] 2> 519162 T2114 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 519162 T2114 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 519163 T2114 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 519164 T2114 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-1372127494299/collection1/'
[junit4:junit4] 2> 519164 T2114 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-1372127494299/collection1/lib/README' to classloader
[junit4:junit4] 2> 519165 T2114 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-1372127494299/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 519203 T2114 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 519234 T2114 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 519235 T2114 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 519238 T2114 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 519568 T2114 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 519573 T2114 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 519576 T2114 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 519586 T2114 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 519589 T2114 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 519591 T2114 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 519592 T2114 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 519593 T2114 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 519593 T2114 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 519594 T2114 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 519594 T2114 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 519594 T2114 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 519594 T2114 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-1372127494299/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty2/
[junit4:junit4] 2> 519594 T2114 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@127e2024
[junit4:junit4] 2> 519595 T2114 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 519595 T2114 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-1372127487851/jetty2
[junit4:junit4] 2> 519595 T2114 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty2/index/
[junit4:junit4] 2> 519596 T2114 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 519596 T2114 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-1372127487851/jetty2/index
[junit4:junit4] 2> 519599 T2114 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-1372127487851/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 519599 T2114 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 519601 T2114 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 519601 T2114 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 519602 T2114 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 519602 T2114 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 519603 T2114 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 519603 T2114 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 519603 T2114 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 519604 T2114 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 519604 T2114 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 519605 T2114 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 519608 T2114 oass.SolrIndexSearcher.<init> Opening Searcher@77f198b1 main
[junit4:junit4] 2> 519609 T2114 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 519609 T2114 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 519612 T2115 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@77f198b1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 519614 T2114 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 519614 T2114 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58326 collection:collection1 shard:shard3
[junit4:junit4] 2> 519615 T2114 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4:junit4] 2> 519619 T2114 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 519621 T2114 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 519621 T2114 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 519622 T2114 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58326/collection1/
[junit4:junit4] 2> 519622 T2114 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 519622 T2114 oasc.SyncStrategy.syncToMe http://127.0.0.1:58326/collection1/ has no replicas
[junit4:junit4] 2> 519622 T2114 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58326/collection1/
[junit4:junit4] 2> 519622 T2114 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4:junit4] 2> 519937 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 519943 T2097 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> 519943 T2084 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> 519943 T2077 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> 519944 T2113 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> 519977 T2114 oasc.ZkController.register We are http://127.0.0.1:58326/collection1/ and leader is http://127.0.0.1:58326/collection1/
[junit4:junit4] 2> 519977 T2114 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58326
[junit4:junit4] 2> 519977 T2114 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 519978 T2114 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 519978 T2114 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 519979 T2114 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 519980 T2055 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 519981 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 519981 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 520049 T2055 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 520051 T2055 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:41627
[junit4:junit4] 2> 520052 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 520052 T2055 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 520052 T2055 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-1372127497336
[junit4:junit4] 2> 520053 T2055 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-1372127497336/solr.xml
[junit4:junit4] 2> 520053 T2055 oasc.CoreContainer.<init> New CoreContainer 1968275236
[junit4:junit4] 2> 520053 T2055 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-1372127497336/'
[junit4:junit4] 2> 520053 T2055 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-1372127497336/'
[junit4:junit4] 2> 520093 T2055 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 520093 T2055 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 520094 T2055 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 520094 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 520094 T2055 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 520094 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 520094 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 520095 T2055 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 520095 T2055 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 520095 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 520098 T2055 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 520099 T2055 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52063/solr
[junit4:junit4] 2> 520099 T2055 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 520100 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 520101 T2127 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2fa2fc4a name:ZooKeeperConnection Watcher:127.0.0.1:52063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 520102 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 520103 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 520106 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 520109 T2129 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5d540512 name:ZooKeeperConnection Watcher:127.0.0.1:52063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 520109 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 520112 T2055 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 521115 T2055 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41627_
[junit4:junit4] 2> 521116 T2055 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:41627_
[junit4:junit4] 2> 521117 T2113 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> 521117 T2097 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> 521119 T2084 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 521120 T2084 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> 521119 T2129 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 521120 T2077 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 521120 T2077 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> 521121 T2097 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 521121 T2113 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 521126 T2130 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 521126 T2130 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 521449 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 521450 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58326",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "node_name":"127.0.0.1:58326_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 521452 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41627",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:41627_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 521453 T2078 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 521453 T2078 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 521456 T2077 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> 521456 T2097 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> 521456 T2113 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> 521456 T2084 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> 521456 T2129 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> 522128 T2130 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-1372127497336/collection1
[junit4:junit4] 2> 522128 T2130 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 522129 T2130 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 522129 T2130 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 522130 T2130 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-1372127497336/collection1/'
[junit4:junit4] 2> 522131 T2130 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-1372127497336/collection1/lib/README' to classloader
[junit4:junit4] 2> 522131 T2130 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-1372127497336/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 522156 T2130 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 522184 T2130 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 522186 T2130 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 522189 T2130 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 522519 T2130 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 522524 T2130 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 522527 T2130 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 522537 T2130 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 522540 T2130 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 522543 T2130 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 522544 T2130 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 522544 T2130 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 522544 T2130 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 522545 T2130 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 522545 T2130 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 522545 T2130 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 522546 T2130 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-1372127497336/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty3/
[junit4:junit4] 2> 522546 T2130 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@127e2024
[junit4:junit4] 2> 522546 T2130 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 522547 T2130 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-1372127487851/jetty3
[junit4:junit4] 2> 522547 T2130 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty3/index/
[junit4:junit4] 2> 522547 T2130 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 522547 T2130 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-1372127487851/jetty3/index
[junit4:junit4] 2> 522550 T2130 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-1372127487851/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 522550 T2130 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 522552 T2130 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 522552 T2130 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 522553 T2130 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 522553 T2130 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 522554 T2130 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 522554 T2130 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 522554 T2130 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 522554 T2130 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 522555 T2130 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 522556 T2130 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 522559 T2130 oass.SolrIndexSearcher.<init> Opening Searcher@6a653f3 main
[junit4:junit4] 2> 522559 T2130 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 522560 T2130 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 522564 T2131 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6a653f3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 522566 T2130 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 522566 T2130 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:41627 collection:collection1 shard:shard1
[junit4:junit4] 2> 522567 T2130 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 522572 T2130 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 522575 T2130 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 522575 T2130 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 522575 T2130 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:41627/collection1/
[junit4:junit4] 2> 522575 T2130 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 522575 T2130 oasc.SyncStrategy.syncToMe http://127.0.0.1:41627/collection1/ has no replicas
[junit4:junit4] 2> 522576 T2130 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:41627/collection1/
[junit4:junit4] 2> 522576 T2130 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 522960 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 522966 T2084 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> 522966 T2077 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> 522966 T2129 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> 522966 T2097 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> 522966 T2113 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> 522982 T2130 oasc.ZkController.register We are http://127.0.0.1:41627/collection1/ and leader is http://127.0.0.1:41627/collection1/
[junit4:junit4] 2> 522982 T2130 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:41627
[junit4:junit4] 2> 522982 T2130 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 522982 T2130 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 522983 T2130 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 522984 T2130 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 522985 T2055 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 522986 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 522986 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 523093 T2055 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 523096 T2055 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55378
[junit4:junit4] 2> 523097 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 523097 T2055 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 523098 T2055 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-1372127500343
[junit4:junit4] 2> 523098 T2055 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-1372127500343/solr.xml
[junit4:junit4] 2> 523098 T2055 oasc.CoreContainer.<init> New CoreContainer 1623864437
[junit4:junit4] 2> 523099 T2055 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-1372127500343/'
[junit4:junit4] 2> 523099 T2055 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-1372127500343/'
[junit4:junit4] 2> 523164 T2055 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 523164 T2055 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 523165 T2055 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 523165 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 523165 T2055 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 523166 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 523166 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 523167 T2055 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 523167 T2055 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 523167 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 523172 T2055 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 523173 T2055 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52063/solr
[junit4:junit4] 2> 523174 T2055 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 523175 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 523176 T2143 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@28fd8183 name:ZooKeeperConnection Watcher:127.0.0.1:52063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 523176 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 523178 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 523183 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 523185 T2145 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@55ba7b7f name:ZooKeeperConnection Watcher:127.0.0.1:52063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 523186 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 523188 T2055 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 524191 T2055 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55378_
[junit4:junit4] 2> 524193 T2055 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55378_
[junit4:junit4] 2> 524195 T2077 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> 524196 T2113 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> 524196 T2097 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 524196 T2145 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 524196 T2084 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> 524196 T2097 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> 524196 T2129 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 524197 T2129 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> 524197 T2077 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 524198 T2084 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 524198 T2113 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 524203 T2146 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 524203 T2146 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 524471 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 524472 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41627",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:41627_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 524475 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55378",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55378_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 524476 T2078 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 524476 T2078 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 524480 T2113 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> 524480 T2084 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> 524480 T2077 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> 524480 T2129 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> 524480 T2097 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> 524480 T2145 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> 525205 T2146 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-1372127500343/collection1
[junit4:junit4] 2> 525205 T2146 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 525206 T2146 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 525206 T2146 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 525207 T2146 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-1372127500343/collection1/'
[junit4:junit4] 2> 525208 T2146 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-1372127500343/collection1/lib/README' to classloader
[junit4:junit4] 2> 525208 T2146 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-1372127500343/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 525246 T2146 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 525277 T2146 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 525279 T2146 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 525282 T2146 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 525640 T2146 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 525645 T2146 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 525647 T2146 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 525657 T2146 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 525660 T2146 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 525663 T2146 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 525664 T2146 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 525664 T2146 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 525664 T2146 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 525665 T2146 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 525665 T2146 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 525665 T2146 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 525666 T2146 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-1372127500343/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty4/
[junit4:junit4] 2> 525666 T2146 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@127e2024
[junit4:junit4] 2> 525666 T2146 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 525666 T2146 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-1372127487851/jetty4
[junit4:junit4] 2> 525667 T2146 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty4/index/
[junit4:junit4] 2> 525667 T2146 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 525667 T2146 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-1372127487851/jetty4/index
[junit4:junit4] 2> 525671 T2146 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-1372127487851/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 525671 T2146 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 525673 T2146 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 525673 T2146 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 525673 T2146 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 525674 T2146 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 525674 T2146 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 525674 T2146 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 525675 T2146 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 525675 T2146 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 525675 T2146 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 525677 T2146 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 525680 T2146 oass.SolrIndexSearcher.<init> Opening Searcher@64961d69 main
[junit4:junit4] 2> 525680 T2146 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 525680 T2146 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 525684 T2147 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@64961d69 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 525686 T2146 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 525686 T2146 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55378 collection:collection1 shard:shard2
[junit4:junit4] 2> 525688 T2146 oasc.ZkController.register We are http://127.0.0.1:55378/collection1/ and leader is http://127.0.0.1:33978/collection1/
[junit4:junit4] 2> 525688 T2146 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55378
[junit4:junit4] 2> 525688 T2146 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 525689 T2146 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C573 name=collection1 org.apache.solr.core.SolrCore@1e362868 url=http://127.0.0.1:55378/collection1 node=127.0.0.1:55378_ C573_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:55378, state=down, core=collection1, node_name=127.0.0.1:55378_, collection=collection1}
[junit4:junit4] 2> 525689 T2148 C573 P55378 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 525689 T2146 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 525690 T2148 C573 P55378 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 525690 T2148 C573 P55378 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 525690 T2148 C573 P55378 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 525691 T2055 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 525691 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 525691 T2148 C573 P55378 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 525692 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 525696 T2091 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 525777 T2055 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 525782 T2055 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:39692
[junit4:junit4] 2> 525783 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 525783 T2055 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 525783 T2055 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-1372127503048
[junit4:junit4] 2> 525783 T2055 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-1372127503048/solr.xml
[junit4:junit4] 2> 525784 T2055 oasc.CoreContainer.<init> New CoreContainer 798627578
[junit4:junit4] 2> 525784 T2055 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-1372127503048/'
[junit4:junit4] 2> 525784 T2055 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-1372127503048/'
[junit4:junit4] 2> 525824 T2055 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 525824 T2055 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 525825 T2055 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 525825 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 525825 T2055 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 525825 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 525826 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 525826 T2055 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 525826 T2055 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 525826 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 525830 T2055 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 525830 T2055 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52063/solr
[junit4:junit4] 2> 525830 T2055 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 525831 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 525833 T2160 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3a142ae6 name:ZooKeeperConnection Watcher:127.0.0.1:52063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 525833 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 525835 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 525838 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 525840 T2162 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4535dbc4 name:ZooKeeperConnection Watcher:127.0.0.1:52063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 525840 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 525843 T2055 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 525986 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 525987 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55378",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:55378_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 525991 T2077 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> 525991 T2129 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> 525991 T2113 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> 525991 T2084 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> 525991 T2097 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> 525991 T2162 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> 525991 T2145 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> 526696 T2091 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 526697 T2091 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={wt=javabin&coreNodeName=5&action=PREPRECOVERY&state=recovering&core=collection1&onlyIfLeader=true&version=2&checkLive=true&nodeName=127.0.0.1:55378_} status=0 QTime=1001
[junit4:junit4] 2> 526846 T2055 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39692_
[junit4:junit4] 2> 526847 T2055 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39692_
[junit4:junit4] 2> 526851 T2084 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> 526851 T2113 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> 526851 T2129 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> 526851 T2145 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> 526852 T2097 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 526852 T2077 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 526852 T2077 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> 526852 T2162 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 526852 T2097 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> 526853 T2162 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> 526869 T2084 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 526869 T2113 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 526870 T2145 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 526870 T2129 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 526874 T2163 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 526874 T2163 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 527495 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 527496 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39692",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:39692_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 527496 T2078 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 527496 T2078 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 527500 T2145 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> 527500 T2129 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> 527500 T2077 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> 527500 T2162 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> 527500 T2084 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> 527500 T2097 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> 527500 T2113 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> 527876 T2163 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-1372127503048/collection1
[junit4:junit4] 2> 527876 T2163 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 527877 T2163 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 527877 T2163 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 527878 T2163 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-1372127503048/collection1/'
[junit4:junit4] 2> 527879 T2163 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-1372127503048/collection1/lib/README' to classloader
[junit4:junit4] 2> 527879 T2163 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-1372127503048/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 527916 T2163 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 527957 T2163 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 527958 T2163 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 527962 T2163 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 528351 T2163 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 528356 T2163 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 528358 T2163 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 528369 T2163 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 528372 T2163 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 528374 T2163 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 528375 T2163 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 528376 T2163 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 528376 T2163 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 528377 T2163 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 528377 T2163 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 528378 T2163 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 528378 T2163 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-1372127503048/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty5/
[junit4:junit4] 2> 528378 T2163 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@127e2024
[junit4:junit4] 2> 528379 T2163 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 528379 T2163 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-1372127487851/jetty5
[junit4:junit4] 2> 528379 T2163 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty5/index/
[junit4:junit4] 2> 528380 T2163 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 528380 T2163 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-1372127487851/jetty5/index
[junit4:junit4] 2> 528383 T2163 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-1372127487851/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 528383 T2163 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 528385 T2163 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 528385 T2163 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 528385 T2163 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 528386 T2163 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 528386 T2163 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 528386 T2163 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 528387 T2163 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 528387 T2163 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 528387 T2163 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 528389 T2163 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 528392 T2163 oass.SolrIndexSearcher.<init> Opening Searcher@3ab2ff5a main
[junit4:junit4] 2> 528392 T2163 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 528392 T2163 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 528396 T2164 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3ab2ff5a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 528398 T2163 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 528398 T2163 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39692 collection:collection1 shard:shard3
[junit4:junit4] 2> 528400 T2163 oasc.ZkController.register We are http://127.0.0.1:39692/collection1/ and leader is http://127.0.0.1:58326/collection1/
[junit4:junit4] 2> 528401 T2163 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39692
[junit4:junit4] 2> 528401 T2163 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 528401 T2163 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C574 name=collection1 org.apache.solr.core.SolrCore@70e3684a url=http://127.0.0.1:39692/collection1 node=127.0.0.1:39692_ C574_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:39692, state=down, core=collection1, node_name=127.0.0.1:39692_, collection=collection1}
[junit4:junit4] 2> 528401 T2165 C574 P39692 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 528402 T2165 C574 P39692 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 528402 T2163 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 528402 T2165 C574 P39692 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 528403 T2165 C574 P39692 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 528403 T2055 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 528404 T2165 C574 P39692 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 528404 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 528404 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 528410 T2106 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 528475 T2055 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 528482 T2055 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54708
[junit4:junit4] 2> 528483 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 528483 T2055 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 528484 T2055 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-1372127505760
[junit4:junit4] 2> 528484 T2055 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-1372127505760/solr.xml
[junit4:junit4] 2> 528485 T2055 oasc.CoreContainer.<init> New CoreContainer 1692372312
[junit4:junit4] 2> 528485 T2055 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-1372127505760/'
[junit4:junit4] 2> 528485 T2055 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-1372127505760/'
[junit4:junit4] 2> 528529 T2055 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 528530 T2055 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 528530 T2055 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 528530 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 528531 T2055 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 528531 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 528531 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 528531 T2055 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 528531 T2055 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 528532 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 528535 T2055 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 528535 T2055 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52063/solr
[junit4:junit4] 2> 528536 T2055 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 528536 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 528538 T2177 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3c546dd1 name:ZooKeeperConnection Watcher:127.0.0.1:52063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 528539 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 528540 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 528543 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 528545 T2179 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@782917db name:ZooKeeperConnection Watcher:127.0.0.1:52063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 528545 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 528548 T2055 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C575 name=collection1 org.apache.solr.core.SolrCore@1e362868 url=http://127.0.0.1:55378/collection1 node=127.0.0.1:55378_ C575_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:55378, state=recovering, core=collection1, shard=shard2, node_name=127.0.0.1:55378_, collection=collection1}
[junit4:junit4] 2> 528698 T2148 C575 P55378 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:33978/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 528698 T2148 C575 P55378 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55378 START replicas=[http://127.0.0.1:33978/collection1/] nUpdates=100
[junit4:junit4] 2> 528698 T2148 C575 P55378 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 528699 T2148 C575 P55378 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 528699 T2148 C575 P55378 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 528699 T2148 C575 P55378 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 528699 T2148 C575 P55378 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 528699 T2148 C575 P55378 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:33978/collection1/. core=collection1
[junit4:junit4] 2> 528700 T2148 C575 P55378 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C576 name=collection1 org.apache.solr.core.SolrCore@3d51df6 url=http://127.0.0.1:33978/collection1 node=127.0.0.1:33978_ C576_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:33978, state=active, core=collection1, shard=shard2, node_name=127.0.0.1:33978_, collection=collection1, leader=true}
[junit4:junit4] 2> 528706 T2091 C576 P33978 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&getVersions=100&distrib=false&version=2&qt=/get} status=0 QTime=1
[junit4:junit4] 2> 528709 T2090 C576 P33978 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 528711 T2090 C576 P33978 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-1372127487851/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 528712 T2090 C576 P33978 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 528718 T2090 C576 P33978 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-1372127487851/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-1372127487851/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 528718 T2090 C576 P33978 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 528719 T2090 C576 P33978 oass.SolrIndexSearcher.<init> Opening Searcher@2622faa3 realtime
[junit4:junit4] 2> 528719 T2090 C576 P33978 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 528719 T2090 C576 P33978 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&waitSearcher=true&openSearcher=false&commit_end_point=true&softCommit=false&commit=true&version=2} {commit=} 0 10
[junit4:junit4] 2> 528720 T2148 C575 P55378 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 528720 T2148 C575 P55378 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 528725 T2092 C576 P33978 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 528726 T2092 C576 P33978 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=javabin&command=indexversion&version=2&qt=/replication} status=0 QTime=4
[junit4:junit4] 2> 528726 T2148 C575 P55378 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 528726 T2148 C575 P55378 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 528727 T2148 C575 P55378 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 528729 T2091 C576 P33978 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=javabin&command=filelist&generation=2&version=2&qt=/replication} status=0 QTime=1
[junit4:junit4] 2> 528729 T2148 C575 P55378 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 528730 T2148 C575 P55378 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-1372127487851/jetty4/index.20130625103146082
[junit4:junit4] 2> 528730 T2148 C575 P55378 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty4/index.20130625103146082 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2bfb1204 fullCopy=false
[junit4:junit4] 2> 528733 T2090 C576 P33978 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=filestream&command=filecontent&file=segments_2&checksum=true&generation=2&qt=/replication} status=0 QTime=0
[junit4:junit4] 2> 528734 T2148 C575 P55378 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 528738 T2148 C575 P55378 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 528739 T2148 C575 P55378 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 528741 T2148 C575 P55378 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-1372127487851/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-1372127487851/jetty4/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 528741 T2148 C575 P55378 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 528741 T2148 C575 P55378 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 528742 T2148 C575 P55378 oass.SolrIndexSearcher.<init> Opening Searcher@7996c2f5 main
[junit4:junit4] 2> 528743 T2147 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7996c2f5 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 528743 T2148 C575 P55378 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-1372127487851/jetty4/index.20130625103146082 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty4/index.20130625103146082;done=true>>]
[junit4:junit4] 2> 528743 T2148 C575 P55378 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty4/index.20130625103146082
[junit4:junit4] 2> 528743 T2148 C575 P55378 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-1372127487851/jetty4/index.20130625103146082
[junit4:junit4] 2> 528744 T2148 C575 P55378 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 528744 T2148 C575 P55378 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 528744 T2148 C575 P55378 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 528744 T2148 C575 P55378 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 528746 T2148 C575 P55378 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 529005 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 529006 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39692",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "node_name":"127.0.0.1:39692_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 529010 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55378",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:55378_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 529030 T2077 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> 529030 T2162 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> 529030 T2129 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> 529030 T2113 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> 529030 T2145 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> 529030 T2097 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> 529030 T2179 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> 529030 T2084 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> 529410 T2106 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 529411 T2106 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={wt=javabin&coreNodeName=6&action=PREPRECOVERY&state=recovering&core=collection1&onlyIfLeader=true&version=2&checkLive=true&nodeName=127.0.0.1:39692_} status=0 QTime=1001
[junit4:junit4] 2> 529551 T2055 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54708_
[junit4:junit4] 2> 529552 T2055 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54708_
[junit4:junit4] 2> 529554 T2097 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> 529554 T2084 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> 529554 T2145 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> 529555 T2162 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 529554 T2179 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> 529555 T2162 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> 529555 T2077 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 529556 T2077 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> 529555 T2113 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 529556 T2084 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 529554 T2129 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> 529556 T2145 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 529556 T2097 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 529556 T2113 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> 529558 T2179 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 529558 T2129 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 529563 T2182 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 529563 T2182 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 530539 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 530539 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54708",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"7",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54708_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 530540 T2078 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 530540 T2078 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 530544 T2129 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> 530544 T2084 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> 530544 T2113 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> 530544 T2097 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> 530544 T2162 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> 530544 T2179 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> 530544 T2077 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> 530544 T2145 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> 530564 T2182 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-1372127505760/collection1
[junit4:junit4] 2> 530565 T2182 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 530565 T2182 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 530565 T2182 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 530566 T2182 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-1372127505760/collection1/'
[junit4:junit4] 2> 530567 T2182 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-1372127505760/collection1/lib/README' to classloader
[junit4:junit4] 2> 530567 T2182 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-1372127505760/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 530594 T2182 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 530622 T2182 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 530623 T2182 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 530627 T2182 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 530953 T2182 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 530959 T2182 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 530961 T2182 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 530972 T2182 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 530975 T2182 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 530977 T2182 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 530978 T2182 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 530979 T2182 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 530979 T2182 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 530980 T2182 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 530980 T2182 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 530980 T2182 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 530980 T2182 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-1372127505760/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty6/
[junit4:junit4] 2> 530980 T2182 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@127e2024
[junit4:junit4] 2> 530981 T2182 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 530981 T2182 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-1372127487851/jetty6
[junit4:junit4] 2> 530981 T2182 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty6/index/
[junit4:junit4] 2> 530982 T2182 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty6/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 530982 T2182 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-1372127487851/jetty6/index
[junit4:junit4] 2> 530985 T2182 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-1372127487851/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 530985 T2182 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 530987 T2182 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 530987 T2182 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 530987 T2182 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 530988 T2182 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 530988 T2182 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 530988 T2182 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 530989 T2182 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 530989 T2182 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 530989 T2182 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 530991 T2182 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 530994 T2182 oass.SolrIndexSearcher.<init> Opening Searcher@5c7e933f main
[junit4:junit4] 2> 530994 T2182 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 530995 T2182 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 530998 T2183 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5c7e933f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 531000 T2182 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 531000 T2182 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54708 collection:collection1 shard:shard1
[junit4:junit4] 2> 531003 T2182 oasc.ZkController.register We are http://127.0.0.1:54708/collection1/ and leader is http://127.0.0.1:41627/collection1/
[junit4:junit4] 2> 531003 T2182 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54708
[junit4:junit4] 2> 531003 T2182 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 531003 T2182 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C577 name=collection1 org.apache.solr.core.SolrCore@4423f3b url=http://127.0.0.1:54708/collection1 node=127.0.0.1:54708_ C577_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:54708, state=down, core=collection1, node_name=127.0.0.1:54708_, collection=collection1}
[junit4:junit4] 2> 531012 T2184 C577 P54708 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 531012 T2184 C577 P54708 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 531012 T2182 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 531013 T2184 C577 P54708 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 531013 T2184 C577 P54708 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 531014 T2055 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 531014 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 531015 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 531016 T2184 C577 P54708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 531022 T2123 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 531114 T2055 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 531117 T2055 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:43987
[junit4:junit4] 2> 531118 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 531118 T2055 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 531118 T2055 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-1372127508370
[junit4:junit4] 2> 531118 T2055 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-1372127508370/solr.xml
[junit4:junit4] 2> 531119 T2055 oasc.CoreContainer.<init> New CoreContainer 80365717
[junit4:junit4] 2> 531119 T2055 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-1372127508370/'
[junit4:junit4] 2> 531119 T2055 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-1372127508370/'
[junit4:junit4] 2> 531159 T2055 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 531160 T2055 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 531160 T2055 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 531160 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 531161 T2055 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 531161 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 531161 T2055 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 531161 T2055 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 531161 T2055 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 531162 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 531165 T2055 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 531166 T2055 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52063/solr
[junit4:junit4] 2> 531166 T2055 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 531167 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 531168 T2196 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@71c05cd name:ZooKeeperConnection Watcher:127.0.0.1:52063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 531169 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 531170 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 531173 T2055 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 531175 T2198 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@48ace6e name:ZooKeeperConnection Watcher:127.0.0.1:52063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 531175 T2055 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 531178 T2055 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C578 name=collection1 org.apache.solr.core.SolrCore@70e3684a url=http://127.0.0.1:39692/collection1 node=127.0.0.1:39692_ C578_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:39692, state=recovering, core=collection1, shard=shard3, node_name=127.0.0.1:39692_, collection=collection1}
[junit4:junit4] 2> 531412 T2165 C578 P39692 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:58326/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 531412 T2165 C578 P39692 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:39692 START replicas=[http://127.0.0.1:58326/collection1/] nUpdates=100
[junit4:junit4] 2> 531412 T2165 C578 P39692 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 531412 T2165 C578 P39692 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 531413 T2165 C578 P39692 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 531413 T2165 C578 P39692 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 531413 T2165 C578 P39692 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 531413 T2165 C578 P39692 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:58326/collection1/. core=collection1
[junit4:junit4] 2> 531413 T2165 C578 P39692 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C579 name=collection1 org.apache.solr.core.SolrCore@3c6977c3 url=http://127.0.0.1:58326/collection1 node=127.0.0.1:58326_ C579_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:58326, state=active, core=collection1, shard=shard3, node_name=127.0.0.1:58326_, collection=collection1, leader=true}
[junit4:junit4] 2> 531420 T2109 C579 P58326 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&getVersions=100&distrib=false&version=2&qt=/get} status=0 QTime=1
[junit4:junit4] 2> 531423 T2107 C579 P58326 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 531425 T2107 C579 P58326 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-1372127487851/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 531426 T2107 C579 P58326 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 531438 T2107 C579 P58326 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-1372127487851/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-1372127487851/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 531438 T2107 C579 P58326 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 531439 T2107 C579 P58326 oass.SolrIndexSearcher.<init> Opening Searcher@50832061 realtime
[junit4:junit4] 2> 531439 T2107 C579 P58326 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 531439 T2107 C579 P58326 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&waitSearcher=true&openSearcher=false&commit_end_point=true&softCommit=false&commit=true&version=2} {commit=} 0 16
[junit4:junit4] 2> 531440 T2165 C578 P39692 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 531440 T2165 C578 P39692 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 531442 T2108 C579 P58326 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 531442 T2108 C579 P58326 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=javabin&command=indexversion&version=2&qt=/replication} status=0 QTime=0
[junit4:junit4] 2> 531443 T2165 C578 P39692 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 531443 T2165 C578 P39692 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 531443 T2165 C578 P39692 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 531445 T2109 C579 P58326 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=javabin&command=filelist&generation=2&version=2&qt=/replication} status=0 QTime=0
[junit4:junit4] 2> 531446 T2165 C578 P39692 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 531446 T2165 C578 P39692 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-1372127487851/jetty5/index.20130625103148798
[junit4:junit4] 2> 531447 T2165 C578 P39692 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty5/index.20130625103148798 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3c1c7a43 fullCopy=false
[junit4:junit4] 2> 531449 T2107 C579 P58326 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=filestream&command=filecontent&file=segments_2&checksum=true&generation=2&qt=/replication} status=0 QTime=0
[junit4:junit4] 2> 531451 T2165 C578 P39692 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 531458 T2165 C578 P39692 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 531459 T2165 C578 P39692 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 531461 T2165 C578 P39692 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-1372127487851/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-1372127487851/jetty5/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 531461 T2165 C578 P39692 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 531461 T2165 C578 P39692 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 531462 T2165 C578 P39692 oass.SolrIndexSearcher.<init> Opening Searcher@770f369 main
[junit4:junit4] 2> 531462 T2164 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@770f369 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 531463 T2165 C578 P39692 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-1372127487851/jetty5/index.20130625103148798 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty5/index.20130625103148798;done=true>>]
[junit4:junit4] 2> 531463 T2165 C578 P39692 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty5/index.20130625103148798
[junit4:junit4] 2> 531463 T2165 C578 P39692 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-1372127487851/jetty5/index.20130625103148798
[junit4:junit4] 2> 531463 T2165 C578 P39692 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 531464 T2165 C578 P39692 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 531464 T2165 C578 P39692 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 531464 T2165 C578 P39692 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 531466 T2165 C578 P39692 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 532049 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 532050 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54708",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"7",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:54708_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 532054 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39692",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "node_name":"127.0.0.1:39692_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 532071 T2198 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> 532071 T2113 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> 532072 T2077 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> 532072 T2129 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> 532071 T2162 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> 532071 T2179 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> 532071 T2097 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> 532073 T2084 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> 532073 T2145 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> 532180 T2055 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43987_
[junit4:junit4] 2> 532181 T2055 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43987_
[junit4:junit4] 2> 532183 T2129 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> 532183 T2077 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> 532183 T2179 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> 532183 T2097 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> 532184 T2145 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 532184 T2145 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> 532184 T2113 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 532184 T2162 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 532185 T2198 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 532185 T2084 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 532185 T2084 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> 532184 T2113 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> 532185 T2198 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> 532185 T2162 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> 532187 T2129 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 532187 T2179 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 532187 T2097 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 532188 T2077 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 532193 T2201 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 532193 T2201 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 533023 T2123 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 533023 T2123 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={wt=javabin&coreNodeName=7&action=PREPRECOVERY&state=recovering&core=collection1&onlyIfLeader=true&version=2&checkLive=true&nodeName=127.0.0.1:54708_} status=0 QTime=2001
[junit4:junit4] 2> 533579 T2078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 533580 T2078 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43987",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"8",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:43987_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 533580 T2078 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 533580 T2078 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 533583 T2113 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> 533584 T2198 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> 533584 T2077 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> 533584 T2097 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> 533584 T2162 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> 533583 T2129 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> 533584 T2084 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> 533583 T2145 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> 533584 T2179 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> 534195 T2201 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-1372127508370/collection1
[junit4:junit4] 2> 534195 T2201 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 534196 T2201 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 534196 T2201 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 534197 T2201 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-1372127508370/collection1/'
[junit4:junit4] 2> 534198 T2201 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-1372127508370/collection1/lib/README' to classloader
[junit4:junit4] 2> 534198 T2201 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-1372127508370/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 534225 T2201 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 534255 T2201 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 534256 T2201 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 534259 T2201 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 534581 T2201 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 534586 T2201 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 534589 T2201 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 534599 T2201 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 534603 T2201 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 534606 T2201 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 534607 T2201 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 534608 T2201 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 534608 T2201 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 534609 T2201 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 534609 T2201 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 534609 T2201 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 534610 T2201 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-1372127508370/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty7/
[junit4:junit4] 2> 534610 T2201 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@127e2024
[junit4:junit4] 2> 534610 T2201 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 534611 T2201 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-1372127487851/jetty7
[junit4:junit4] 2> 534611 T2201 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty7/index/
[junit4:junit4] 2> 534611 T2201 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty7/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 534611 T2201 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-1372127487851/jetty7/index
[junit4:junit4] 2> 534614 T2201 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-1372127487851/jetty7/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 534614 T2201 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 534616 T2201 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 534616 T2201 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 534617 T2201 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 534617 T2201 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 534618 T2201 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 534618 T2201 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 534618 T2201 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 534618 T2201 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 534619 T2201 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 534620 T2201 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 534623 T2201 oass.SolrIndexSearcher.<init> Opening Searcher@13352bc4 main
[junit4:junit4] 2> 534624 T2201 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 534624 T2201 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 534654 T2202 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@13352bc4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 534657 T2201 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 534657 T2201 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43987 collection:collection1 shard:shard2
[junit4:junit4] 2> 534659 T2201 oasc.ZkController.register We are http://127.0.0.1:43987/collection1/ and leader is http://127.0.0.1:33978/collection1/
[junit4:junit4] 2> 534659 T2201 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43987
[junit4:junit4] 2> 534659 T2201 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 534660 T2201 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C580 name=collection1 org.apache.solr.core.SolrCore@355c7bad url=http://127.0.0.1:43987/collection1 node=127.0.0.1:43987_ C580_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:43987, state=down, core=collection1, node_name=127.0.0.1:43987_, collection=collection1}
[junit4:junit4] 2> 534660 T2203 C580 P43987 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 534660 T2201 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 534660 T2203 C580 P43987 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 534661 T2203 C580 P43987 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 534661 T2203 C580 P43987 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 534661 T2055 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 534662 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 534662 T2203 C580 P43987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 534662 T2055 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 534668 T2093 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 8, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 534739 T2055 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 534747 T2055 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51006
[junit4:junit4] 2> 534748 T2055 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 534748 T2055 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 53
[...truncated too long message...]
... 5 more
[junit4:junit4] 2>
[junit4:junit4] 2> 734278 T2382 oascc.DefaultConnectionStrategy.reconnect Reconnect to ZooKeeper failed
[junit4:junit4] 2> 734278 T2382 oascc.ConnectionManager.process Connected:true
[junit4:junit4] 2> 734503 T2055 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 734503 T2055 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 734506 T2055 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@34241a16
[junit4:junit4] 2> 734507 T2055 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=22,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=16,adds=16,deletesById=17,deletesByQuery=0,errors=0,cumulative_adds=47,cumulative_deletesById=32,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 734508 T2055 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 734509 T2055 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 734509 T2055 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> C849_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:59036, state=active, core=collection1, shard=shard1, node_name=127.0.0.1:59036_, collection=collection1, leader=true}
[junit4:junit4] 2> 734540 T2055 C849 P59036 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-1372127487851/jetty12/index.20130625103302160,segFN=segments_u,generation=30}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty12/index.20130625103302160,segFN=segments_v,generation=31}
[junit4:junit4] 2> 734541 T2055 C849 P59036 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 31
[junit4:junit4] 2> 734543 T2055 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 734545 T2055 oasc.CachingDirectoryFactory.close Closing StandardDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 734545 T2055 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-1372127487851/jetty12 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty12;done=false>>]
[junit4:junit4] 2> 734546 T2055 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty12
[junit4:junit4] 2> 734546 T2055 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-1372127487851/jetty12/index.20130625103302160 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty12/index.20130625103302160;done=false>>]
[junit4:junit4] 2> 734547 T2055 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372127487851/jetty12/index.20130625103302160
[junit4:junit4] 2> 734548 T2661 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89923747044065323-127.0.0.1:59036_-n_0000000021) am no longer a leader.
[junit4:junit4] 2> 734573 T2055 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 734670 T2055 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 734672 T2055 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:52063 52063
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 1> safe stop:
[junit4:junit4] 1> safe stop:
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeySafeLeaderTest -Dtests.method=testDistribSearch -Dtests.seed=379D4B486BE43D7F -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=in -Dtests.timezone=Asia/Chongqing -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 224s J0 | ChaosMonkeySafeLeaderTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard3 is not consistent. Got 100 from http://127.0.0.1:58326/collection1lastClient and got 59 from http://127.0.0.1:39692/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([379D4B486BE43D7F:B67BC5501CBB5D43]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2> 734702 T2055 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 224211 T2054 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 734727 T2274 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 734728 T2274 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 734728 T2274 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 735850 T2452 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 735851 T2452 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> 735851 T2452 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Asserting, sim=DefaultSimilarity, locale=in, timezone=Asia/Chongqing
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic amd64/Oracle Corporation 1.8.0-ea (64-bit)/cpus=8,threads=4,free=151162328,total=372244480
[junit4:junit4] 2> NOTE: All tests run in this JVM: [AliasIntegrationTest, PeerSyncTest, PrimitiveFieldTypeTest, UnloadDistributedZkTest, IndexSchemaTest, ZkCLITest, QueryParsingTest, TestFieldResource, CircularListTest, TestValueSourceCache, DistributedSpellCheckComponentTest, TestCharFilters, DirectSolrConnectionTest, TestPluginEnable, TestLMDirichletSimilarityFactory, SolrInfoMBeanTest, DocValuesTest, SchemaVersionSpecificBehaviorTest, TestQuerySenderListener, SliceStateUpdateTest, TestPseudoReturnFields, DocumentBuilderTest, TestWriterPerf, PluginInfoTest, TestFieldTypeCollectionResource, LegacyHTMLStripCharFilterTest, TestXIncludeConfig, TestCloudManagedSchemaAddField, TestBadConfig, AlternateDirectoryTest, TestConfig, TestSolrQueryParserDefaultOperatorResource, PreAnalyzedFieldTest, SuggesterFSTTest, ReturnFieldsTest, BasicDistributedZkTest, ClusterStateUpdateTest, FieldMutatingUpdateProcessorTest, SolrCoreTest, TestGroupingSearch, CSVRequestHandlerTest, LeaderElectionTest, TestFastWriter, SolrTestCaseJ4Test, TestJoin, OverseerCollectionProcessorTest, SolrIndexSplitterTest, TestSurroundQueryParser, TestLRUCache, SpellingQueryConverterTest, TestFuzzyAnalyzedSuggestions, TestSort, TestRealTimeGet, ScriptEngineTest, TestSolrXmlPersistence, FastVectorHighlighterTest, TestSolrCoreProperties, FileBasedSpellCheckerTest, CacheHeaderTest, TestCopyFieldCollectionResource, MBeansHandlerTest, TestReloadAndDeleteDocs, PrimUtilsTest, TestReversedWildcardFilterFactory, SyncSliceTest, TestSchemaNameResource, TestDynamicFieldCollectionResource, LukeRequestHandlerTest, TestSolrDeletionPolicy1, SimpleFacetsTest, TestQueryUtils, ChaosMonkeyNothingIsSafeTest, MinimalSchemaTest, ChaosMonkeySafeLeaderTest]
[junit4:junit4] Completed on J0 in 225.49s, 1 test, 1 failure <<< FAILURES!
[...truncated 443 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 failure, 16 ignored (7 assumptions)
Total time: 35 minutes 11 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.8.0-ea-b93 -XX:+UseCompressedOops -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure