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/17 02:34:06 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.7.0_21) - Build #
6171 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/6171/
Java: 32bit/jdk1.7.0_21 -server -XX:+UseSerialGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.testDistribSearch
Error Message:
shard3 is not consistent. Got 42 from http://127.0.0.1:32842/th_zn/collection1lastClient and got 37 from http://127.0.0.1:59410/th_zn/collection1
Stack Trace:
java.lang.AssertionError: shard3 is not consistent. Got 42 from http://127.0.0.1:32842/th_zn/collection1lastClient and got 37 from http://127.0.0.1:59410/th_zn/collection1
at __randomizedtesting.SeedInfo.seed([FB5BFA710EBB3452:7ABD746979E4546E]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9393 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
[junit4:junit4] 2> 201022 T710 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /th_zn/
[junit4:junit4] 2> 201035 T710 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeySafeLeaderTest-1371428170406
[junit4:junit4] 2> 201036 T710 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 201037 T711 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 201137 T710 oasc.ZkTestServer.run start zk server on port:60508
[junit4:junit4] 2> 201140 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 201208 T717 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1760b0f name:ZooKeeperConnection Watcher:127.0.0.1:60508 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 201208 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 201208 T710 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 201212 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 201214 T719 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@168ce8 name:ZooKeeperConnection Watcher:127.0.0.1:60508/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 201214 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 201214 T710 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 201219 T710 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 201221 T710 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 201223 T710 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 201226 T710 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> 201226 T710 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 201230 T710 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> 201230 T710 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 201233 T710 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> 201234 T710 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 201236 T710 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> 201237 T710 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 201239 T710 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> 201239 T710 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 201242 T710 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> 201242 T710 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 201245 T710 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> 201245 T710 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 201248 T710 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> 201248 T710 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 201250 T710 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> 201251 T710 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 201317 T710 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 201321 T710 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:46757
[junit4:junit4] 2> 201321 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 201322 T710 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 201322 T710 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371428170624
[junit4:junit4] 2> 201323 T710 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371428170624/solr.xml
[junit4:junit4] 2> 201323 T710 oasc.CoreContainer.<init> New CoreContainer 30988171
[junit4:junit4] 2> 201324 T710 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371428170624/'
[junit4:junit4] 2> 201324 T710 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371428170624/'
[junit4:junit4] 2> 201373 T710 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 201374 T710 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 201374 T710 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 201375 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 201375 T710 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 201376 T710 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 201376 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 201376 T710 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 201377 T710 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 201377 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 201381 T710 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 201382 T710 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60508/solr
[junit4:junit4] 2> 201382 T710 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 201383 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 201385 T730 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19da533 name:ZooKeeperConnection Watcher:127.0.0.1:60508 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 201385 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 201387 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 201390 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 201392 T732 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2774a4 name:ZooKeeperConnection Watcher:127.0.0.1:60508/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 201392 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 201393 T710 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 201396 T710 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 201398 T710 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 201400 T710 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46757_th_zn
[junit4:junit4] 2> 201401 T710 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46757_th_zn
[junit4:junit4] 2> 201403 T710 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 201407 T710 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 201409 T710 oasc.Overseer.start Overseer (id=89877916575858691-127.0.0.1:46757_th_zn-n_0000000000) starting
[junit4:junit4] 2> 201412 T710 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 201415 T734 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 201415 T710 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 201417 T710 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 201418 T710 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 201420 T733 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 201422 T735 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 201423 T735 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 202924 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 202924 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46757_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46757/th_zn"}
[junit4:junit4] 2> 202925 T733 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 202927 T733 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 202930 T732 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> 203424 T735 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371428170624/collection1
[junit4:junit4] 2> 203424 T735 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 203425 T735 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 203425 T735 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 203426 T735 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371428170624/collection1/'
[junit4:junit4] 2> 203427 T735 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371428170624/collection1/lib/README' to classloader
[junit4:junit4] 2> 203427 T735 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371428170624/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 203462 T735 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 203510 T735 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 203511 T735 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 203516 T735 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 203845 T735 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 203850 T735 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 203852 T735 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 203863 T735 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 203866 T735 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 203869 T735 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 203870 T735 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 203870 T735 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 203870 T735 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 203871 T735 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 203871 T735 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 203872 T735 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 203878 T735 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371428170624/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/control/data/
[junit4:junit4] 2> 203878 T735 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@96bfda
[junit4:junit4] 2> 203878 T735 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 203879 T735 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/control/data
[junit4:junit4] 2> 203879 T735 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/control/data/index/
[junit4:junit4] 2> 203879 T735 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 203879 T735 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/control/data/index
[junit4:junit4] 2> 203882 T735 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 203883 T735 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 203884 T735 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 203885 T735 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 203885 T735 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 203885 T735 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 203886 T735 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 203886 T735 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 203886 T735 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 203886 T735 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 203887 T735 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 203889 T735 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 203898 T735 oass.SolrIndexSearcher.<init> Opening Searcher@190f2c6 main
[junit4:junit4] 2> 203898 T735 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 203898 T735 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 203902 T736 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@190f2c6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 203903 T735 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 203903 T735 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46757/th_zn collection:control_collection shard:shard1
[junit4:junit4] 2> 203904 T735 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 203910 T735 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 203913 T735 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 203913 T735 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 203913 T735 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:46757/th_zn/collection1/
[junit4:junit4] 2> 203914 T735 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 203914 T735 oasc.SyncStrategy.syncToMe http://127.0.0.1:46757/th_zn/collection1/ has no replicas
[junit4:junit4] 2> 203914 T735 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:46757/th_zn/collection1/
[junit4:junit4] 2> 203914 T735 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 204433 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 204441 T732 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> 204473 T735 oasc.ZkController.register We are http://127.0.0.1:46757/th_zn/collection1/ and leader is http://127.0.0.1:46757/th_zn/collection1/
[junit4:junit4] 2> 204473 T735 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46757/th_zn
[junit4:junit4] 2> 204473 T735 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 204474 T735 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 204474 T735 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 204475 T735 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 204488 T710 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 204489 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 204489 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 204496 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 204498 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 204500 T739 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@37ae07 name:ZooKeeperConnection Watcher:127.0.0.1:60508/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 204500 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 204502 T710 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 204506 T710 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 204589 T710 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 204591 T710 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:44217
[junit4:junit4] 2> 204592 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 204592 T710 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 204592 T710 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371428173876
[junit4:junit4] 2> 204593 T710 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371428173876/solr.xml
[junit4:junit4] 2> 204593 T710 oasc.CoreContainer.<init> New CoreContainer 27666751
[junit4:junit4] 2> 204593 T710 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371428173876/'
[junit4:junit4] 2> 204594 T710 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371428173876/'
[junit4:junit4] 2> 204633 T710 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 204633 T710 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 204633 T710 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 204634 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 204634 T710 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 204634 T710 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 204635 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 204635 T710 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 204635 T710 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 204635 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 204639 T710 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 204639 T710 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60508/solr
[junit4:junit4] 2> 204640 T710 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 204648 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 204649 T750 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@aa1054 name:ZooKeeperConnection Watcher:127.0.0.1:60508 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 204650 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 204652 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 204657 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 204658 T752 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@fd3fe0 name:ZooKeeperConnection Watcher:127.0.0.1:60508/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 204659 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 204662 T710 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 205664 T710 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44217_th_zn
[junit4:junit4] 2> 205666 T710 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:44217_th_zn
[junit4:junit4] 2> 205669 T732 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 205669 T739 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 205669 T752 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 205669 T732 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> 205675 T753 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 205675 T753 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 205947 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 205948 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:46757_th_zn_collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46757_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46757/th_zn"}
[junit4:junit4] 2> 205951 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44217_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44217/th_zn"}
[junit4:junit4] 2> 205951 T733 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 3
[junit4:junit4] 2> 205951 T733 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 205955 T739 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> 205955 T752 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> 205955 T732 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> 206676 T753 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371428173876/collection1
[junit4:junit4] 2> 206677 T753 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 206678 T753 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 206678 T753 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 206679 T753 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371428173876/collection1/'
[junit4:junit4] 2> 206680 T753 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371428173876/collection1/lib/README' to classloader
[junit4:junit4] 2> 206680 T753 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371428173876/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 206715 T753 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 206764 T753 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 206765 T753 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 206770 T753 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 207110 T753 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 207115 T753 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 207118 T753 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 207130 T753 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 207133 T753 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 207136 T753 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 207137 T753 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 207137 T753 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 207137 T753 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 207138 T753 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 207139 T753 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 207139 T753 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 207139 T753 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371428173876/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty1/
[junit4:junit4] 2> 207139 T753 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@96bfda
[junit4:junit4] 2> 207140 T753 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 207140 T753 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty1
[junit4:junit4] 2> 207140 T753 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty1/index/
[junit4:junit4] 2> 207140 T753 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 207141 T753 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty1/index
[junit4:junit4] 2> 207143 T753 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 207143 T753 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 207145 T753 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 207145 T753 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 207145 T753 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 207146 T753 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 207146 T753 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 207146 T753 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 207147 T753 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 207147 T753 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 207147 T753 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 207149 T753 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 207152 T753 oass.SolrIndexSearcher.<init> Opening Searcher@1c4b232 main
[junit4:junit4] 2> 207153 T753 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 207153 T753 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 207156 T754 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1c4b232 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 207157 T753 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 207157 T753 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:44217/th_zn collection:collection1 shard:shard1
[junit4:junit4] 2> 207158 T753 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 207164 T753 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 207166 T753 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 207166 T753 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 207166 T753 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:44217/th_zn/collection1/
[junit4:junit4] 2> 207166 T753 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 207166 T753 oasc.SyncStrategy.syncToMe http://127.0.0.1:44217/th_zn/collection1/ has no replicas
[junit4:junit4] 2> 207167 T753 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:44217/th_zn/collection1/
[junit4:junit4] 2> 207167 T753 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 207460 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 207467 T739 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> 207468 T752 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> 207467 T732 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> 207473 T753 oasc.ZkController.register We are http://127.0.0.1:44217/th_zn/collection1/ and leader is http://127.0.0.1:44217/th_zn/collection1/
[junit4:junit4] 2> 207473 T753 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44217/th_zn
[junit4:junit4] 2> 207473 T753 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 207474 T753 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 207474 T753 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 207475 T753 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 207477 T710 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 207477 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 207477 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 207546 T710 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 207548 T710 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:47985
[junit4:junit4] 2> 207549 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 207549 T710 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 207549 T710 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371428176851
[junit4:junit4] 2> 207550 T710 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371428176851/solr.xml
[junit4:junit4] 2> 207550 T710 oasc.CoreContainer.<init> New CoreContainer 12704999
[junit4:junit4] 2> 207550 T710 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371428176851/'
[junit4:junit4] 2> 207551 T710 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371428176851/'
[junit4:junit4] 2> 207601 T710 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 207601 T710 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 207602 T710 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 207602 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 207602 T710 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 207602 T710 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 207603 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 207603 T710 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 207603 T710 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 207604 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 207607 T710 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 207608 T710 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60508/solr
[junit4:junit4] 2> 207608 T710 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 207609 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 207612 T766 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a2d083 name:ZooKeeperConnection Watcher:127.0.0.1:60508 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 207613 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 207614 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 207618 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 207619 T768 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6b638c name:ZooKeeperConnection Watcher:127.0.0.1:60508/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 207620 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 207623 T710 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 208626 T710 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47985_th_zn
[junit4:junit4] 2> 208628 T710 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47985_th_zn
[junit4:junit4] 2> 208630 T752 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> 208630 T739 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> 208631 T768 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 208631 T732 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 208631 T732 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> 208632 T752 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 208635 T739 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 208636 T769 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 208636 T769 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 208973 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 208973 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:44217_th_zn_collection1",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44217_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44217/th_zn"}
[junit4:junit4] 2> 208976 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:47985_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47985/th_zn"}
[junit4:junit4] 2> 208977 T733 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 208977 T733 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 208981 T768 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> 208981 T752 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> 208981 T732 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> 208981 T739 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> 209637 T769 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371428176851/collection1
[junit4:junit4] 2> 209638 T769 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 209638 T769 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 209639 T769 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 209640 T769 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371428176851/collection1/'
[junit4:junit4] 2> 209640 T769 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371428176851/collection1/lib/README' to classloader
[junit4:junit4] 2> 209641 T769 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371428176851/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 209669 T769 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 209696 T769 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 209698 T769 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 209701 T769 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 210018 T769 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 210199 T769 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 210201 T769 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 210215 T769 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 210218 T769 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 210221 T769 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 210222 T769 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 210222 T769 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 210222 T769 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 210223 T769 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 210223 T769 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 210223 T769 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 210223 T769 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371428176851/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty2/
[junit4:junit4] 2> 210224 T769 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@96bfda
[junit4:junit4] 2> 210224 T769 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 210224 T769 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty2
[junit4:junit4] 2> 210225 T769 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty2/index/
[junit4:junit4] 2> 210225 T769 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 210225 T769 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty2/index
[junit4:junit4] 2> 210228 T769 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 210229 T769 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 210230 T769 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 210231 T769 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 210231 T769 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 210231 T769 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 210232 T769 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 210232 T769 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 210232 T769 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 210233 T769 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 210233 T769 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 210235 T769 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 210237 T769 oass.SolrIndexSearcher.<init> Opening Searcher@1277f77 main
[junit4:junit4] 2> 210238 T769 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 210238 T769 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 210243 T770 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1277f77 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 210245 T769 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 210245 T769 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47985/th_zn collection:collection1 shard:shard2
[junit4:junit4] 2> 210246 T769 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 210250 T769 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 210252 T769 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 210253 T769 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 210253 T769 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:47985/th_zn/collection1/
[junit4:junit4] 2> 210253 T769 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 210253 T769 oasc.SyncStrategy.syncToMe http://127.0.0.1:47985/th_zn/collection1/ has no replicas
[junit4:junit4] 2> 210253 T769 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:47985/th_zn/collection1/
[junit4:junit4] 2> 210253 T769 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 210487 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 210495 T739 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> 210495 T752 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> 210495 T732 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> 210495 T768 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> 210507 T769 oasc.ZkController.register We are http://127.0.0.1:47985/th_zn/collection1/ and leader is http://127.0.0.1:47985/th_zn/collection1/
[junit4:junit4] 2> 210508 T769 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47985/th_zn
[junit4:junit4] 2> 210508 T769 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 210508 T769 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 210508 T769 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 210510 T769 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 210511 T710 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 210511 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 210511 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 210576 T710 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 210578 T710 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:60163
[junit4:junit4] 2> 210578 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 210579 T710 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 210579 T710 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371428179885
[junit4:junit4] 2> 210579 T710 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371428179885/solr.xml
[junit4:junit4] 2> 210580 T710 oasc.CoreContainer.<init> New CoreContainer 28843858
[junit4:junit4] 2> 210580 T710 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371428179885/'
[junit4:junit4] 2> 210581 T710 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371428179885/'
[junit4:junit4] 2> 210626 T710 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 210626 T710 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 210626 T710 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 210627 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 210627 T710 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 210627 T710 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 210628 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 210628 T710 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 210628 T710 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 210629 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 210632 T710 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 210633 T710 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60508/solr
[junit4:junit4] 2> 210633 T710 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 210634 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 210635 T782 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@17a4f0c name:ZooKeeperConnection Watcher:127.0.0.1:60508 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 210636 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 210638 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 210641 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 210643 T784 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1fe7650 name:ZooKeeperConnection Watcher:127.0.0.1:60508/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 210643 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 210646 T710 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 211649 T710 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60163_th_zn
[junit4:junit4] 2> 211651 T710 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60163_th_zn
[junit4:junit4] 2> 211653 T739 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> 211653 T752 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> 211654 T768 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 211654 T768 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> 211655 T732 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 211655 T732 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> 211656 T784 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 211656 T752 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 211656 T739 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 211661 T785 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 211661 T785 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 212001 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 212002 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:47985_th_zn_collection1",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:47985_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47985/th_zn"}
[junit4:junit4] 2> 212006 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:60163_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60163/th_zn"}
[junit4:junit4] 2> 212006 T733 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 212006 T733 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 212011 T752 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> 212011 T768 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> 212011 T784 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> 212011 T739 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> 212011 T732 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> 212663 T785 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371428179885/collection1
[junit4:junit4] 2> 212663 T785 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 212664 T785 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 212664 T785 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 212665 T785 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371428179885/collection1/'
[junit4:junit4] 2> 212665 T785 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371428179885/collection1/lib/README' to classloader
[junit4:junit4] 2> 212666 T785 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371428179885/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 212688 T785 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 212720 T785 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 212722 T785 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 212725 T785 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 213045 T785 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 213051 T785 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 213054 T785 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 213068 T785 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 213071 T785 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 213073 T785 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 213075 T785 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 213075 T785 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 213075 T785 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 213076 T785 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 213077 T785 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 213077 T785 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 213077 T785 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371428179885/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty3/
[junit4:junit4] 2> 213077 T785 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@96bfda
[junit4:junit4] 2> 213078 T785 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 213078 T785 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty3
[junit4:junit4] 2> 213079 T785 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty3/index/
[junit4:junit4] 2> 213079 T785 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 213080 T785 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty3/index
[junit4:junit4] 2> 213083 T785 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 213083 T785 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 213085 T785 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 213085 T785 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 213085 T785 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 213086 T785 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 213086 T785 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 213086 T785 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 213087 T785 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 213087 T785 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 213087 T785 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 213089 T785 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 213092 T785 oass.SolrIndexSearcher.<init> Opening Searcher@12c5ef8 main
[junit4:junit4] 2> 213093 T785 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 213093 T785 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 213096 T786 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12c5ef8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 213098 T785 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 213098 T785 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:60163/th_zn collection:collection1 shard:shard3
[junit4:junit4] 2> 213099 T785 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4:junit4] 2> 213104 T785 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 213106 T785 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 213107 T785 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 213107 T785 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:60163/th_zn/collection1/
[junit4:junit4] 2> 213107 T785 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 213107 T785 oasc.SyncStrategy.syncToMe http://127.0.0.1:60163/th_zn/collection1/ has no replicas
[junit4:junit4] 2> 213107 T785 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:60163/th_zn/collection1/
[junit4:junit4] 2> 213107 T785 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4:junit4] 2> 213516 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 213524 T739 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> 213524 T732 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> 213525 T784 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> 213524 T752 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> 213524 T768 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> 213563 T785 oasc.ZkController.register We are http://127.0.0.1:60163/th_zn/collection1/ and leader is http://127.0.0.1:60163/th_zn/collection1/
[junit4:junit4] 2> 213563 T785 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60163/th_zn
[junit4:junit4] 2> 213564 T785 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 213564 T785 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 213564 T785 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 213566 T785 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 213567 T710 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 213567 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 213568 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 213645 T710 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 213647 T710 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50047
[junit4:junit4] 2> 213648 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 213648 T710 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 213649 T710 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371428182943
[junit4:junit4] 2> 213649 T710 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371428182943/solr.xml
[junit4:junit4] 2> 213649 T710 oasc.CoreContainer.<init> New CoreContainer 22682889
[junit4:junit4] 2> 213650 T710 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371428182943/'
[junit4:junit4] 2> 213650 T710 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371428182943/'
[junit4:junit4] 2> 213699 T710 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 213699 T710 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 213700 T710 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 213700 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 213701 T710 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 213701 T710 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 213701 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 213702 T710 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 213702 T710 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 213702 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 213706 T710 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 213706 T710 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60508/solr
[junit4:junit4] 2> 213707 T710 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 213707 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 213709 T798 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11bdaf0 name:ZooKeeperConnection Watcher:127.0.0.1:60508 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 213709 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 213711 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 213715 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 213716 T800 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@85375 name:ZooKeeperConnection Watcher:127.0.0.1:60508/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 213716 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 213719 T710 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 214721 T710 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50047_th_zn
[junit4:junit4] 2> 214723 T710 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50047_th_zn
[junit4:junit4] 2> 214725 T739 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> 214725 T752 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> 214726 T768 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 214726 T784 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 214726 T768 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> 214726 T732 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 214727 T800 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 214726 T784 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> 214727 T732 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> 214728 T739 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 214728 T752 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 214733 T801 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 214733 T801 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 215030 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 215031 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:60163_th_zn_collection1",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:60163_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60163/th_zn"}
[junit4:junit4] 2> 215034 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:50047_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50047/th_zn"}
[junit4:junit4] 2> 215034 T733 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 215034 T733 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 215039 T739 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> 215039 T800 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> 215039 T732 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> 215039 T752 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> 215039 T784 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> 215039 T768 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> 215735 T801 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371428182943/collection1
[junit4:junit4] 2> 215735 T801 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 215736 T801 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 215736 T801 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 215737 T801 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371428182943/collection1/'
[junit4:junit4] 2> 215738 T801 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371428182943/collection1/lib/README' to classloader
[junit4:junit4] 2> 215738 T801 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371428182943/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 215769 T801 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 215795 T801 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 215797 T801 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 215800 T801 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 216126 T801 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 216131 T801 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 216133 T801 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 216146 T801 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 216149 T801 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 216152 T801 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 216153 T801 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 216153 T801 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 216153 T801 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 216155 T801 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 216155 T801 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 216155 T801 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 216155 T801 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371428182943/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty4/
[junit4:junit4] 2> 216155 T801 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@96bfda
[junit4:junit4] 2> 216156 T801 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 216156 T801 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty4
[junit4:junit4] 2> 216156 T801 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty4/index/
[junit4:junit4] 2> 216157 T801 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 216157 T801 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty4/index
[junit4:junit4] 2> 216160 T801 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 216160 T801 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 216161 T801 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 216162 T801 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 216162 T801 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 216162 T801 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 216163 T801 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 216163 T801 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 216163 T801 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 216164 T801 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 216164 T801 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 216166 T801 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 216168 T801 oass.SolrIndexSearcher.<init> Opening Searcher@1450df4 main
[junit4:junit4] 2> 216169 T801 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 216169 T801 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 216173 T802 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1450df4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 216174 T801 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 216174 T801 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50047/th_zn collection:collection1 shard:shard1
[junit4:junit4] 2> 216178 T801 oasc.ZkController.register We are http://127.0.0.1:50047/th_zn/collection1/ and leader is http://127.0.0.1:44217/th_zn/collection1/
[junit4:junit4] 2> 216178 T801 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50047/th_zn
[junit4:junit4] 2> 216178 T801 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 216178 T801 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2381 name=collection1 org.apache.solr.core.SolrCore@1b53749 url=http://127.0.0.1:50047/th_zn/collection1 node=127.0.0.1:50047_th_zn C2381_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:50047_th_zn, base_url=http://127.0.0.1:50047/th_zn}
[junit4:junit4] 2> 216181 T803 C2381 P50047 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 216181 T803 C2381 P50047 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 216181 T801 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 216182 T803 C2381 P50047 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 216182 T803 C2381 P50047 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 216182 T710 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 216183 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 216183 T803 C2381 P50047 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 216183 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 216192 T745 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:50047_th_zn_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 216254 T710 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 216257 T710 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59568
[junit4:junit4] 2> 216257 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 216257 T710 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 216258 T710 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371428185557
[junit4:junit4] 2> 216258 T710 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371428185557/solr.xml
[junit4:junit4] 2> 216258 T710 oasc.CoreContainer.<init> New CoreContainer 8419161
[junit4:junit4] 2> 216259 T710 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371428185557/'
[junit4:junit4] 2> 216259 T710 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371428185557/'
[junit4:junit4] 2> 216296 T710 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 216296 T710 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 216297 T710 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 216297 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 216297 T710 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 216298 T710 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 216298 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 216298 T710 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 216299 T710 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 216299 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 216302 T710 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 216303 T710 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60508/solr
[junit4:junit4] 2> 216303 T710 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 216304 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 216306 T815 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16ae863 name:ZooKeeperConnection Watcher:127.0.0.1:60508 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 216306 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 216307 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 216312 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 216314 T817 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@694d19 name:ZooKeeperConnection Watcher:127.0.0.1:60508/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 216314 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 216317 T710 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 216545 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 216546 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50047_th_zn_collection1",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:50047_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50047/th_zn"}
[junit4:junit4] 2> 216551 T739 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> 216551 T752 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> 216551 T732 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> 216551 T784 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> 216551 T800 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> 216551 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 216551 T768 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> 217193 T745 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:50047_th_zn_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 217193 T745 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:50047_th_zn_collection1&state=recovering&nodeName=127.0.0.1:50047_th_zn&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1003
[junit4:junit4] 2> 217320 T710 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59568_th_zn
[junit4:junit4] 2> 217322 T710 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59568_th_zn
[junit4:junit4] 2> 217324 T739 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> 217324 T752 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> 217325 T817 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 217325 T768 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 217325 T768 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> 217325 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 217325 T800 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 217325 T732 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 217325 T784 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 217326 T732 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> 217326 T800 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> 217327 T739 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 217326 T784 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> 217327 T752 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 217332 T818 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 217333 T818 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 218056 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 218057 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59568_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59568/th_zn"}
[junit4:junit4] 2> 218057 T733 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 218058 T733 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 218061 T739 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> 218061 T800 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> 218062 T784 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> 218062 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 218061 T768 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> 218062 T732 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> 218062 T752 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> 218334 T818 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371428185557/collection1
[junit4:junit4] 2> 218334 T818 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 218335 T818 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 218335 T818 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 218336 T818 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371428185557/collection1/'
[junit4:junit4] 2> 218337 T818 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371428185557/collection1/lib/README' to classloader
[junit4:junit4] 2> 218337 T818 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371428185557/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 218368 T818 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 218394 T818 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 218396 T818 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 218399 T818 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 218733 T818 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 218737 T818 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 218740 T818 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 218760 T818 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 218763 T818 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 218767 T818 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 218769 T818 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 218769 T818 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 218770 T818 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 218771 T818 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 218771 T818 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 218771 T818 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 218772 T818 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371428185557/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty5/
[junit4:junit4] 2> 218772 T818 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@96bfda
[junit4:junit4] 2> 218772 T818 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 218773 T818 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty5
[junit4:junit4] 2> 218773 T818 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty5/index/
[junit4:junit4] 2> 218774 T818 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 218774 T818 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty5/index
[junit4:junit4] 2> 218778 T818 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 218778 T818 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 218781 T818 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 218781 T818 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 218782 T818 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 218782 T818 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 218783 T818 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 218783 T818 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 218783 T818 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 218784 T818 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 218784 T818 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 218788 T818 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 218791 T818 oass.SolrIndexSearcher.<init> Opening Searcher@1a93b87 main
[junit4:junit4] 2> 218792 T818 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 218792 T818 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 218796 T819 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1a93b87 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 218798 T818 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 218798 T818 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59568/th_zn collection:collection1 shard:shard2
[junit4:junit4] 2> 218801 T818 oasc.ZkController.register We are http://127.0.0.1:59568/th_zn/collection1/ and leader is http://127.0.0.1:47985/th_zn/collection1/
[junit4:junit4] 2> 218801 T818 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59568/th_zn
[junit4:junit4] 2> 218802 T818 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 218802 T818 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2382 name=collection1 org.apache.solr.core.SolrCore@44ec0f url=http://127.0.0.1:59568/th_zn/collection1 node=127.0.0.1:59568_th_zn C2382_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:59568_th_zn, base_url=http://127.0.0.1:59568/th_zn}
[junit4:junit4] 2> 218802 T820 C2382 P59568 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 218803 T820 C2382 P59568 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 218803 T818 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 218803 T820 C2382 P59568 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 218803 T820 C2382 P59568 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 218804 T710 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 218804 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 218804 T820 C2382 P59568 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 218805 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 218810 T761 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:59568_th_zn_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 218879 T710 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 218882 T710 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57876
[junit4:junit4] 2> 218882 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 218882 T710 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 218883 T710 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371428188180
[junit4:junit4] 2> 218883 T710 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371428188180/solr.xml
[junit4:junit4] 2> 218883 T710 oasc.CoreContainer.<init> New CoreContainer 30019864
[junit4:junit4] 2> 218884 T710 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371428188180/'
[junit4:junit4] 2> 218884 T710 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371428188180/'
[junit4:junit4] 2> 218931 T710 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 218931 T710 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 218931 T710 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 218932 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 218932 T710 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 218932 T710 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 218933 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 218933 T710 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 218933 T710 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 218934 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 218937 T710 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 218938 T710 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60508/solr
[junit4:junit4] 2> 218938 T710 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 218939 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 218940 T832 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@90d398 name:ZooKeeperConnection Watcher:127.0.0.1:60508 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 218941 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 218942 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 218946 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 218947 T834 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1e1f3a2 name:ZooKeeperConnection Watcher:127.0.0.1:60508/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 218947 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 218951 T710 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C2383 name=collection1 org.apache.solr.core.SolrCore@1b53749 url=http://127.0.0.1:50047/th_zn/collection1 node=127.0.0.1:50047_th_zn C2383_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:50047_th_zn, base_url=http://127.0.0.1:50047/th_zn}
[junit4:junit4] 2> 219195 T803 C2383 P50047 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:44217/th_zn/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 219198 T803 C2383 P50047 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 219203 T803 C2383 P50047 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50047/th_zn START replicas=[http://127.0.0.1:44217/th_zn/collection1/] nUpdates=100
[junit4:junit4] 2> 219203 T803 C2383 P50047 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 219204 T803 C2383 P50047 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 219204 T803 C2383 P50047 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 219204 T803 C2383 P50047 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 219204 T803 C2383 P50047 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 219204 T803 C2383 P50047 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:44217/th_zn/collection1/. core=collection1
[junit4:junit4] 2> 219204 T803 C2383 P50047 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2384 name=collection1 org.apache.solr.core.SolrCore@6117ea url=http://127.0.0.1:44217/th_zn/collection1 node=127.0.0.1:44217_th_zn C2384_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:44217_th_zn, base_url=http://127.0.0.1:44217/th_zn, leader=true}
[junit4:junit4] 2> 219210 T745 C2384 P44217 oasc.SolrCore.execute [collection1] webapp=/th_zn path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 219214 T746 C2384 P44217 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 219216 T746 C2384 P44217 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 219217 T746 C2384 P44217 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 219226 T746 C2384 P44217 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 219227 T746 C2384 P44217 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 219228 T746 C2384 P44217 oass.SolrIndexSearcher.<init> Opening Searcher@65ce6d realtime
[junit4:junit4] 2> 219228 T746 C2384 P44217 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 219228 T746 C2384 P44217 oasup.LogUpdateProcessor.finish [collection1] webapp=/th_zn path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 15
[junit4:junit4] 2> 219245 T803 C2383 P50047 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 219246 T803 C2383 P50047 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4] 2> 219250 T803 C2383 P50047 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 219253 T748 C2384 P44217 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 219253 T748 C2384 P44217 oasc.SolrCore.execute [collection1] webapp=/th_zn path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 219254 T803 C2383 P50047 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 219254 T803 C2383 P50047 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 219255 T803 C2383 P50047 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 219257 T745 C2384 P44217 oasc.SolrCore.execute [collection1] webapp=/th_zn path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 219258 T803 C2383 P50047 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 219258 T803 C2383 P50047 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty4/index.20130616201628628
[junit4:junit4] 2> 219259 T803 C2383 P50047 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty4/index.20130616201628628 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c9fc60 fullCopy=false
[junit4:junit4] 2> 219264 T746 C2384 P44217 oasc.SolrCore.execute [collection1] webapp=/th_zn path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 219268 T803 C2383 P50047 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 219278 T803 C2383 P50047 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 219278 T803 C2383 P50047 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 219279 T803 C2383 P50047 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty4/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 219280 T803 C2383 P50047 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 219280 T803 C2383 P50047 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 219280 T803 C2383 P50047 oass.SolrIndexSearcher.<init> Opening Searcher@167101a main
[junit4:junit4] 2> 219281 T802 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@167101a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 219282 T803 C2383 P50047 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty4/index.20130616201628628 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty4/index.20130616201628628;done=true>>]
[junit4:junit4] 2> 219282 T803 C2383 P50047 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty4/index.20130616201628628
[junit4:junit4] 2> 219282 T803 C2383 P50047 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty4/index.20130616201628628
[junit4:junit4] 2> 219283 T803 C2383 P50047 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 219283 T803 C2383 P50047 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 219283 T803 C2383 P50047 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 219283 T803 C2383 P50047 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 219285 T803 C2383 P50047 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 219567 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 219568 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59568_th_zn_collection1",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59568_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59568/th_zn"}
[junit4:junit4] 2> 219572 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50047_th_zn_collection1",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:50047_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50047/th_zn"}
[junit4:junit4] 2> 219597 T768 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> 219597 T834 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> 219597 T784 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> 219597 T732 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> 219597 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 219597 T752 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> 219597 T800 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> 219597 T739 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> 219810 T761 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:59568_th_zn_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 219810 T761 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:59568_th_zn_collection1&state=recovering&nodeName=127.0.0.1:59568_th_zn&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1000
[junit4:junit4] 2> 219953 T710 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57876_th_zn
[junit4:junit4] 2> 219955 T710 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57876_th_zn
[junit4:junit4] 2> 219956 T739 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> 219957 T834 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> 219957 T752 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> 219957 T768 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 219957 T800 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 219958 T784 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 219958 T817 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 219957 T768 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> 219958 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 219958 T784 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> 219958 T800 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> 219958 T732 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 219959 T732 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> 219959 T752 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 219960 T834 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 219960 T739 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 219965 T837 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 219965 T837 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 221105 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 221106 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:57876_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57876/th_zn"}
[junit4:junit4] 2> 221106 T733 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 221106 T733 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 221110 T800 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> 221110 T834 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> 221111 T784 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> 221111 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 221111 T739 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> 221110 T768 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> 221111 T752 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> 221112 T732 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> ASYNC NEW_CORE C2385 name=collection1 org.apache.solr.core.SolrCore@44ec0f url=http://127.0.0.1:59568/th_zn/collection1 node=127.0.0.1:59568_th_zn C2385_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:59568_th_zn, base_url=http://127.0.0.1:59568/th_zn}
[junit4:junit4] 2> 221811 T820 C2385 P59568 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:47985/th_zn/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 221812 T820 C2385 P59568 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:59568/th_zn START replicas=[http://127.0.0.1:47985/th_zn/collection1/] nUpdates=100
[junit4:junit4] 2> 221812 T820 C2385 P59568 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 221813 T820 C2385 P59568 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 221813 T820 C2385 P59568 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 221813 T820 C2385 P59568 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 221813 T820 C2385 P59568 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 221813 T820 C2385 P59568 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:47985/th_zn/collection1/. core=collection1
[junit4:junit4] 2> 221813 T820 C2385 P59568 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2386 name=collection1 org.apache.solr.core.SolrCore@edf5d6 url=http://127.0.0.1:47985/th_zn/collection1 node=127.0.0.1:47985_th_zn C2386_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:47985_th_zn, base_url=http://127.0.0.1:47985/th_zn, leader=true}
[junit4:junit4] 2> 221817 T763 C2386 P47985 oasc.SolrCore.execute [collection1] webapp=/th_zn path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 221820 T764 C2386 P47985 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 221823 T764 C2386 P47985 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 221824 T764 C2386 P47985 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 221836 T764 C2386 P47985 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 221837 T764 C2386 P47985 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 221838 T764 C2386 P47985 oass.SolrIndexSearcher.<init> Opening Searcher@ac6e5d realtime
[junit4:junit4] 2> 221838 T764 C2386 P47985 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 221839 T764 C2386 P47985 oasup.LogUpdateProcessor.finish [collection1] webapp=/th_zn path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 19
[junit4:junit4] 2> 221840 T820 C2385 P59568 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 221840 T820 C2385 P59568 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 221842 T762 C2386 P47985 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 221843 T762 C2386 P47985 oasc.SolrCore.execute [collection1] webapp=/th_zn path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 221843 T820 C2385 P59568 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 221843 T820 C2385 P59568 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 221844 T820 C2385 P59568 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 221846 T763 C2386 P47985 oasc.SolrCore.execute [collection1] webapp=/th_zn path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 221846 T820 C2385 P59568 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 221847 T820 C2385 P59568 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty5/index.20130616201631216
[junit4:junit4] 2> 221847 T820 C2385 P59568 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty5/index.20130616201631216 lockFactory=org.apache.lucene.store.NativeFSLockFactory@186514c fullCopy=false
[junit4:junit4] 2> 221849 T764 C2386 P47985 oasc.SolrCore.execute [collection1] webapp=/th_zn path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 221851 T820 C2385 P59568 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 221857 T820 C2385 P59568 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 221857 T820 C2385 P59568 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 221859 T820 C2385 P59568 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty5/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 221860 T820 C2385 P59568 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 221860 T820 C2385 P59568 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 221860 T820 C2385 P59568 oass.SolrIndexSearcher.<init> Opening Searcher@1f566c1 main
[junit4:junit4] 2> 221861 T819 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f566c1 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 221861 T820 C2385 P59568 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty5/index.20130616201631216 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty5/index.20130616201631216;done=true>>]
[junit4:junit4] 2> 221861 T820 C2385 P59568 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty5/index.20130616201631216
[junit4:junit4] 2> 221862 T820 C2385 P59568 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty5/index.20130616201631216
[junit4:junit4] 2> 221862 T820 C2385 P59568 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 221862 T820 C2385 P59568 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 221862 T820 C2385 P59568 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 221862 T820 C2385 P59568 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 221864 T820 C2385 P59568 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 221966 T837 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371428188180/collection1
[junit4:junit4] 2> 221966 T837 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 221967 T837 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 221967 T837 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 221968 T837 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371428188180/collection1/'
[junit4:junit4] 2> 221969 T837 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371428188180/collection1/lib/README' to classloader
[junit4:junit4] 2> 221969 T837 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371428188180/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 222004 T837 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 222033 T837 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 222034 T837 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 222038 T837 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 222362 T837 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 222367 T837 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 222369 T837 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 222380 T837 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 222383 T837 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 222386 T837 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 222393 T837 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 222393 T837 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 222393 T837 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 222394 T837 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 222394 T837 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 222395 T837 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 222395 T837 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371428188180/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty6/
[junit4:junit4] 2> 222395 T837 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@96bfda
[junit4:junit4] 2> 222396 T837 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 222396 T837 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty6
[junit4:junit4] 2> 222396 T837 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty6/index/
[junit4:junit4] 2> 222397 T837 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty6/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 222397 T837 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty6/index
[junit4:junit4] 2> 222418 T837 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 222418 T837 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 222420 T837 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 222420 T837 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 222420 T837 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 222421 T837 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 222421 T837 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 222421 T837 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 222424 T837 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 222424 T837 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 222424 T837 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 222427 T837 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 222430 T837 oass.SolrIndexSearcher.<init> Opening Searcher@19bd82f main
[junit4:junit4] 2> 222431 T837 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 222431 T837 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 222436 T840 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19bd82f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 222438 T837 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 222438 T837 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57876/th_zn collection:collection1 shard:shard3
[junit4:junit4] 2> 222441 T837 oasc.ZkController.register We are http://127.0.0.1:57876/th_zn/collection1/ and leader is http://127.0.0.1:60163/th_zn/collection1/
[junit4:junit4] 2> 222441 T837 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57876/th_zn
[junit4:junit4] 2> 222442 T837 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 222442 T837 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2387 name=collection1 org.apache.solr.core.SolrCore@cb759c url=http://127.0.0.1:57876/th_zn/collection1 node=127.0.0.1:57876_th_zn C2387_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:57876_th_zn, base_url=http://127.0.0.1:57876/th_zn}
[junit4:junit4] 2> 222442 T841 C2387 P57876 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 222443 T841 C2387 P57876 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 222443 T837 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 222443 T841 C2387 P57876 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 222443 T841 C2387 P57876 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 222444 T710 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 222444 T841 C2387 P57876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 222444 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 222445 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 222450 T777 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:57876_th_zn_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 222515 T710 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 222517 T710 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49312
[junit4:junit4] 2> 222518 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 222518 T710 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 222518 T710 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371428191818
[junit4:junit4] 2> 222519 T710 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371428191818/solr.xml
[junit4:junit4] 2> 222519 T710 oasc.CoreContainer.<init> New CoreContainer 28494331
[junit4:junit4] 2> 222519 T710 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371428191818/'
[junit4:junit4] 2> 222520 T710 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371428191818/'
[junit4:junit4] 2> 222560 T710 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 222561 T710 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 222561 T710 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 222561 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 222562 T710 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 222562 T710 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 222562 T710 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 222563 T710 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 222563 T710 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 222563 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 222575 T710 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 222575 T710 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60508/solr
[junit4:junit4] 2> 222576 T710 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 222577 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 222578 T853 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@143ce54 name:ZooKeeperConnection Watcher:127.0.0.1:60508 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 222578 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 222583 T710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 222587 T710 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 222588 T855 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c8847 name:ZooKeeperConnection Watcher:127.0.0.1:60508/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 222588 T710 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 222592 T710 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 222616 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 222617 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59568_th_zn_collection1",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59568_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59568/th_zn"}
[junit4:junit4] 2> 222619 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:57876_th_zn_collection1",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:57876_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57876/th_zn"}
[junit4:junit4] 2> 222623 T784 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> 222624 T752 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> 222624 T732 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> 222624 T834 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> 222624 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 222623 T739 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> 222623 T768 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> 222623 T800 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> 222625 T855 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> 223451 T777 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:57876_th_zn_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 223451 T777 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:57876_th_zn_collection1&state=recovering&nodeName=127.0.0.1:57876_th_zn&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 223595 T710 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49312_th_zn
[junit4:junit4] 2> 223596 T710 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49312_th_zn
[junit4:junit4] 2> 223598 T739 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> 223598 T834 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> 223599 T752 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> 223599 T784 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 223599 T855 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> 223599 T817 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 223600 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 223600 T800 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 223600 T800 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> 223599 T784 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> 223600 T768 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 223600 T732 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 223601 T732 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> 223601 T768 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> 223602 T834 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 223602 T752 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 223602 T739 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 223603 T855 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 223607 T856 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 223607 T856 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 224130 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 224131 T733 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49312_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49312/th_zn"}
[junit4:junit4] 2> 224131 T733 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 224131 T733 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 224135 T768 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> 224136 T752 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> 224136 T732 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> 224136 T855 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> 224135 T834 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> 224136 T800 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> 224135 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 224135 T784 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> 224135 T739 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> 224609 T856 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371428191818/collection1
[junit4:junit4] 2> 224609 T856 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 224610 T856 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 224610 T856 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 224611 T856 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371428191818/collection1/'
[junit4:junit4] 2> 224612 T856 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371428191818/collection1/lib/README' to classloader
[junit4:junit4] 2> 224612 T856 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371428191818/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 224634 T856 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 224669 T856 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 224670 T856 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 224674 T856 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 225012 T856 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 225017 T856 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 225019 T856 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 225031 T856 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 225033 T856 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 225036 T856 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 225037 T856 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 225038 T856 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 225038 T856 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 225039 T856 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 225039 T856 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 225039 T856 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 225039 T856 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371428191818/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty7/
[junit4:junit4] 2> 225039 T856 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@96bfda
[junit4:junit4] 2> 225040 T856 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 225040 T856 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty7
[junit4:junit4] 2> 225041 T856 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty7/index/
[junit4:junit4] 2> 225041 T856 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty7/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 225041 T856 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty7/index
[junit4:junit4] 2> 225045 T856 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty7/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 225045 T856 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 225046 T856 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 225047 T856 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 225047 T856 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 225047 T856 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 225048 T856 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 225048 T856 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 225048 T856 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 225049 T856 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 225049 T856 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 225051 T856 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 225053 T856 oass.SolrIndexSearcher.<init> Opening Searcher@9f30ff main
[junit4:junit4] 2> 225054 T856 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 225054 T856 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 225057 T857 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9f30ff main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 225059 T856 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 225059 T856 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49312/th_zn collection:collection1 shard:shard1
[junit4:junit4] 2> 225062 T856 oasc.ZkController.register We are http://127.0.0.1:49312/th_zn/collection1/ and leader is http://127.0.0.1:44217/th_zn/collection1/
[junit4:junit4] 2> 225062 T856 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49312/th_zn
[junit4:junit4] 2> 225062 T856 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 225062 T856 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2388 name=collection1 org.apache.solr.core.SolrCore@1a5a52e url=http://127.0.0.1:49312/th_zn/collection1 node=127.0.0.1:49312_th_zn C2388_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:49312_th_zn, base_url=http://127.0.0.1:49312/th_zn}
[junit4:junit4] 2> 225063 T858 C2388 P49312 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 225063 T858 C2388 P49312 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 225063 T856 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 225064 T858 C2388 P49312 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 225064 T858 C2388 P49312 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 225064 T710 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 225065 T710 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 225065 T858 C2388 P49312 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[j
[...truncated too long message...]
ull}
[junit4:junit4] 2> 344045 T710 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 59410
[junit4:junit4] 2> 344046 T710 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=22023292
[junit4:junit4] 2> 344403 T1152 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 344405 T1152 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50526_th_zn_collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:50526_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50526/th_zn"}
[junit4:junit4] 2> 344410 T1152 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50526_th_zn_collection1",
[junit4:junit4] 2> "numShards":null,
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:50526_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50526/th_zn"}
[junit4:junit4] 2> 344415 T1152 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59410_th_zn_collection1",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59410_th_zn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59410/th_zn"}
[junit4:junit4] 2> 344422 T950 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> 345048 T710 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 345049 T710 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 345052 T710 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@1497b61
[junit4:junit4] 2> 345054 T710 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=22,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=69,cumulative_deletesById=32,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 345055 T710 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 345056 T710 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 345057 T710 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 345059 T710 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 345060 T710 oasc.CachingDirectoryFactory.close Closing StandardDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 345061 T710 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty12 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty12;done=false>>]
[junit4:junit4] 2> 345062 T710 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty12
[junit4:junit4] 2> 345062 T710 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty12/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty12/index;done=false>>]
[junit4:junit4] 2> 345063 T710 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371428170406/jetty12/index
[junit4:junit4] 2> 345064 T1152 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89877916575858716-127.0.0.1:59410_th_zn-n_0000000012) am no longer a leader.
[junit4:junit4] 2> 345090 T710 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/th_zn,null}
[junit4:junit4] 2> 345168 T710 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 345170 T710 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:60508 60508
[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=FB5BFA710EBB3452 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=nl_NL -Dtests.timezone=America/Curacao -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 144s J1 | ChaosMonkeySafeLeaderTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard3 is not consistent. Got 42 from http://127.0.0.1:32842/th_zn/collection1lastClient and got 37 from http://127.0.0.1:59410/th_zn/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([FB5BFA710EBB3452:7ABD746979E4546E]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 345210 T710 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 144191 T709 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> 346368 T950 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 346368 T950 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> 346369 T950 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene41, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=nl_NL, timezone=America/Curacao
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic i386/Oracle Corporation 1.7.0_21 (32-bit)/cpus=8,threads=2,free=14281104,total=124227584
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SuggesterWFSTTest, TestElisionMultitermQuery, TestFiltering, HighlighterTest, XsltUpdateRequestHandlerTest, TestQueryTypes, TimeZoneUtilsTest, TestCSVResponseWriter, DirectUpdateHandlerTest, StandardRequestHandlerTest, SolrRequestParserTest, TestMultiCoreConfBootstrap, TestZkChroot, TestFieldTypeResource, TestManagedSchemaFieldResource, TestSolrXMLSerializer, TestRecovery, XmlUpdateRequestHandlerTest, TestRandomFaceting, SignatureUpdateProcessorFactoryTest, TestSolrQueryParserDefaultOperatorResource, ClusterStateTest, SuggesterTSTTest, TestJmxIntegration, TestDistributedGrouping, TestWordDelimiterFilterFactory, IndexReaderFactoryTest, RequiredFieldsTest, TestCopyFieldCollectionResource, TestAnalyzedSuggestions, TestReload, PingRequestHandlerTest, DateMathParserTest, RequestHandlersTest, FileUtilsTest, TestDFRSimilarityFactory, TestFoldingMultitermQuery, ChaosMonkeySafeLeaderTest]
[junit4:junit4] Completed on J1 in 145.48s, 1 test, 1 failure <<< FAILURES!
[...truncated 696 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:386: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:366: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1243: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:887: There were test failures: 296 suites, 1243 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 39 minutes 2 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_21 -server -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure