You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/25 05:19:30 UTC
[JENKINS] Lucene-Solr-4.x-Linux (64bit/jdk1.6.0_45) - Build # 6226
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/6226/
Java: 64bit/jdk1.6.0_45 -XX:+UseCompressedOops -XX:+UseSerialGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.testDistribSearch
Error Message:
shard3 is not consistent. Got 45 from http://127.0.0.1:43327/collection1lastClient and got 43 from http://127.0.0.1:46368/collection1
Stack Trace:
java.lang.AssertionError: shard3 is not consistent. Got 45 from http://127.0.0.1:43327/collection1lastClient and got 43 from http://127.0.0.1:46368/collection1
at __randomizedtesting.SeedInfo.seed([5DFD305AA549EAB5:DC1BBE42D2168A89]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:662)
Build Log:
[...truncated 8769 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
[junit4:junit4] 2> 42202 T208 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 42214 T208 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeySafeLeaderTest-1372129157759
[junit4:junit4] 2> 42217 T208 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 42220 T209 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 42319 T208 oasc.ZkTestServer.run start zk server on port:42996
[junit4:junit4] 2> 42368 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 42419 T215 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@70a612ad name:ZooKeeperConnection Watcher:127.0.0.1:42996 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 42423 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 42424 T208 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 42449 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 42455 T217 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@526c6b62 name:ZooKeeperConnection Watcher:127.0.0.1:42996/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 42455 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 42457 T208 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 42461 T208 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 42465 T208 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 42468 T208 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 42472 T208 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 42639 T208 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 42646 T208 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 42647 T208 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 42651 T208 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 42652 T208 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 42656 T208 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 42657 T208 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 42661 T208 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 42661 T208 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 42665 T208 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 42666 T208 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 42670 T208 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 42671 T208 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 42675 T208 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 42676 T208 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 42679 T208 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 42680 T208 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 42769 T208 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 42787 T208 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:38955
[junit4:junit4] 2> 42787 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 42788 T208 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 42788 T208 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372129158228
[junit4:junit4] 2> 42789 T208 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372129158228/solr.xml
[junit4:junit4] 2> 42789 T208 oasc.CoreContainer.<init> New CoreContainer 142278335
[junit4:junit4] 2> 42790 T208 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372129158228/'
[junit4:junit4] 2> 42790 T208 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372129158228/'
[junit4:junit4] 2> 42838 T208 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 42839 T208 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 42839 T208 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 42840 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 42840 T208 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 42841 T208 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 42841 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 42842 T208 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 42842 T208 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 42842 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 42846 T208 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 42847 T208 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42996/solr
[junit4:junit4] 2> 42860 T208 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 42861 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 42864 T228 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4c057cc6 name:ZooKeeperConnection Watcher:127.0.0.1:42996 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 42864 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 42868 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 42874 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 42876 T230 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2584a7d6 name:ZooKeeperConnection Watcher:127.0.0.1:42996/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 42876 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 42882 T208 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 42891 T208 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 42900 T208 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 42903 T208 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38955_
[junit4:junit4] 2> 42907 T208 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38955_
[junit4:junit4] 2> 42912 T208 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 42924 T208 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 42928 T208 oasc.Overseer.start Overseer (id=89923856487677955-127.0.0.1:38955_-n_0000000000) starting
[junit4:junit4] 2> 42939 T208 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 42950 T232 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 42950 T208 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 42954 T208 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 42958 T208 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 42966 T231 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 42973 T233 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 42973 T233 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 44474 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 44475 T231 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:38955_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38955"}
[junit4:junit4] 2> 44476 T231 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 44482 T231 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 44493 T230 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> 44976 T233 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372129158228/collection1
[junit4:junit4] 2> 44976 T233 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 44977 T233 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 44978 T233 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 44980 T233 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372129158228/collection1/'
[junit4:junit4] 2> 44981 T233 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372129158228/collection1/lib/README' to classloader
[junit4:junit4] 2> 44981 T233 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372129158228/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 45015 T233 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 45058 T233 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 45060 T233 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 45067 T233 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 45495 T233 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 45495 T233 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 45496 T233 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 45503 T233 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 45507 T233 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 45528 T233 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 45532 T233 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 45536 T233 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 45538 T233 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 45539 T233 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 45539 T233 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 45541 T233 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 45541 T233 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 45542 T233 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 45548 T233 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372129158228/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/control/data/
[junit4:junit4] 2> 45548 T233 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@47875da7
[junit4:junit4] 2> 45549 T233 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 45549 T233 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/control/data
[junit4:junit4] 2> 45550 T233 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/control/data/index/
[junit4:junit4] 2> 45550 T233 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 45551 T233 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/control/data/index
[junit4:junit4] 2> 45568 T233 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 45569 T233 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 45572 T233 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 45572 T233 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 45573 T233 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 45574 T233 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 45575 T233 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 45575 T233 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 45575 T233 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 45576 T233 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 45577 T233 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 45579 T233 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 45582 T233 oass.SolrIndexSearcher.<init> Opening Searcher@4f0ea988 main
[junit4:junit4] 2> 45583 T233 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 45583 T233 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 45587 T234 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4f0ea988 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 45589 T233 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 45590 T233 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38955 collection:control_collection shard:shard1
[junit4:junit4] 2> 45592 T233 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 45597 T233 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 45607 T233 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 45611 T233 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 45611 T233 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 45613 T233 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:38955/collection1/
[junit4:junit4] 2> 45613 T233 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 45613 T233 oasc.SyncStrategy.syncToMe http://127.0.0.1:38955/collection1/ has no replicas
[junit4:junit4] 2> 45613 T233 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:38955/collection1/
[junit4:junit4] 2> 45614 T233 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 45999 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 46086 T230 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> 46124 T233 oasc.ZkController.register We are http://127.0.0.1:38955/collection1/ and leader is http://127.0.0.1:38955/collection1/
[junit4:junit4] 2> 46125 T233 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38955
[junit4:junit4] 2> 46125 T233 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 46125 T233 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 46125 T233 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 46128 T233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 46129 T208 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 46130 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 46131 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 46136 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 46139 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 46142 T237 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@47fe766f name:ZooKeeperConnection Watcher:127.0.0.1:42996/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 46142 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 46144 T208 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 46149 T208 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 46218 T208 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 46220 T208 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50964
[junit4:junit4] 2> 46221 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 46221 T208 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 46221 T208 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372129161693
[junit4:junit4] 2> 46222 T208 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372129161693/solr.xml
[junit4:junit4] 2> 46222 T208 oasc.CoreContainer.<init> New CoreContainer 1182831483
[junit4:junit4] 2> 46223 T208 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372129161693/'
[junit4:junit4] 2> 46223 T208 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372129161693/'
[junit4:junit4] 2> 46275 T208 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 46276 T208 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 46276 T208 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 46277 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 46277 T208 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 46278 T208 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 46278 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 46279 T208 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 46279 T208 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 46279 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 46284 T208 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 46285 T208 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42996/solr
[junit4:junit4] 2> 46285 T208 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 46286 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 46289 T248 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@684640e6 name:ZooKeeperConnection Watcher:127.0.0.1:42996 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 46290 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 46292 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 46298 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 46300 T250 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d2fa9ae name:ZooKeeperConnection Watcher:127.0.0.1:42996/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 46300 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 46305 T208 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 47309 T208 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50964_
[junit4:junit4] 2> 47311 T208 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50964_
[junit4:junit4] 2> 47314 T230 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> 47315 T237 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 47315 T250 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 47317 T230 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 47322 T251 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 47323 T251 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 47594 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 47595 T231 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:38955__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:38955_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38955"}
[junit4:junit4] 2> 47600 T231 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:50964_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50964"}
[junit4:junit4] 2> 47601 T231 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 3
[junit4:junit4] 2> 47601 T231 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 47627 T230 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> 47627 T237 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> 47627 T250 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> 48324 T251 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372129161693/collection1
[junit4:junit4] 2> 48325 T251 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 48326 T251 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 48326 T251 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 48328 T251 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372129161693/collection1/'
[junit4:junit4] 2> 48328 T251 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372129161693/collection1/lib/README' to classloader
[junit4:junit4] 2> 48329 T251 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372129161693/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 48365 T251 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 48400 T251 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 48402 T251 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 48406 T251 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 48840 T251 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 48841 T251 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 48842 T251 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 48850 T251 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 48854 T251 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 48882 T251 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 48894 T251 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 48916 T251 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 48923 T251 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 48924 T251 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 48924 T251 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 48926 T251 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 48927 T251 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 48927 T251 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 48928 T251 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372129161693/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty1/
[junit4:junit4] 2> 48928 T251 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@47875da7
[junit4:junit4] 2> 48929 T251 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 48930 T251 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty1
[junit4:junit4] 2> 48930 T251 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty1/index/
[junit4:junit4] 2> 48931 T251 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 48931 T251 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty1/index
[junit4:junit4] 2> 49008 T251 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 49009 T251 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 49012 T251 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 49012 T251 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 49013 T251 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 49013 T251 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 49014 T251 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 49014 T251 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 49015 T251 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 49015 T251 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 49016 T251 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 49018 T251 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 49021 T251 oass.SolrIndexSearcher.<init> Opening Searcher@a70cf21 main
[junit4:junit4] 2> 49021 T251 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 49022 T251 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 49028 T252 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@a70cf21 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 49031 T251 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 49032 T251 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50964 collection:collection1 shard:shard1
[junit4:junit4] 2> 49033 T251 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 49042 T251 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 49045 T251 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 49046 T251 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 49046 T251 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50964/collection1/
[junit4:junit4] 2> 49046 T251 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 49047 T251 oasc.SyncStrategy.syncToMe http://127.0.0.1:50964/collection1/ has no replicas
[junit4:junit4] 2> 49047 T251 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50964/collection1/
[junit4:junit4] 2> 49048 T251 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 49136 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 49147 T237 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> 49147 T250 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> 49147 T230 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> 49156 T251 oasc.ZkController.register We are http://127.0.0.1:50964/collection1/ and leader is http://127.0.0.1:50964/collection1/
[junit4:junit4] 2> 49156 T251 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50964
[junit4:junit4] 2> 49156 T251 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 49157 T251 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 49157 T251 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 49159 T251 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 49160 T208 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 49161 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 49161 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 49238 T208 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 49240 T208 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57963
[junit4:junit4] 2> 49241 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 49241 T208 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 49242 T208 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372129164709
[junit4:junit4] 2> 49242 T208 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372129164709/solr.xml
[junit4:junit4] 2> 49242 T208 oasc.CoreContainer.<init> New CoreContainer 92692649
[junit4:junit4] 2> 49243 T208 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372129164709/'
[junit4:junit4] 2> 49243 T208 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372129164709/'
[junit4:junit4] 2> 49315 T208 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 49316 T208 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 49316 T208 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 49317 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 49317 T208 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 49318 T208 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 49318 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 49319 T208 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 49319 T208 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 49320 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 49325 T208 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 49326 T208 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42996/solr
[junit4:junit4] 2> 49327 T208 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 49328 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 49330 T264 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@74d53153 name:ZooKeeperConnection Watcher:127.0.0.1:42996 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 49331 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 49333 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 49338 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 49341 T266 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c4b5011 name:ZooKeeperConnection Watcher:127.0.0.1:42996/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 49341 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 49347 T208 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 50353 T208 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57963_
[junit4:junit4] 2> 50355 T208 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57963_
[junit4:junit4] 2> 50358 T237 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> 50358 T230 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> 50360 T266 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 50360 T250 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 50360 T250 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> 50362 T237 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 50362 T230 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 50367 T267 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 50367 T267 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 50655 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 50656 T231 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50964__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:50964_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50964"}
[junit4:junit4] 2> 50661 T231 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:57963_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57963"}
[junit4:junit4] 2> 50662 T231 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 50662 T231 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 50697 T250 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> 50697 T266 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> 50697 T230 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> 50697 T237 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> 51369 T267 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372129164709/collection1
[junit4:junit4] 2> 51369 T267 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 51371 T267 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 51371 T267 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 51372 T267 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372129164709/collection1/'
[junit4:junit4] 2> 51373 T267 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372129164709/collection1/lib/README' to classloader
[junit4:junit4] 2> 51373 T267 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372129164709/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 51409 T267 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 51466 T267 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 51468 T267 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 51474 T267 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 51883 T267 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 51884 T267 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 51885 T267 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 51891 T267 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 51894 T267 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 51919 T267 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 51924 T267 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 51928 T267 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 51930 T267 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 51930 T267 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 51931 T267 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 51932 T267 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 51933 T267 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 51933 T267 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 51933 T267 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372129164709/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty2/
[junit4:junit4] 2> 51933 T267 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@47875da7
[junit4:junit4] 2> 51934 T267 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 51935 T267 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty2
[junit4:junit4] 2> 51935 T267 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty2/index/
[junit4:junit4] 2> 51935 T267 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 51935 T267 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty2/index
[junit4:junit4] 2> 52010 T267 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 52011 T267 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 52014 T267 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 52015 T267 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 52016 T267 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 52017 T267 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 52018 T267 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 52018 T267 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 52019 T267 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 52019 T267 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 52020 T267 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 52023 T267 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 52028 T267 oass.SolrIndexSearcher.<init> Opening Searcher@332a4674 main
[junit4:junit4] 2> 52029 T267 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 52029 T267 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 52036 T268 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@332a4674 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 52040 T267 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 52040 T267 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57963 collection:collection1 shard:shard2
[junit4:junit4] 2> 52041 T267 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 52050 T267 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 52054 T267 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 52054 T267 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 52055 T267 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:57963/collection1/
[junit4:junit4] 2> 52055 T267 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 52055 T267 oasc.SyncStrategy.syncToMe http://127.0.0.1:57963/collection1/ has no replicas
[junit4:junit4] 2> 52056 T267 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:57963/collection1/
[junit4:junit4] 2> 52056 T267 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 52205 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52216 T230 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> 52216 T266 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> 52216 T250 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> 52216 T237 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> 52263 T267 oasc.ZkController.register We are http://127.0.0.1:57963/collection1/ and leader is http://127.0.0.1:57963/collection1/
[junit4:junit4] 2> 52263 T267 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57963
[junit4:junit4] 2> 52264 T267 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 52264 T267 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 52264 T267 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 52278 T267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52279 T208 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 52280 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 52280 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 52353 T208 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 52355 T208 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50043
[junit4:junit4] 2> 52356 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 52356 T208 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 52357 T208 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372129167828
[junit4:junit4] 2> 52357 T208 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372129167828/solr.xml
[junit4:junit4] 2> 52358 T208 oasc.CoreContainer.<init> New CoreContainer 828519305
[junit4:junit4] 2> 52358 T208 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372129167828/'
[junit4:junit4] 2> 52358 T208 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372129167828/'
[junit4:junit4] 2> 52408 T208 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 52409 T208 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 52409 T208 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 52410 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 52410 T208 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 52410 T208 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 52411 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 52411 T208 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 52412 T208 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 52412 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 52416 T208 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 52416 T208 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42996/solr
[junit4:junit4] 2> 52417 T208 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 52418 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 52420 T280 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@331d3edd name:ZooKeeperConnection Watcher:127.0.0.1:42996 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 52421 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 52423 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 52427 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 52428 T282 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@52c4d93 name:ZooKeeperConnection Watcher:127.0.0.1:42996/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 52429 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 52433 T208 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 53437 T208 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50043_
[junit4:junit4] 2> 53438 T208 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50043_
[junit4:junit4] 2> 53441 T237 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> 53441 T230 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> 53442 T266 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 53442 T266 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> 53443 T282 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 53443 T250 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 53443 T250 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> 53446 T230 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 53446 T237 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 53450 T283 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 53451 T283 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 53725 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53727 T231 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:57963__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:57963_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57963"}
[junit4:junit4] 2> 53732 T231 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:50043_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50043"}
[junit4:junit4] 2> 53732 T231 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 53732 T231 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 53757 T250 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> 53757 T266 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> 53757 T230 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> 53757 T282 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> 53757 T237 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> 54452 T283 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372129167828/collection1
[junit4:junit4] 2> 54453 T283 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 54454 T283 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 54454 T283 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 54456 T283 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372129167828/collection1/'
[junit4:junit4] 2> 54456 T283 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372129167828/collection1/lib/README' to classloader
[junit4:junit4] 2> 54457 T283 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372129167828/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 54491 T283 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 54526 T283 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 54528 T283 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 54532 T283 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 54947 T283 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 54948 T283 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 54949 T283 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 54957 T283 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 54959 T283 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 54977 T283 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 54985 T283 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 54989 T283 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 54991 T283 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 54991 T283 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 54991 T283 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 54993 T283 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 54993 T283 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 54994 T283 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 54994 T283 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372129167828/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty3/
[junit4:junit4] 2> 54994 T283 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@47875da7
[junit4:junit4] 2> 54995 T283 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 54995 T283 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty3
[junit4:junit4] 2> 54996 T283 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty3/index/
[junit4:junit4] 2> 54996 T283 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 54996 T283 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty3/index
[junit4:junit4] 2> 55018 T283 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 55019 T283 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 55021 T283 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 55021 T283 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 55022 T283 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 55022 T283 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 55023 T283 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 55023 T283 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 55023 T283 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 55024 T283 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 55024 T283 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 55026 T283 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 55031 T283 oass.SolrIndexSearcher.<init> Opening Searcher@17a0d510 main
[junit4:junit4] 2> 55031 T283 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 55032 T283 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 55038 T284 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@17a0d510 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 55042 T283 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 55042 T283 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50043 collection:collection1 shard:shard3
[junit4:junit4] 2> 55043 T283 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4:junit4] 2> 55050 T283 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 55054 T283 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 55054 T283 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 55054 T283 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50043/collection1/
[junit4:junit4] 2> 55055 T283 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 55055 T283 oasc.SyncStrategy.syncToMe http://127.0.0.1:50043/collection1/ has no replicas
[junit4:junit4] 2> 55056 T283 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50043/collection1/
[junit4:junit4] 2> 55056 T283 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4:junit4] 2> 55267 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 55275 T237 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> 55276 T250 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> 55276 T266 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> 55276 T282 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> 55277 T230 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> 55313 T283 oasc.ZkController.register We are http://127.0.0.1:50043/collection1/ and leader is http://127.0.0.1:50043/collection1/
[junit4:junit4] 2> 55314 T283 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50043
[junit4:junit4] 2> 55314 T283 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 55314 T283 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 55314 T283 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 55316 T283 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 55318 T208 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 55318 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 55318 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 55389 T208 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 55392 T208 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:32793
[junit4:junit4] 2> 55392 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 55393 T208 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 55393 T208 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372129170866
[junit4:junit4] 2> 55393 T208 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372129170866/solr.xml
[junit4:junit4] 2> 55394 T208 oasc.CoreContainer.<init> New CoreContainer 121074373
[junit4:junit4] 2> 55394 T208 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372129170866/'
[junit4:junit4] 2> 55395 T208 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372129170866/'
[junit4:junit4] 2> 55443 T208 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 55444 T208 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 55445 T208 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 55445 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 55446 T208 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 55446 T208 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 55447 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 55447 T208 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 55448 T208 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 55448 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 55451 T208 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 55452 T208 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42996/solr
[junit4:junit4] 2> 55452 T208 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 55453 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 55455 T296 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4f639615 name:ZooKeeperConnection Watcher:127.0.0.1:42996 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 55456 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 55462 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 55465 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 55467 T298 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@649cbfa1 name:ZooKeeperConnection Watcher:127.0.0.1:42996/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 55468 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 55472 T208 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 56476 T208 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:32793_
[junit4:junit4] 2> 56478 T208 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:32793_
[junit4:junit4] 2> 56481 T237 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> 56481 T282 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> 56481 T230 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> 56483 T266 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 56483 T266 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> 56483 T250 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 56484 T250 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> 56484 T298 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 56485 T237 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 56485 T282 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 56486 T230 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 56491 T299 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 56492 T299 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 56786 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 56790 T231 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50043__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:50043_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50043"}
[junit4:junit4] 2> 56796 T231 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:32793_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:32793"}
[junit4:junit4] 2> 56796 T231 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 56796 T231 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 56847 T230 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> 56847 T266 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> 56847 T250 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> 56847 T298 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> 56847 T237 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> 56847 T282 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> 57493 T299 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372129170866/collection1
[junit4:junit4] 2> 57494 T299 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 57495 T299 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 57495 T299 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 57497 T299 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372129170866/collection1/'
[junit4:junit4] 2> 57497 T299 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372129170866/collection1/lib/README' to classloader
[junit4:junit4] 2> 57498 T299 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372129170866/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 57538 T299 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 57592 T299 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 57594 T299 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 57600 T299 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 58036 T299 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 58036 T299 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 58037 T299 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 58043 T299 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 58046 T299 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 58066 T299 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 58069 T299 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 58074 T299 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 58075 T299 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 58076 T299 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 58076 T299 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 58078 T299 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 58078 T299 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 58078 T299 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 58078 T299 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372129170866/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty4/
[junit4:junit4] 2> 58079 T299 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@47875da7
[junit4:junit4] 2> 58079 T299 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 58080 T299 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty4
[junit4:junit4] 2> 58080 T299 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty4/index/
[junit4:junit4] 2> 58080 T299 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 58081 T299 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty4/index
[junit4:junit4] 2> 58083 T299 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 58084 T299 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 58086 T299 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 58086 T299 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 58087 T299 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 58087 T299 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 58088 T299 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 58088 T299 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 58088 T299 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 58089 T299 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 58089 T299 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 58091 T299 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 58096 T299 oass.SolrIndexSearcher.<init> Opening Searcher@2868fede main
[junit4:junit4] 2> 58096 T299 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 58097 T299 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 58102 T300 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2868fede main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 58104 T299 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 58104 T299 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:32793 collection:collection1 shard:shard1
[junit4:junit4] 2> 58108 T299 oasc.ZkController.register We are http://127.0.0.1:32793/collection1/ and leader is http://127.0.0.1:50964/collection1/
[junit4:junit4] 2> 58109 T299 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:32793
[junit4:junit4] 2> 58109 T299 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 58110 T299 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C78 name=collection1 org.apache.solr.core.SolrCore@747efaf6 url=http://127.0.0.1:32793/collection1 node=127.0.0.1:32793_ C78_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:32793_, base_url=http://127.0.0.1:32793}
[junit4:junit4] 2> 58114 T301 C78 P32793 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 58114 T299 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 58117 T301 C78 P32793 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 58118 T301 C78 P32793 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 58118 T301 C78 P32793 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 58120 T208 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 58120 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 58120 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 58121 T301 C78 P32793 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 58133 T244 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:32793__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 58199 T208 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 58202 T208 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50497
[junit4:junit4] 2> 58203 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 58204 T208 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 58204 T208 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372129173670
[junit4:junit4] 2> 58204 T208 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372129173670/solr.xml
[junit4:junit4] 2> 58205 T208 oasc.CoreContainer.<init> New CoreContainer 1137015402
[junit4:junit4] 2> 58205 T208 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372129173670/'
[junit4:junit4] 2> 58206 T208 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372129173670/'
[junit4:junit4] 2> 58261 T208 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 58261 T208 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 58262 T208 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 58262 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 58263 T208 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 58263 T208 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 58263 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 58264 T208 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 58264 T208 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 58264 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 58268 T208 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 58269 T208 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42996/solr
[junit4:junit4] 2> 58269 T208 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 58270 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 58272 T313 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7a112202 name:ZooKeeperConnection Watcher:127.0.0.1:42996 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 58273 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 58275 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 58279 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 58281 T315 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9ebaf65 name:ZooKeeperConnection Watcher:127.0.0.1:42996/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 58282 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 58286 T208 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 58358 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 58359 T231 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:32793__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:32793_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:32793"}
[junit4:junit4] 2> 58365 T237 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> 58366 T282 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> 58366 T230 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> 58366 T266 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> 58366 T298 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> 58365 T315 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> 58365 T250 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> 59134 T244 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:32793__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 59134 T244 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:32793__collection1&state=recovering&nodeName=127.0.0.1:32793_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1003
[junit4:junit4] 2> 59292 T208 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50497_
[junit4:junit4] 2> 59293 T208 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50497_
[junit4:junit4] 2> 59296 T237 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> 59296 T230 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> 59297 T282 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> 59297 T298 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 59298 T298 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> 59297 T250 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 59298 T250 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> 59299 T315 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 59298 T266 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 59299 T266 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> 59299 T315 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> 59300 T237 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 59300 T230 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 59301 T282 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 59314 T316 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 59314 T316 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 59875 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 59877 T231 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:50497_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50497"}
[junit4:junit4] 2> 59877 T231 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 59877 T231 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 59882 T250 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> 59882 T230 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> 59882 T298 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> 59883 T282 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> 59883 T315 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> 59882 T266 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> 59882 T237 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> 60317 T316 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372129173670/collection1
[junit4:junit4] 2> 60317 T316 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 60318 T316 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 60319 T316 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 60320 T316 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372129173670/collection1/'
[junit4:junit4] 2> 60321 T316 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372129173670/collection1/lib/README' to classloader
[junit4:junit4] 2> 60322 T316 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372129173670/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 60360 T316 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 60393 T316 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 60395 T316 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 60399 T316 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 60837 T316 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 60837 T316 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 60838 T316 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 60844 T316 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 60847 T316 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 60870 T316 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 60873 T316 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 60877 T316 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 60878 T316 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 60879 T316 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 60879 T316 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 60880 T316 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 60880 T316 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 60881 T316 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 60881 T316 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372129173670/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty5/
[junit4:junit4] 2> 60881 T316 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@47875da7
[junit4:junit4] 2> 60882 T316 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 60882 T316 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty5
[junit4:junit4] 2> 60883 T316 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty5/index/
[junit4:junit4] 2> 60883 T316 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 60883 T316 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty5/index
[junit4:junit4] 2> 60886 T316 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 60886 T316 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 60888 T316 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 60889 T316 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 60889 T316 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 60890 T316 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 60890 T316 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 60891 T316 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 60891 T316 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 60892 T316 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 60892 T316 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 60894 T316 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 60897 T316 oass.SolrIndexSearcher.<init> Opening Searcher@70019a64 main
[junit4:junit4] 2> 60898 T316 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 60898 T316 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 60903 T317 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@70019a64 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 60905 T316 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 60906 T316 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50497 collection:collection1 shard:shard2
[junit4:junit4] 2> 60910 T316 oasc.ZkController.register We are http://127.0.0.1:50497/collection1/ and leader is http://127.0.0.1:57963/collection1/
[junit4:junit4] 2> 60910 T316 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50497
[junit4:junit4] 2> 60910 T316 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 60910 T316 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C79 name=collection1 org.apache.solr.core.SolrCore@3a028fb7 url=http://127.0.0.1:50497/collection1 node=127.0.0.1:50497_ C79_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:50497_, base_url=http://127.0.0.1:50497}
[junit4:junit4] 2> 60911 T318 C79 P50497 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 60912 T316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 60917 T318 C79 P50497 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 60918 T318 C79 P50497 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 60918 T318 C79 P50497 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 60919 T208 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 60920 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 60920 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 60921 T318 C79 P50497 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 60930 T262 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:50497__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 61024 T208 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 61027 T208 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58541
[junit4:junit4] 2> 61028 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 61028 T208 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 61029 T208 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372129176470
[junit4:junit4] 2> 61029 T208 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372129176470/solr.xml
[junit4:junit4] 2> 61029 T208 oasc.CoreContainer.<init> New CoreContainer 966372305
[junit4:junit4] 2> 61030 T208 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372129176470/'
[junit4:junit4] 2> 61030 T208 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372129176470/'
[junit4:junit4] 2> 61081 T208 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 61082 T208 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 61082 T208 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 61082 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 61083 T208 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 61083 T208 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 61083 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 61084 T208 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 61084 T208 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 61084 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 61088 T208 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 61088 T208 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42996/solr
[junit4:junit4] 2> 61089 T208 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 61090 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 61095 T330 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@709ff881 name:ZooKeeperConnection Watcher:127.0.0.1:42996 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 61096 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 61103 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 61110 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 61111 T332 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7a01fdb2 name:ZooKeeperConnection Watcher:127.0.0.1:42996/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 61112 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 61117 T208 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C80 name=collection1 org.apache.solr.core.SolrCore@747efaf6 url=http://127.0.0.1:32793/collection1 node=127.0.0.1:32793_ C80_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:32793_, base_url=http://127.0.0.1:32793}
[junit4:junit4] 2> 61136 T301 C80 P32793 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50964/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 61140 T301 C80 P32793 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 61146 T301 C80 P32793 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:32793 START replicas=[http://127.0.0.1:50964/collection1/] nUpdates=100
[junit4:junit4] 2> 61147 T301 C80 P32793 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 61148 T301 C80 P32793 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 61148 T301 C80 P32793 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 61148 T301 C80 P32793 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 61149 T301 C80 P32793 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 61151 T301 C80 P32793 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50964/collection1/. core=collection1
[junit4:junit4] 2> 61152 T301 C80 P32793 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C81 name=collection1 org.apache.solr.core.SolrCore@6e1def url=http://127.0.0.1:50964/collection1 node=127.0.0.1:50964_ C81_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50964_, base_url=http://127.0.0.1:50964, leader=true}
[junit4:junit4] 2> 61156 T246 C81 P50964 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 61161 T245 C81 P50964 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 61165 T245 C81 P50964 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 61165 T245 C81 P50964 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 61177 T245 C81 P50964 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 61177 T245 C81 P50964 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 61178 T245 C81 P50964 oass.SolrIndexSearcher.<init> Opening Searcher@743b4f79 realtime
[junit4:junit4] 2> 61179 T245 C81 P50964 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 61179 T245 C81 P50964 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 21
[junit4:junit4] 2> 61204 T301 C80 P32793 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 61205 T301 C80 P32793 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4] 2> 61213 T301 C80 P32793 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 61216 T246 C81 P50964 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 61217 T246 C81 P50964 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 61218 T301 C80 P32793 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 61219 T301 C80 P32793 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 61219 T301 C80 P32793 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 61222 T243 C81 P50964 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 61223 T301 C80 P32793 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 61224 T301 C80 P32793 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty4/index.20130624225936768
[junit4:junit4] 2> 61225 T301 C80 P32793 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty4/index.20130624225936768 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d94a7ec fullCopy=false
[junit4:junit4] 2> 61232 T245 C81 P50964 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=2
[junit4:junit4] 2> 61239 T301 C80 P32793 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 61248 T301 C80 P32793 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 61249 T301 C80 P32793 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 61253 T301 C80 P32793 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty4/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 61254 T301 C80 P32793 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 61254 T301 C80 P32793 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 61255 T301 C80 P32793 oass.SolrIndexSearcher.<init> Opening Searcher@6ff58334 main
[junit4:junit4] 2> 61256 T300 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6ff58334 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 61257 T301 C80 P32793 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty4/index.20130624225936768 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty4/index.20130624225936768;done=true>>]
[junit4:junit4] 2> 61257 T301 C80 P32793 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty4/index.20130624225936768
[junit4:junit4] 2> 61257 T301 C80 P32793 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty4/index.20130624225936768
[junit4:junit4] 2> 61261 T301 C80 P32793 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 61262 T301 C80 P32793 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 61262 T301 C80 P32793 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 61262 T301 C80 P32793 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 61264 T301 C80 P32793 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 61390 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 61391 T231 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50497__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:50497_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50497"}
[junit4:junit4] 2> 61395 T231 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:32793__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:32793_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:32793"}
[junit4:junit4] 2> 61417 T250 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> 61418 T266 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> 61417 T315 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> 61417 T237 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> 61417 T332 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> 61418 T282 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> 61418 T230 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> 61418 T298 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> 61931 T262 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:50497__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 61932 T262 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:50497__collection1&state=recovering&nodeName=127.0.0.1:50497_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 62122 T208 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58541_
[junit4:junit4] 2> 62123 T208 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58541_
[junit4:junit4] 2> 62125 T237 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> 62126 T230 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> 62125 T332 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> 62127 T250 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 62127 T282 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> 62127 T315 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 62128 T250 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> 62128 T315 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> 62129 T298 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 62129 T298 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> 62129 T266 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 62130 T266 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> 62132 T237 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 62132 T332 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 62133 T230 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 62135 T282 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 62140 T335 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 62140 T335 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 62932 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 62934 T231 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:58541_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58541"}
[junit4:junit4] 2> 62934 T231 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 62934 T231 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 62941 T237 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> 62941 T298 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> 62941 T266 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> 62941 T230 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> 62941 T282 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> 62941 T315 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> 62941 T332 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> 62941 T250 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> 63142 T335 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372129176470/collection1
[junit4:junit4] 2> 63142 T335 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 63144 T335 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 63144 T335 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 63146 T335 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372129176470/collection1/'
[junit4:junit4] 2> 63147 T335 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372129176470/collection1/lib/README' to classloader
[junit4:junit4] 2> 63147 T335 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372129176470/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 63197 T335 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 63228 T335 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 63230 T335 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 63235 T335 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 63662 T335 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 63662 T335 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 63663 T335 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 63669 T335 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 63672 T335 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 63691 T335 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 63695 T335 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 63699 T335 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 63700 T335 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 63701 T335 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 63701 T335 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 63702 T335 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 63703 T335 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 63703 T335 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 63703 T335 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372129176470/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty6/
[junit4:junit4] 2> 63703 T335 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@47875da7
[junit4:junit4] 2> 63704 T335 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 63704 T335 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty6
[junit4:junit4] 2> 63705 T335 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty6/index/
[junit4:junit4] 2> 63705 T335 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty6/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 63705 T335 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty6/index
[junit4:junit4] 2> 63708 T335 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 63708 T335 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 63710 T335 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 63711 T335 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 63711 T335 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 63712 T335 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 63712 T335 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 63713 T335 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 63713 T335 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 63714 T335 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 63714 T335 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 63722 T335 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 63725 T335 oass.SolrIndexSearcher.<init> Opening Searcher@e55bf9c main
[junit4:junit4] 2> 63726 T335 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 63726 T335 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 63731 T336 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e55bf9c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 63733 T335 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 63734 T335 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58541 collection:collection1 shard:shard3
[junit4:junit4] 2> 63737 T335 oasc.ZkController.register We are http://127.0.0.1:58541/collection1/ and leader is http://127.0.0.1:50043/collection1/
[junit4:junit4] 2> 63738 T335 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58541
[junit4:junit4] 2> 63738 T335 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 63738 T335 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C82 name=collection1 org.apache.solr.core.SolrCore@6aaea944 url=http://127.0.0.1:58541/collection1 node=127.0.0.1:58541_ C82_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:58541_, base_url=http://127.0.0.1:58541}
[junit4:junit4] 2> 63739 T337 C82 P58541 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 63739 T335 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 63739 T337 C82 P58541 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 63740 T337 C82 P58541 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 63740 T337 C82 P58541 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 63741 T208 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 63742 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 63741 T337 C82 P58541 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 63742 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 63747 T275 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:58541__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 63823 T208 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 63825 T208 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58041
[junit4:junit4] 2> 63826 T208 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 63826 T208 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 63827 T208 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372129179290
[junit4:junit4] 2> 63827 T208 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372129179290/solr.xml
[junit4:junit4] 2> 63827 T208 oasc.CoreContainer.<init> New CoreContainer 1924868815
[junit4:junit4] 2> 63828 T208 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372129179290/'
[junit4:junit4] 2> 63828 T208 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372129179290/'
[junit4:junit4] 2> 63876 T208 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 63877 T208 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 63877 T208 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 63878 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 63878 T208 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 63878 T208 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 63879 T208 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 63879 T208 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 63879 T208 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 63880 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 63883 T208 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 63884 T208 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42996/solr
[junit4:junit4] 2> 63884 T208 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 63885 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 63887 T349 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12146018 name:ZooKeeperConnection Watcher:127.0.0.1:42996 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 63888 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 63890 T208 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 63895 T208 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 63896 T351 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@39a44220 name:ZooKeeperConnection Watcher:127.0.0.1:42996/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 63896 T208 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 63901 T208 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C83 name=collection1 org.apache.solr.core.SolrCore@3a028fb7 url=http://127.0.0.1:50497/collection1 node=127.0.0.1:50497_ C83_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:50497_, base_url=http://127.0.0.1:50497}
[junit4:junit4] 2> 63933 T318 C83 P50497 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:57963/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 63933 T318 C83 P50497 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50497 START replicas=[http://127.0.0.1:57963/collection1/] nUpdates=100
[junit4:junit4] 2> 63934 T318 C83 P50497 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 63934 T318 C83 P50497 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 63934 T318 C83 P50497 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 63935 T318 C83 P50497 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 63935 T318 C83 P50497 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 63937 T318 C83 P50497 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:57963/collection1/. core=collection1
[junit4:junit4] 2> 63937 T318 C83 P50497 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C84 name=collection1 org.apache.solr.core.SolrCore@20ab085 url=http://127.0.0.1:57963/collection1 node=127.0.0.1:57963_ C84_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57963_, base_url=http://127.0.0.1:57963, leader=true}
[junit4:junit4] 2> 63945 T261 C84 P57963 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 63947 T260 C84 P57963 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 63950 T260 C84 P57963 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 63951 T260 C84 P57963 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 63957 T260 C84 P57963 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 63957 T260 C84 P57963 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 63959 T260 C84 P57963 oass.SolrIndexSearcher.<init> Opening Searcher@4200e87e realtime
[junit4:junit4] 2> 63959 T260 C84 P57963 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 63960 T260 C84 P57963 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 13
[junit4:junit4] 2> 63961 T318 C83 P50497 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 63961 T318 C83 P50497 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 63963 T261 C84 P57963 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 63964 T261 C84 P57963 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 63965 T318 C83 P50497 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 63965 T318 C83 P50497 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 63965 T318 C83 P50497 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 63967 T260 C84 P57963 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 63968 T318 C83 P50497 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 63969 T318 C83 P50497 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty5/index.20130624225939513
[junit4:junit4] 2> 63970 T318 C83 P50497 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty5/index.20130624225939513 lockFactory=org.apache.lucene.store.NativeFSLockFactory@56554acb fullCopy=false
[junit4:junit4] 2> 63972 T262 C84 P57963 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 63974 T318 C83 P50497 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 63987 T318 C83 P50497 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 63988 T318 C83 P50497 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 63990 T318 C83 P50497 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty5/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 63991 T318 C83 P50497 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 63991 T318 C83 P50497 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 63992 T318 C83 P50497 oass.SolrIndexSearcher.<init> Opening Searcher@65052f49 main
[junit4:junit4] 2> 63993 T317 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@65052f49 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 63994 T318 C83 P50497 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty5/index.20130624225939513 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty5/index.20130624225939513;done=true>>]
[junit4:junit4] 2> 63994 T318 C83 P50497 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty5/index.20130624225939513
[junit4:junit4] 2> 63995 T318 C83 P50497 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty5/index.20130624225939513
[junit4:junit4] 2> 63995 T318 C83 P50497 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 63995 T318 C83 P50497 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 63995 T318 C83 P50497 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 63996 T318 C83 P50497 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 63998 T318 C83 P50497 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 64450 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 64451 T231 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58541__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:58541_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58541"}
[junit4:junit4] 2> 64457 T231 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50497__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:50497_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50497"}
[junit4:junit4] 2> 64487 T250 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> 64488 T351 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> 64488 T237 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> 64488 T315 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> 64488 T298 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> 64487 T332 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> 64487 T266 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> 64489 T230 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> 64489 T282 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> 64747 T275 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:58541__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 64748 T275 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:58541__collection1&state=recovering&nodeName=127.0.0.1:58541_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 64906 T208 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58041_
[junit4:junit4] 2> 64908 T208 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58041_
[junit4:junit4] 2> 64911 T237 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> 64911 T332 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> 64911 T230 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> 64911 T282 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> 64912 T250 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 64912 T266 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 64913 T266 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> 64913 T351 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 64913 T351 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> 64912 T315 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 64914 T315 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> 64912 T298 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 64912 T250 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> 64916 T230 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 64915 T298 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> 64916 T237 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 64917 T282 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 64916 T332 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 64926 T354 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 64926 T354 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 66002 T231 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 66003 T231 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:58041_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58041"}
[junit4:junit4] 2> 66004 T231 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 66004 T231 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 66010 T230 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> 66010 T266 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> 66010 T282 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> 66010 T298 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> 66010 T315 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> 66010 T351 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> 66010 T237 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> 66010 T332 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> 66010 T250 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> ASYNC NEW_CORE C85 name=collection1 org.apache.solr.core.SolrCore@6aaea944 url=http://127.0.0.1:58541/collection1 node=127.0.0.1:58541_ C85_STATE=coll:collection1 core:collection1 props:{shard=shard3, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:58541_, base_url=http://127.0.0.1:58541}
[junit4:junit4] 2> 66749 T337 C85 P58541 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50043/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 66750 T337 C85 P58541 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58541 START replicas=[http://127.0.0.1:50043/collection1/] nUpdates=100
[junit4:junit4] 2> 66750 T337 C85 P58541 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 66751 T337 C85 P58541 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 66751 T337 C85 P58541 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 66752 T337 C85 P58541 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 66752 T337 C85 P58541 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 66759 T337 C85 P58541 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50043/collection1/. core=collection1
[junit4:junit4] 2> 66759 T337 C85 P58541 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C86 name=collection1 org.apache.solr.core.SolrCore@224b44f0 url=http://127.0.0.1:50043/collection1 node=127.0.0.1:50043_ C86_STATE=coll:collection1 core:collection1 props:{shard=shard3, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50043_, base_url=http://127.0.0.1:50043, leader=true}
[junit4:junit4] 2> 66766 T278 C86 P50043 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 66767 T275 C86 P50043 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 66770 T275 C86 P50043 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 66770 T275 C86 P50043 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 66777 T275 C86 P50043 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty3/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 66777 T275 C86 P50043 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 66778 T275 C86 P50043 oass.SolrIndexSearcher.<init> Opening Searcher@21bdfbf6 realtime
[junit4:junit4] 2> 66778 T275 C86 P50043 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 66779 T275 C86 P50043 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 12
[junit4:junit4] 2> 66780 T337 C85 P58541 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 66780 T337 C85 P58541 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 66782 T278 C86 P50043 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 66783 T278 C86 P50043 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 66783 T337 C85 P58541 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 66784 T337 C85 P58541 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 66784 T337 C85 P58541 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 66787 T277 C86 P50043 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 66787 T337 C85 P58541 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 66788 T337 C85 P58541 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty6/index.20130624225942332
[junit4:junit4] 2> 66788 T337 C85 P58541 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty6/index.20130624225942332 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b68dbcd fullCopy=false
[junit4:junit4] 2> 66791 T275 C86 P50043 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 66793 T337 C85 P58541 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 66797 T337 C85 P58541 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 66798 T337 C85 P58541 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 66799 T337 C85 P58541 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty6/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 66800 T337 C85 P58541 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 66800 T337 C85 P58541 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 66801 T337 C85 P58541 oass.SolrIndexSearcher.<init> Opening Searcher@101b085 main
[junit4:junit4] 2> 66802 T336 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@101b085 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 66802 T337 C85 P58541 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty6/index.20130624225942332 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty6/index.20130624225942332;done=true>>]
[junit4:junit4] 2> 66802 T337 C85 P58541 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty6/index.20130624225942332
[junit4:junit4] 2> 66803 T337 C85 P58541 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty6/index.20130624225942332
[junit4:junit4] 2> 66803 T337 C85 P58541 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 66803 T337 C85 P58541 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 66803 T337 C85 P58541 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 66804 T337 C85 P58541 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 66806 T337 C85 P58541 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 66928 T354 oasc.CoreContainer.create Creating SolrCor
[...truncated too long message...]
.1:43121_-n_0000000010) am no longer a leader.
[junit4:junit4] 2> 190560 T448 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> 190561 T448 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4:junit4] 2> 190562 T448 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 190564 T448 oasc.Overseer.start Overseer (id=89923856487677980-127.0.0.1:46368_-n_0000000012) starting
[junit4:junit4] 2> 190567 T708 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 190576 T707 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 190579 T707 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 190580 T707 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:43121__collection1",
[junit4:junit4] 2> "numShards":null,
[junit4:junit4] 2> "shard":"shard1",
[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:43121_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43121"}
[junit4:junit4] 2> 190583 T448 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> 190587 T208 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 190638 T208 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 48519
[junit4:junit4] 2> 190639 T208 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 46368
[junit4:junit4] 2> 190639 T208 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=528524735
[junit4:junit4] 2> 190770 T531 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 190770 T531 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> 190770 T531 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 191641 T208 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 191641 T208 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 191643 T208 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@1f7e6153
[junit4:junit4] 2> 191644 T208 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=78,cumulative_deletesById=35,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 191645 T208 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 191645 T208 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 191646 T208 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 191647 T208 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 191647 T208 oasc.CachingDirectoryFactory.close Closing StandardDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 191648 T208 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty12/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty12/index;done=false>>]
[junit4:junit4] 2> 191648 T208 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty12/index
[junit4:junit4] 2> 191648 T208 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty12 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty12;done=false>>]
[junit4:junit4] 2> 191649 T208 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372129157758/jetty12
[junit4:junit4] 2> 191649 T707 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89923856487677980-127.0.0.1:46368_-n_0000000012) am no longer a leader.
[junit4:junit4] 2> 191650 T448 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> 191651 T448 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 191651 T448 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 191672 T208 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 191745 T208 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 191747 T208 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:42996 42996
[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=5DFD305AA549EAB5 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_TN -Dtests.timezone=Brazil/West -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] FAILURE 150s J1 | ChaosMonkeySafeLeaderTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard3 is not consistent. Got 45 from http://127.0.0.1:43327/collection1lastClient and got 43 from http://127.0.0.1:46368/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([5DFD305AA549EAB5:DC1BBE42D2168A89]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:662)
[junit4:junit4] 2> 191788 T208 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 149590 T207 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> 191860 T410 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 191860 T410 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> 191861 T410 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene40, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=ar_TN, timezone=Brazil/West
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic amd64/Sun Microsystems Inc. 1.6.0_45 (64-bit)/cpus=8,threads=1,free=60085088,total=126484480
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TermVectorComponentDistributedTest, TestJmxIntegration, TestAnalyzedSuggestions, MultiTermTest, HardAutoCommitTest, TestRecovery, JSONWriterTest, TestDynamicFieldCollectionResource, HighlighterConfigTest, ChaosMonkeySafeLeaderTest]
[junit4:junit4] Completed on J1 in 150.37s, 1 test, 1 failure <<< FAILURES!
[...truncated 821 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:392: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:372: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1246: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:890: There were test failures: 298 suites, 1256 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 38 minutes 15 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.6.0_45 -XX:+UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure