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/24 11:09:37 UTC
[JENKINS] Lucene-Solr-4.x-MacOSX (64bit/jdk1.7.0) - Build # 574 -
Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-MacOSX/574/
Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseSerialGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.testDistribSearch
Error Message:
shard3 is not consistent. Got 46 from http://127.0.0.1:52226/collection1lastClient and got 41 from http://127.0.0.1:52241/collection1
Stack Trace:
java.lang.AssertionError: shard3 is not consistent. Got 46 from http://127.0.0.1:52226/collection1lastClient and got 41 from http://127.0.0.1:52241/collection1
at __randomizedtesting.SeedInfo.seed([1DA144D5B259798E:9C47CACDC50619B2]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Build Log:
[...truncated 9742 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
[junit4:junit4] 2> 1533880 T3194 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 1533923 T3194 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./solrtest-ChaosMonkeySafeLeaderTest-1372063157178
[junit4:junit4] 2> 1533925 T3194 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1533928 T3195 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1533940 T3194 oasc.ZkTestServer.run start zk server on port:52179
[junit4:junit4] 2> 1533943 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1533971 T3196 oazs.NIOServerCnxn.doIO WARN Exception causing close of session 0x0 due to java.io.IOException: ZooKeeperServer not running
[junit4:junit4] 2> 1536336 T3198 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@25644f52 name:ZooKeeperConnection Watcher:127.0.0.1:52179 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1536337 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1536337 T3194 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1537080 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1537081 T3203 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@21d7db58 name:ZooKeeperConnection Watcher:127.0.0.1:52179/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1537081 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1537081 T3194 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1537089 T3194 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1537096 T3194 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1537101 T3194 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1537109 T3194 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1537110 T3194 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1537125 T3194 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 1537126 T3194 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1537133 T3194 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1537134 T3194 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1537143 T3194 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 1537144 T3194 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1537151 T3194 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 1537152 T3194 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1537159 T3194 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1537160 T3194 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1537167 T3194 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1537168 T3194 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1537176 T3194 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1537176 T3194 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1537188 T3194 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1537190 T3194 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1537648 T3194 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1537655 T3194 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52183
[junit4:junit4] 2> 1537656 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1537657 T3194 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1537657 T3194 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372063160453
[junit4:junit4] 2> 1537658 T3194 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372063160453/solr.xml
[junit4:junit4] 2> 1537659 T3194 oasc.CoreContainer.<init> New CoreContainer 1963801566
[junit4:junit4] 2> 1537659 T3194 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372063160453/'
[junit4:junit4] 2> 1537667 T3194 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372063160453/'
[junit4:junit4] 2> 1537839 T3194 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1537839 T3194 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1537840 T3194 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1537840 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1537841 T3194 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1537841 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1537843 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1537843 T3194 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1537843 T3194 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1537844 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1537868 T3194 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1537869 T3194 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52179/solr
[junit4:junit4] 2> 1537870 T3194 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1537871 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1537877 T3214 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4c0e4abc name:ZooKeeperConnection Watcher:127.0.0.1:52179 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1537877 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1537881 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1537897 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1537899 T3216 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2a2ee55c name:ZooKeeperConnection Watcher:127.0.0.1:52179/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1537900 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1537903 T3194 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1537912 T3194 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1537924 T3194 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1537930 T3194 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52183_
[junit4:junit4] 2> 1537932 T3194 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52183_
[junit4:junit4] 2> 1537942 T3194 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1537955 T3194 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1537962 T3194 oasc.Overseer.start Overseer (id=89919531070586883-127.0.0.1:52183_-n_0000000000) starting
[junit4:junit4] 2> 1537971 T3194 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1537989 T3218 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1537991 T3217 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1537994 T3194 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1538003 T3194 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1538009 T3194 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1538023 T3219 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1538024 T3219 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1539532 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1539533 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[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:52183_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52183"}
[junit4:junit4] 2> 1539534 T3217 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1539534 T3217 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1539546 T3216 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> 1540030 T3219 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372063160453/collection1
[junit4:junit4] 2> 1540030 T3219 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1540032 T3219 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1540032 T3219 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1540038 T3219 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372063160453/collection1/'
[junit4:junit4] 2> 1540042 T3219 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372063160453/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1540045 T3219 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372063160453/collection1/lib/README' to classloader
[junit4:junit4] 2> 1540121 T3219 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1540200 T3219 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1540204 T3219 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1540229 T3219 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1541144 T3219 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1541145 T3219 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1541146 T3219 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1541163 T3219 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1541168 T3219 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1541204 T3219 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1541212 T3219 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1541221 T3219 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1541229 T3219 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1541230 T3219 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1541230 T3219 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1541233 T3219 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1541233 T3219 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1541234 T3219 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1541270 T3219 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372063160453/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/control/data/
[junit4:junit4] 2> 1541270 T3219 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a983bcc
[junit4:junit4] 2> 1541271 T3219 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1541272 T3219 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/control/data
[junit4:junit4] 2> 1541273 T3219 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/control/data/index/
[junit4:junit4] 2> 1541273 T3219 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1541274 T3219 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/control/data/index
[junit4:junit4] 2> 1541281 T3219 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1541282 T3219 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1541286 T3219 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1541287 T3219 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1541288 T3219 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1541289 T3219 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1541290 T3219 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1541290 T3219 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1541292 T3219 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1541297 T3219 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1541298 T3219 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1541313 T3219 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1541325 T3219 oass.SolrIndexSearcher.<init> Opening Searcher@4e312d0c main
[junit4:junit4] 2> 1541327 T3219 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1541327 T3219 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1541333 T3220 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4e312d0c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1541365 T3219 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1541367 T3219 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52183 collection:control_collection shard:shard1
[junit4:junit4] 2> 1541369 T3219 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1541388 T3219 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1541395 T3219 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1541395 T3219 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1541395 T3219 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52183/collection1/
[junit4:junit4] 2> 1541396 T3219 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1541396 T3219 oasc.SyncStrategy.syncToMe http://127.0.0.1:52183/collection1/ has no replicas
[junit4:junit4] 2> 1541396 T3219 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52183/collection1/
[junit4:junit4] 2> 1541397 T3219 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1542611 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1542632 T3216 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> 1542655 T3219 oasc.ZkController.register We are http://127.0.0.1:52183/collection1/ and leader is http://127.0.0.1:52183/collection1/
[junit4:junit4] 2> 1542655 T3219 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52183
[junit4:junit4] 2> 1542656 T3219 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1542656 T3219 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1542656 T3219 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1542660 T3219 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1542669 T3194 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1542669 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1542670 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1542692 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1542697 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1542701 T3223 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4e650eed name:ZooKeeperConnection Watcher:127.0.0.1:52179/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1542701 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1542704 T3194 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1542712 T3194 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1543170 T3194 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1543178 T3194 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52187
[junit4:junit4] 2> 1543179 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1543180 T3194 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1543180 T3194 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372063165966
[junit4:junit4] 2> 1543181 T3194 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372063165966/solr.xml
[junit4:junit4] 2> 1543181 T3194 oasc.CoreContainer.<init> New CoreContainer 1094514073
[junit4:junit4] 2> 1543182 T3194 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372063165966/'
[junit4:junit4] 2> 1543182 T3194 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372063165966/'
[junit4:junit4] 2> 1543363 T3194 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1543364 T3194 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1543364 T3194 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1543365 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1543365 T3194 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1543366 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1543366 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1543367 T3194 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1543367 T3194 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1543368 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1543388 T3194 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1543389 T3194 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52179/solr
[junit4:junit4] 2> 1543390 T3194 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1543392 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1543404 T3234 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@44b438bf name:ZooKeeperConnection Watcher:127.0.0.1:52179 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1543405 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1543409 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1543424 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1543429 T3236 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@56763802 name:ZooKeeperConnection Watcher:127.0.0.1:52179/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1543429 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1543441 T3194 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1544149 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1544151 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[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:52183_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52183"}
[junit4:junit4] 2> 1544161 T3236 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> 1544162 T3223 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> 1544164 T3216 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> 1544451 T3194 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52187_
[junit4:junit4] 2> 1544453 T3194 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52187_
[junit4:junit4] 2> 1544468 T3216 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1544468 T3216 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> 1544469 T3236 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1544469 T3236 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> 1544469 T3223 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1544470 T3223 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> 1544490 T3237 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1544491 T3237 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1545684 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1545685 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[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:52187_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52187"}
[junit4:junit4] 2> 1545686 T3217 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 3
[junit4:junit4] 2> 1545686 T3217 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1545697 T3236 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> 1545697 T3216 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> 1545697 T3223 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> 1546503 T3237 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372063165966/collection1
[junit4:junit4] 2> 1546504 T3237 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1546505 T3237 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1546506 T3237 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1546509 T3237 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372063165966/collection1/'
[junit4:junit4] 2> 1546510 T3237 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372063165966/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1546511 T3237 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372063165966/collection1/lib/README' to classloader
[junit4:junit4] 2> 1546582 T3237 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1546685 T3237 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1546689 T3237 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1546696 T3237 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1547554 T3237 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1547555 T3237 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1547556 T3237 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1547566 T3237 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1547570 T3237 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1547604 T3237 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1547612 T3237 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1547623 T3237 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1547627 T3237 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1547628 T3237 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1547628 T3237 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1547631 T3237 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1547631 T3237 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1547631 T3237 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1547632 T3237 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372063165966/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty1/
[junit4:junit4] 2> 1547632 T3237 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a983bcc
[junit4:junit4] 2> 1547633 T3237 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1547634 T3237 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty1
[junit4:junit4] 2> 1547634 T3237 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty1/index/
[junit4:junit4] 2> 1547635 T3237 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1547636 T3237 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty1/index
[junit4:junit4] 2> 1547642 T3237 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1547642 T3237 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1547646 T3237 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1547647 T3237 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1547648 T3237 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1547649 T3237 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1547650 T3237 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1547650 T3237 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1547651 T3237 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1547652 T3237 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1547652 T3237 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1547667 T3237 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1547676 T3237 oass.SolrIndexSearcher.<init> Opening Searcher@496fd1ee main
[junit4:junit4] 2> 1547682 T3237 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1547682 T3237 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1547689 T3238 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@496fd1ee main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1547691 T3237 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1547691 T3237 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52187 collection:collection1 shard:shard1
[junit4:junit4] 2> 1547693 T3237 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1547710 T3237 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1547716 T3237 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1547716 T3237 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1547717 T3237 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52187/collection1/
[junit4:junit4] 2> 1547717 T3237 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1547717 T3237 oasc.SyncStrategy.syncToMe http://127.0.0.1:52187/collection1/ has no replicas
[junit4:junit4] 2> 1547717 T3237 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52187/collection1/
[junit4:junit4] 2> 1547718 T3237 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1548730 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1548755 T3236 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> 1548755 T3216 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> 1548756 T3223 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> 1548808 T3237 oasc.ZkController.register We are http://127.0.0.1:52187/collection1/ and leader is http://127.0.0.1:52187/collection1/
[junit4:junit4] 2> 1548811 T3237 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52187
[junit4:junit4] 2> 1548812 T3237 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1548813 T3237 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1548814 T3237 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1548820 T3237 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1548825 T3194 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1548826 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1548826 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1549298 T3194 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1549303 T3194 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52190
[junit4:junit4] 2> 1549305 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1549306 T3194 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1549306 T3194 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372063172101
[junit4:junit4] 2> 1549307 T3194 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372063172101/solr.xml
[junit4:junit4] 2> 1549307 T3194 oasc.CoreContainer.<init> New CoreContainer 67530455
[junit4:junit4] 2> 1549308 T3194 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372063172101/'
[junit4:junit4] 2> 1549309 T3194 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372063172101/'
[junit4:junit4] 2> 1549494 T3194 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1549495 T3194 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1549495 T3194 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1549496 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1549496 T3194 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1549497 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1549497 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1549498 T3194 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1549498 T3194 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1549499 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1549516 T3194 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1549516 T3194 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52179/solr
[junit4:junit4] 2> 1549517 T3194 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1549518 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1549523 T3250 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f9d02fb name:ZooKeeperConnection Watcher:127.0.0.1:52179 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1549525 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1549529 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1549531 T3196 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f75564bd50007, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 1549548 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1549552 T3252 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@243ba813 name:ZooKeeperConnection Watcher:127.0.0.1:52179/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1549552 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1549563 T3194 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1550277 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1550279 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[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:52187_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52187"}
[junit4:junit4] 2> 1550289 T3216 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> 1550294 T3223 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> 1550294 T3252 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> 1550295 T3236 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> 1550572 T3194 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52190_
[junit4:junit4] 2> 1550574 T3194 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52190_
[junit4:junit4] 2> 1550579 T3252 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1550580 T3252 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> 1550580 T3223 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1550580 T3223 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> 1550584 T3216 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1550584 T3216 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> 1550589 T3236 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1550590 T3236 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> 1550608 T3253 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1550609 T3253 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1551810 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1551812 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[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:52190_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52190"}
[junit4:junit4] 2> 1551813 T3217 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 1551813 T3217 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1551822 T3252 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> 1551823 T3223 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> 1551826 T3216 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> 1551827 T3236 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> 1552614 T3253 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372063172101/collection1
[junit4:junit4] 2> 1552614 T3253 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1552617 T3253 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1552618 T3253 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1552622 T3253 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372063172101/collection1/'
[junit4:junit4] 2> 1552624 T3253 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372063172101/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1552624 T3253 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372063172101/collection1/lib/README' to classloader
[junit4:junit4] 2> 1552687 T3253 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1552794 T3253 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1552800 T3253 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1552807 T3253 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1553691 T3253 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1553692 T3253 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1553694 T3253 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1553706 T3253 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1553715 T3253 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1553753 T3253 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1553761 T3253 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1553767 T3253 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1553770 T3253 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1553770 T3253 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1553771 T3253 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1553777 T3253 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1553779 T3253 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1553779 T3253 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1553780 T3253 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372063172101/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty2/
[junit4:junit4] 2> 1553780 T3253 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a983bcc
[junit4:junit4] 2> 1553781 T3253 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1553782 T3253 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty2
[junit4:junit4] 2> 1553783 T3253 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty2/index/
[junit4:junit4] 2> 1553784 T3253 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1553785 T3253 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty2/index
[junit4:junit4] 2> 1553792 T3253 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1553792 T3253 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1553796 T3253 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1553796 T3253 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1553799 T3253 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1553800 T3253 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1553800 T3253 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1553800 T3253 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1553801 T3253 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1553802 T3253 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1553802 T3253 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1553815 T3253 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1553825 T3253 oass.SolrIndexSearcher.<init> Opening Searcher@327a42f3 main
[junit4:junit4] 2> 1553826 T3253 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1553827 T3253 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1553834 T3254 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@327a42f3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1553838 T3253 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1553839 T3253 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52190 collection:collection1 shard:shard2
[junit4:junit4] 2> 1553841 T3253 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 1553864 T3253 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1553870 T3253 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1553870 T3253 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1553871 T3253 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52190/collection1/
[junit4:junit4] 2> 1553871 T3253 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1553871 T3253 oasc.SyncStrategy.syncToMe http://127.0.0.1:52190/collection1/ has no replicas
[junit4:junit4] 2> 1553872 T3253 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52190/collection1/
[junit4:junit4] 2> 1553872 T3253 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1554846 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1554866 T3252 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> 1554866 T3223 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> 1554870 T3216 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> 1554875 T3236 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> 1554888 T3253 oasc.ZkController.register We are http://127.0.0.1:52190/collection1/ and leader is http://127.0.0.1:52190/collection1/
[junit4:junit4] 2> 1554889 T3253 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52190
[junit4:junit4] 2> 1554889 T3253 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1554890 T3253 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1554890 T3253 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1554895 T3253 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1554897 T3194 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1554898 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1554899 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1555387 T3194 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1555395 T3194 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52193
[junit4:junit4] 2> 1555397 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1555397 T3194 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1555398 T3194 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372063178172
[junit4:junit4] 2> 1555398 T3194 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372063178172/solr.xml
[junit4:junit4] 2> 1555399 T3194 oasc.CoreContainer.<init> New CoreContainer 315481429
[junit4:junit4] 2> 1555399 T3194 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372063178172/'
[junit4:junit4] 2> 1555400 T3194 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372063178172/'
[junit4:junit4] 2> 1555586 T3194 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1555586 T3194 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1555587 T3194 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1555587 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1555588 T3194 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1555588 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1555589 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1555589 T3194 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1555590 T3194 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1555590 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1555614 T3194 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1555615 T3194 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52179/solr
[junit4:junit4] 2> 1555615 T3194 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1555617 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1555621 T3266 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6523046b name:ZooKeeperConnection Watcher:127.0.0.1:52179 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1555624 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1555630 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1555647 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1555653 T3268 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5a6569cf name:ZooKeeperConnection Watcher:127.0.0.1:52179/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1555653 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1555666 T3194 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1556393 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1556395 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[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:52190_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52190"}
[junit4:junit4] 2> 1556413 T3236 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> 1556413 T3268 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> 1556421 T3216 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> 1556425 T3252 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> 1556426 T3223 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> 1556677 T3194 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52193_
[junit4:junit4] 2> 1556680 T3194 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52193_
[junit4:junit4] 2> 1556687 T3268 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> 1556691 T3252 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1556691 T3252 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> 1556692 T3236 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1556692 T3236 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> 1556698 T3268 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1556709 T3269 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1556710 T3269 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1556718 T3216 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1556718 T3216 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> 1556720 T3223 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1556720 T3223 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> 1557945 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1557950 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:52193_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52193"}
[junit4:junit4] 2> 1557950 T3217 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 1557951 T3217 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 1557960 T3252 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> 1557960 T3236 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> 1557961 T3216 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> 1557963 T3268 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> 1557976 T3223 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> 1558727 T3269 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372063178172/collection1
[junit4:junit4] 2> 1558727 T3269 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1558729 T3269 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1558729 T3269 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1558733 T3269 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372063178172/collection1/'
[junit4:junit4] 2> 1558734 T3269 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372063178172/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1558735 T3269 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372063178172/collection1/lib/README' to classloader
[junit4:junit4] 2> 1558811 T3269 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1558908 T3269 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1558916 T3269 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1558922 T3269 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1559813 T3269 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1559814 T3269 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1559815 T3269 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1559830 T3269 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1559836 T3269 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1559881 T3269 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1559891 T3269 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1559898 T3269 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1559901 T3269 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1559901 T3269 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1559902 T3269 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1559906 T3269 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1559906 T3269 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1559906 T3269 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1559907 T3269 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372063178172/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty3/
[junit4:junit4] 2> 1559907 T3269 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a983bcc
[junit4:junit4] 2> 1559908 T3269 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1559909 T3269 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty3
[junit4:junit4] 2> 1559910 T3269 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty3/index/
[junit4:junit4] 2> 1559911 T3269 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1559912 T3269 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty3/index
[junit4:junit4] 2> 1559920 T3269 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1559920 T3269 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1559929 T3269 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1559930 T3269 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1559931 T3269 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1559932 T3269 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1559933 T3269 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1559933 T3269 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1559934 T3269 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1559935 T3269 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1559935 T3269 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1559954 T3269 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1559965 T3269 oass.SolrIndexSearcher.<init> Opening Searcher@7378a5f3 main
[junit4:junit4] 2> 1559967 T3269 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1559967 T3269 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1559983 T3270 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7378a5f3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1559986 T3269 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1559986 T3269 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52193 collection:collection1 shard:shard3
[junit4:junit4] 2> 1559988 T3269 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4:junit4] 2> 1560006 T3269 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1560015 T3269 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1560015 T3269 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1560016 T3269 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52193/collection1/
[junit4:junit4] 2> 1560016 T3269 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1560016 T3269 oasc.SyncStrategy.syncToMe http://127.0.0.1:52193/collection1/ has no replicas
[junit4:junit4] 2> 1560017 T3269 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52193/collection1/
[junit4:junit4] 2> 1560017 T3269 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4:junit4] 2> 1561026 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1561053 T3252 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> 1561055 T3223 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> 1561055 T3236 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> 1561055 T3216 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> 1561056 T3268 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> 1561087 T3269 oasc.ZkController.register We are http://127.0.0.1:52193/collection1/ and leader is http://127.0.0.1:52193/collection1/
[junit4:junit4] 2> 1561088 T3269 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52193
[junit4:junit4] 2> 1561088 T3269 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1561088 T3269 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1561088 T3269 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1561091 T3269 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1561093 T3194 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1561093 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1561094 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1561805 T3194 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1561812 T3194 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52196
[junit4:junit4] 2> 1561813 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1561814 T3194 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1561815 T3194 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372063184370
[junit4:junit4] 2> 1561816 T3194 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372063184370/solr.xml
[junit4:junit4] 2> 1561816 T3194 oasc.CoreContainer.<init> New CoreContainer 1352924865
[junit4:junit4] 2> 1561817 T3194 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372063184370/'
[junit4:junit4] 2> 1561817 T3194 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372063184370/'
[junit4:junit4] 2> 1561992 T3194 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1561993 T3194 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1561994 T3194 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1561994 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1561995 T3194 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1561995 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1561996 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1561996 T3194 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1561997 T3194 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1561997 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1562020 T3194 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1562021 T3194 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52179/solr
[junit4:junit4] 2> 1562021 T3194 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1562023 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1562029 T3282 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@dec883a name:ZooKeeperConnection Watcher:127.0.0.1:52179 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1562031 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1562035 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1562052 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1562061 T3284 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9a653d7 name:ZooKeeperConnection Watcher:127.0.0.1:52179/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1562061 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1562073 T3194 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1562583 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1562588 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:52193_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52193"}
[junit4:junit4] 2> 1562601 T3216 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> 1562602 T3236 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> 1562602 T3223 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> 1562603 T3268 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> 1562605 T3252 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> 1562605 T3284 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> 1563090 T3194 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52196_
[junit4:junit4] 2> 1563093 T3194 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52196_
[junit4:junit4] 2> 1563100 T3268 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> 1563103 T3284 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1563103 T3284 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> 1563109 T3268 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1563120 T3216 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1563121 T3216 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> 1563121 T3252 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1563121 T3252 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> 1563121 T3223 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1563122 T3236 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1563122 T3236 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> 1563122 T3223 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> 1563134 T3285 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1563134 T3285 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1564128 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1564131 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:52196_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52196"}
[junit4:junit4] 2> 1564131 T3217 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 1564131 T3217 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1564140 T3236 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> 1564140 T3268 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> 1564145 T3216 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> 1564151 T3252 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> 1564151 T3223 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> 1564151 T3284 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> 1565140 T3285 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372063184370/collection1
[junit4:junit4] 2> 1565145 T3285 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1565148 T3285 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1565148 T3285 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1565152 T3285 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372063184370/collection1/'
[junit4:junit4] 2> 1565153 T3285 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372063184370/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1565153 T3285 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372063184370/collection1/lib/README' to classloader
[junit4:junit4] 2> 1565221 T3285 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1565328 T3285 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1565334 T3285 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1565342 T3285 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1566245 T3285 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1566247 T3285 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1566248 T3285 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1566259 T3285 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1566265 T3285 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1566305 T3285 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1566311 T3285 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1566317 T3285 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1566320 T3285 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1566320 T3285 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1566320 T3285 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1566323 T3285 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1566324 T3285 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1566324 T3285 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1566324 T3285 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372063184370/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty4/
[junit4:junit4] 2> 1566325 T3285 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a983bcc
[junit4:junit4] 2> 1566325 T3285 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1566326 T3285 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty4
[junit4:junit4] 2> 1566327 T3285 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty4/index/
[junit4:junit4] 2> 1566327 T3285 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1566328 T3285 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty4/index
[junit4:junit4] 2> 1566334 T3285 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1566334 T3285 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1566344 T3285 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1566344 T3285 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1566345 T3285 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1566346 T3285 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1566347 T3285 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1566347 T3285 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1566348 T3285 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1566349 T3285 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1566349 T3285 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1566364 T3285 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1566374 T3285 oass.SolrIndexSearcher.<init> Opening Searcher@237029dd main
[junit4:junit4] 2> 1566375 T3285 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1566376 T3285 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1566381 T3286 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@237029dd main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1566385 T3285 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1566385 T3285 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52196 collection:collection1 shard:shard1
[junit4:junit4] 2> 1566393 T3285 oasc.ZkController.register We are http://127.0.0.1:52196/collection1/ and leader is http://127.0.0.1:52187/collection1/
[junit4:junit4] 2> 1566393 T3285 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52196
[junit4:junit4] 2> 1566394 T3285 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1566394 T3285 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2282 name=collection1 org.apache.solr.core.SolrCore@187dd7e4 url=http://127.0.0.1:52196/collection1 node=127.0.0.1:52196_ C2282_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:52196_, base_url=http://127.0.0.1:52196}
[junit4:junit4] 2> 1566395 T3287 C2282 P52196 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1566396 T3287 C2282 P52196 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1566397 T3287 C2282 P52196 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1566397 T3287 C2282 P52196 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1566400 T3287 C2282 P52196 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1566413 T3285 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1566419 T3194 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1566420 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1566421 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1566429 T3228 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1566904 T3194 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1566949 T3194 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52200
[junit4:junit4] 2> 1566951 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1566952 T3194 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1566952 T3194 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372063189689
[junit4:junit4] 2> 1566952 T3194 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372063189689/solr.xml
[junit4:junit4] 2> 1566953 T3194 oasc.CoreContainer.<init> New CoreContainer 1803861343
[junit4:junit4] 2> 1566954 T3194 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372063189689/'
[junit4:junit4] 2> 1566954 T3194 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372063189689/'
[junit4:junit4] 2> 1567156 T3194 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1567156 T3194 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1567157 T3194 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1567157 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1567158 T3194 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1567158 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1567159 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1567159 T3194 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1567160 T3194 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1567160 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1567178 T3194 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1567179 T3194 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52179/solr
[junit4:junit4] 2> 1567180 T3194 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1567182 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1567444 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1567446 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:52196_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52196"}
[junit4:junit4] 2> 1567447 T3299 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3372a9bf name:ZooKeeperConnection Watcher:127.0.0.1:52179 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1567448 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1567533 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1567559 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1567562 T3252 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> 1567562 T3216 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> 1567563 T3223 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> 1567563 T3236 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> 1567564 T3284 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> 1567562 T3268 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> 1567570 T3301 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5a032b6d name:ZooKeeperConnection Watcher:127.0.0.1:52179/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1567571 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1567590 T3194 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1568432 T3228 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1568433 T3228 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:52196_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2004
[junit4:junit4] 2> 1568601 T3194 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52200_
[junit4:junit4] 2> 1568608 T3194 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52200_
[junit4:junit4] 2> 1568619 T3236 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 1568620 T3236 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> 1568620 T3284 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 1568620 T3284 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> 1568622 T3301 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 1568628 T3268 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> 1568632 T3223 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 1568632 T3223 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> 1568638 T3268 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 1568639 T3252 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 1568639 T3252 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> 1568644 T3216 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 1568644 T3216 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> 1568663 T3302 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1568663 T3302 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1569100 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1569104 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[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:52200_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52200"}
[junit4:junit4] 2> 1569105 T3217 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 1569106 T3217 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1569117 T3252 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> 1569118 T3223 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> 1569118 T3268 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> 1569125 T3216 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> 1569132 T3236 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> 1569135 T3301 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> 1569138 T3284 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> 1569667 T3302 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372063189689/collection1
[junit4:junit4] 2> 1569668 T3302 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1569669 T3302 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1569669 T3302 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1569673 T3302 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372063189689/collection1/'
[junit4:junit4] 2> 1569674 T3302 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372063189689/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1569675 T3302 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372063189689/collection1/lib/README' to classloader
[junit4:junit4] 2> 1569764 T3302 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1569849 T3302 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1569854 T3302 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1569861 T3302 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C2283 name=collection1 org.apache.solr.core.SolrCore@187dd7e4 url=http://127.0.0.1:52196/collection1 node=127.0.0.1:52196_ C2283_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:52196_, base_url=http://127.0.0.1:52196}
[junit4:junit4] 2> 1570435 T3287 C2283 P52196 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52187/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1570436 T3287 C2283 P52196 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52196 START replicas=[http://127.0.0.1:52187/collection1/] nUpdates=100
[junit4:junit4] 2> 1570436 T3287 C2283 P52196 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1570437 T3287 C2283 P52196 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1570438 T3287 C2283 P52196 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1570438 T3287 C2283 P52196 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1570438 T3287 C2283 P52196 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1570438 T3287 C2283 P52196 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52187/collection1/. core=collection1
[junit4:junit4] 2> 1570439 T3287 C2283 P52196 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2284 name=collection1 org.apache.solr.core.SolrCore@6e289ea5 url=http://127.0.0.1:52187/collection1 node=127.0.0.1:52187_ C2284_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52187_, base_url=http://127.0.0.1:52187, leader=true}
[junit4:junit4] 2> 1570472 T3227 C2284 P52187 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1570473 T3229 C2284 P52187 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> 1570497 T3227 C2284 P52187 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1570499 T3227 C2284 P52187 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1570503 T3227 C2284 P52187 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 1570504 T3227 C2284 P52187 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1570506 T3227 C2284 P52187 oass.SolrIndexSearcher.<init> Opening Searcher@183e3af0 realtime
[junit4:junit4] 2> 1570508 T3227 C2284 P52187 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1570508 T3227 C2284 P52187 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 37
[junit4:junit4] 2> 1570511 T3287 C2283 P52196 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1570511 T3287 C2283 P52196 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1570520 T3227 C2284 P52187 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1570521 T3227 C2284 P52187 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 1570522 T3287 C2283 P52196 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1570522 T3287 C2283 P52196 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1570522 T3287 C2283 P52196 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1570528 T3232 C2284 P52187 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> 1570529 T3287 C2283 P52196 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1570547 T3287 C2283 P52196 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty4/index.20130624113953784
[junit4:junit4] 2> 1570551 T3287 C2283 P52196 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty4/index.20130624113953784 lockFactory=org.apache.lucene.store.NativeFSLockFactory@61dd98a8 fullCopy=false
[junit4:junit4] 2> 1570555 T3228 C2284 P52187 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> 1570559 T3287 C2283 P52196 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1570563 T3287 C2283 P52196 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1570563 T3287 C2283 P52196 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1570568 T3287 C2283 P52196 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty4/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 1570569 T3287 C2283 P52196 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1570569 T3287 C2283 P52196 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1570570 T3287 C2283 P52196 oass.SolrIndexSearcher.<init> Opening Searcher@1d2dc163 main
[junit4:junit4] 2> 1570572 T3286 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d2dc163 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1570573 T3287 C2283 P52196 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty4/index.20130624113953784 [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty4/index.20130624113953784;done=true>>]
[junit4:junit4] 2> 1570573 T3287 C2283 P52196 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty4/index.20130624113953784
[junit4:junit4] 2> 1570573 T3287 C2283 P52196 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty4/index.20130624113953784
[junit4:junit4] 2> 1570575 T3287 C2283 P52196 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1570575 T3287 C2283 P52196 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1570575 T3287 C2283 P52196 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1570586 T3287 C2283 P52196 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1570609 T3287 C2283 P52196 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1570662 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1570676 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:52196_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52196"}
[junit4:junit4] 2> 1570686 T3284 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> 1570686 T3216 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> 1570687 T3301 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> 1570687 T3223 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> 1570686 T3236 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> 1570686 T3252 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> 1570687 T3268 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> 1570864 T3302 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1570865 T3302 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1570866 T3302 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1570878 T3302 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1570889 T3302 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1570927 T3302 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1570953 T3302 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1570960 T3302 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1570962 T3302 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1570963 T3302 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1570963 T3302 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1570967 T3302 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1570967 T3302 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1570967 T3302 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1570968 T3302 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372063189689/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty5/
[junit4:junit4] 2> 1570968 T3302 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a983bcc
[junit4:junit4] 2> 1570969 T3302 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1570970 T3302 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty5
[junit4:junit4] 2> 1570971 T3302 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty5/index/
[junit4:junit4] 2> 1570972 T3302 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1570973 T3302 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty5/index
[junit4:junit4] 2> 1570979 T3302 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1570979 T3302 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1570986 T3302 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1570986 T3302 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1570987 T3302 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1570988 T3302 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1570989 T3302 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1570989 T3302 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1570994 T3302 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1570995 T3302 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1570996 T3302 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1571033 T3302 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1571048 T3302 oass.SolrIndexSearcher.<init> Opening Searcher@4bd38356 main
[junit4:junit4] 2> 1571049 T3302 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1571049 T3302 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1571104 T3305 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4bd38356 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1571107 T3302 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1571108 T3302 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52200 collection:collection1 shard:shard2
[junit4:junit4] 2> 1571116 T3302 oasc.ZkController.register We are http://127.0.0.1:52200/collection1/ and leader is http://127.0.0.1:52190/collection1/
[junit4:junit4] 2> 1571116 T3302 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52200
[junit4:junit4] 2> 1571116 T3302 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1571117 T3302 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2285 name=collection1 org.apache.solr.core.SolrCore@2522f5aa url=http://127.0.0.1:52200/collection1 node=127.0.0.1:52200_ C2285_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:52200_, base_url=http://127.0.0.1:52200}
[junit4:junit4] 2> 1571118 T3306 C2285 P52200 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1571119 T3302 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1571123 T3194 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1571124 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1571125 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1571127 T3306 C2285 P52200 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1571141 T3306 C2285 P52200 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1571142 T3306 C2285 P52200 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1571150 T3306 C2285 P52200 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1571171 T3248 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1571587 T3194 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1571595 T3194 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52207
[junit4:junit4] 2> 1571601 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1571602 T3194 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1571602 T3194 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372063194404
[junit4:junit4] 2> 1571603 T3194 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372063194404/solr.xml
[junit4:junit4] 2> 1571603 T3194 oasc.CoreContainer.<init> New CoreContainer 381135722
[junit4:junit4] 2> 1571604 T3194 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372063194404/'
[junit4:junit4] 2> 1571604 T3194 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372063194404/'
[junit4:junit4] 2> 1571771 T3194 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1571772 T3194 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1571772 T3194 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1571773 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1571773 T3194 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1571774 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1571775 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1571775 T3194 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1571776 T3194 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1571777 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1571796 T3194 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1571797 T3194 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52179/solr
[junit4:junit4] 2> 1571798 T3194 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1571800 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1571805 T3318 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@18bc038b name:ZooKeeperConnection Watcher:127.0.0.1:52179 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1571806 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1571817 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1571836 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1571841 T3320 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@442af9b0 name:ZooKeeperConnection Watcher:127.0.0.1:52179/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1571842 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1571854 T3194 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1572205 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1572206 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[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:52200_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52200"}
[junit4:junit4] 2> 1572216 T3320 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> 1572217 T3236 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> 1572219 T3216 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> 1572220 T3268 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> 1572223 T3301 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> 1572224 T3252 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> 1572224 T3284 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> 1572223 T3223 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> 1572865 T3194 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52207_
[junit4:junit4] 2> 1572868 T3194 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52207_
[junit4:junit4] 2> 1572875 T3301 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> 1572876 T3268 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> 1572888 T3236 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1572889 T3236 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> 1572889 T3252 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1572888 T3216 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1572890 T3216 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> 1572888 T3223 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1572890 T3223 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> 1572888 T3284 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1572891 T3284 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> 1572889 T3320 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1572892 T3320 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> 1572889 T3252 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> 1572897 T3301 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1572902 T3268 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1572914 T3321 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1572914 T3321 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1573174 T3248 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1573175 T3248 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=6&state=recovering&nodeName=127.0.0.1:52200_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2004
[junit4:junit4] 2> 1573746 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1573748 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"7",
[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:52207_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52207"}
[junit4:junit4] 2> 1573749 T3217 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 1573749 T3217 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 1573763 T3216 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> 1573764 T3236 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> 1573764 T3223 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> 1573765 T3320 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> 1573784 T3252 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> 1573785 T3268 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> 1573784 T3284 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> 1573785 T3301 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> 1573918 T3321 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372063194404/collection1
[junit4:junit4] 2> 1573919 T3321 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1573920 T3321 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1573920 T3321 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1573927 T3321 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372063194404/collection1/'
[junit4:junit4] 2> 1573930 T3321 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372063194404/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1573933 T3321 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372063194404/collection1/lib/README' to classloader
[junit4:junit4] 2> 1574022 T3321 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1574138 T3321 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1574142 T3321 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1574148 T3321 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1575043 T3321 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1575043 T3321 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1575048 T3321 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1575064 T3321 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1575069 T3321 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1575115 T3321 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1575129 T3321 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1575137 T3321 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1575140 T3321 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1575140 T3321 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1575140 T3321 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1575143 T3321 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1575143 T3321 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1575144 T3321 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1575144 T3321 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372063194404/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty6/
[junit4:junit4] 2> 1575145 T3321 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a983bcc
[junit4:junit4] 2> 1575145 T3321 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1575146 T3321 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty6
[junit4:junit4] 2> 1575147 T3321 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty6/index/
[junit4:junit4] 2> 1575148 T3321 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty6/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1575149 T3321 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty6/index
[junit4:junit4] 2> 1575155 T3321 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1575156 T3321 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1575159 T3321 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1575160 T3321 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1575162 T3321 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1575163 T3321 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1575164 T3321 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1575164 T3321 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1575165 T3321 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1575166 T3321 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1575166 T3321 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> ASYNC NEW_CORE C2286 name=collection1 org.apache.solr.core.SolrCore@2522f5aa url=http://127.0.0.1:52200/collection1 node=127.0.0.1:52200_ C2286_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:52200_, base_url=http://127.0.0.1:52200}
[junit4:junit4] 2> 1575176 T3306 C2286 P52200 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52190/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1575178 T3306 C2286 P52200 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52200 START replicas=[http://127.0.0.1:52190/collection1/] nUpdates=100
[junit4:junit4] 2> 1575183 T3306 C2286 P52200 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1575186 T3306 C2286 P52200 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1575186 T3306 C2286 P52200 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1575187 T3306 C2286 P52200 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1575187 T3306 C2286 P52200 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1575187 T3306 C2286 P52200 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52190/collection1/. core=collection1
[junit4:junit4] 2> 1575188 T3306 C2286 P52200 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1575192 T3321 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> ASYNC NEW_CORE C2287 name=collection1 org.apache.solr.core.SolrCore@b1c0bcc url=http://127.0.0.1:52190/collection1 node=127.0.0.1:52190_ C2287_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52190_, base_url=http://127.0.0.1:52190, leader=true}
[junit4:junit4] 2> 1575228 T3248 C2287 P52190 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> 1575236 T3321 oass.SolrIndexSearcher.<init> Opening Searcher@24a677b main
[junit4:junit4] 2> 1575238 T3321 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1575239 T3321 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1575246 T3323 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@24a677b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1575266 T3321 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1575267 T3321 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52207 collection:collection1 shard:shard3
[junit4:junit4] 2> 1575297 T3243 C2287 P52190 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1575304 T3243 C2287 P52190 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1575305 T3243 C2287 P52190 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1575311 T3243 C2287 P52190 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 1575312 T3243 C2287 P52190 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1575315 T3243 C2287 P52190 oass.SolrIndexSearcher.<init> Opening Searcher@2e93be6e realtime
[junit4:junit4] 2> 1575315 T3243 C2287 P52190 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1575316 T3243 C2287 P52190 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 19
[junit4:junit4] 2> ASYNC NEW_CORE C2288 name=collection1 org.apache.solr.core.SolrCore@2522f5aa url=http://127.0.0.1:52200/collection1 node=127.0.0.1:52200_ C2288_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:52200_, base_url=http://127.0.0.1:52200}
[junit4:junit4] 2> 1575331 T3306 C2288 P52200 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1575331 T3306 C2288 P52200 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1575335 T3244 C2287 P52190 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1575336 T3244 C2287 P52190 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 1575338 T3306 C2288 P52200 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1575338 T3306 C2288 P52200 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1575342 T3306 C2288 P52200 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1575341 T3321 oasc.ZkController.register We are http://127.0.0.1:52207/collection1/ and leader is http://127.0.0.1:52193/collection1/
[junit4:junit4] 2> 1575346 T3321 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52207
[junit4:junit4] 2> 1575346 T3321 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1575347 T3321 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2289 name=collection1 org.apache.solr.core.SolrCore@78b1d892 url=http://127.0.0.1:52207/collection1 node=127.0.0.1:52207_ C2289_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:52207_, base_url=http://127.0.0.1:52207}
[junit4:junit4] 2> 1575348 T3324 C2289 P52207 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1575348 T3246 C2287 P52190 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> 1575349 T3324 C2289 P52207 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1575350 T3324 C2289 P52207 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1575350 T3324 C2289 P52207 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1575350 T3306 C2288 P52200 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1575351 T3321 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1575353 T3324 C2289 P52207 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1575356 T3194 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1575356 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1575357 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1575375 T3306 C2288 P52200 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty5/index.20130624113958606
[junit4:junit4] 2> 1575376 T3306 C2288 P52200 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty5/index.20130624113958606 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d9f36e6 fullCopy=false
[junit4:junit4] 2> 1575395 T3247 C2287 P52190 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> 1575397 T3259 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1575402 T3306 C2288 P52200 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1575409 T3306 C2288 P52200 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1575409 T3306 C2288 P52200 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1575414 T3306 C2288 P52200 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty5/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 1575416 T3306 C2288 P52200 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1575416 T3306 C2288 P52200 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1575417 T3306 C2288 P52200 oass.SolrIndexSearcher.<init> Opening Searcher@22749180 main
[junit4:junit4] 2> 1575418 T3305 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@22749180 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1575423 T3306 C2288 P52200 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty5/index.20130624113958606 [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty5/index.20130624113958606;done=true>>]
[junit4:junit4] 2> 1575423 T3306 C2288 P52200 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty5/index.20130624113958606
[junit4:junit4] 2> 1575425 T3306 C2288 P52200 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty5/index.20130624113958606
[junit4:junit4] 2> 1575429 T3306 C2288 P52200 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1575430 T3306 C2288 P52200 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1575430 T3306 C2288 P52200 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1575430 T3306 C2288 P52200 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1575433 T3306 C2288 P52200 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1575841 T3194 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1575853 T3194 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52214
[junit4:junit4] 2> 1575854 T3194 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1575855 T3194 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1575855 T3194 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372063198634
[junit4:junit4] 2> 1575856 T3194 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372063198634/solr.xml
[junit4:junit4] 2> 1575856 T3194 oasc.CoreContainer.<init> New CoreContainer 794238011
[junit4:junit4] 2> 1575857 T3194 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372063198634/'
[junit4:junit4] 2> 1575858 T3194 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372063198634/'
[junit4:junit4] 2> 1576019 T3194 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1576020 T3194 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1576021 T3194 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1576021 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1576022 T3194 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1576022 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1576023 T3194 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1576023 T3194 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1576024 T3194 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1576024 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1576045 T3194 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1576047 T3194 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52179/solr
[junit4:junit4] 2> 1576047 T3194 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1576050 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1576055 T3337 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@779ba625 name:ZooKeeperConnection Watcher:127.0.0.1:52179 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1576056 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1576061 T3194 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1576075 T3196 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f75564bd50011, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 1576083 T3194 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1576090 T3339 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@791d50e9 name:ZooKeeperConnection Watcher:127.0.0.1:52179/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1576090 T3194 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1576100 T3194 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1576824 T3217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1576827 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"7",
[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:52207_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52207"}
[junit4:junit4] 2> 1576833 T3217 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[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:52200_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52200"}
[junit4:junit4] 2> 1576841 T3223 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> 1576842 T3320 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> 1576842 T3339 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> 1576842 T3236 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> 1576852 T3216 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> 1576853 T3252 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> 1576854 T3284 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> 1576853 T3268 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> 1576855 T3301 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> 1577111 T3194 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52214_
[junit4:junit4] 2> 1577113 T3194 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52214_
[junit4:junit4] 2> 1577120 T3301 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> 1577120 T3339 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> 1577128 T3236 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1577129 T3236 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> 1577131 T3284 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1577131 T3284 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> 1577131 T3252 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1577131 T3252 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> 1577134 T3268 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> 1577134 T3320 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1577135 T3320 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> 1577135 T3223 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1577135 T3223 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> 1577138 T3216 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1577138 T3216 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> 1577143 T3301 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1577148 T3268 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1577151 T3339 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1577162 T3340 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1577163 T3340 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1577399 T3259 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1577400 T3259 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=7&state=recovering&nodeName=127.0.0.1:52207_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime
[...truncated too long message...]
egments_q,generation=26}
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty12/index,segFN=segments_r,generation=27}
[junit4:junit4] 2> 1705691 T3194 C2499 P52241 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 27
[junit4:junit4] 2> 1705694 T3194 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1705695 T3194 oasc.CachingDirectoryFactory.close Closing StandardDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1705695 T3194 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty12/index [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty12/index;done=false>>]
[junit4:junit4] 2> 1705696 T3194 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty12/index
[junit4:junit4] 2> 1705696 T3194 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty12 [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty12;done=false>>]
[junit4:junit4] 2> 1705697 T3194 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372063157177/jetty12
[junit4:junit4] 2> 1705699 T3656 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89919531070586908-127.0.0.1:52241_-n_0000000012) am no longer a leader.
[junit4:junit4] 2> 1705716 T3194 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 1705900 T3194 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1705903 T3194 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:52179 52179
[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=1DA144D5B259798E -Dtests.slow=true -Dtests.locale=lt_LT -Dtests.timezone=Africa/Mogadishu -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 172s | ChaosMonkeySafeLeaderTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard3 is not consistent. Got 46 from http://127.0.0.1:52226/collection1lastClient and got 41 from http://127.0.0.1:52241/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([1DA144D5B259798E:9C47CACDC50619B2]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2> 1706038 T3194 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 172169 T3193 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> 1707003 T3434 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1707003 T3434 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> 1707004 T3434 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {range_facet_l=PostingsFormat(name=TestBloomFilteredLucene41Postings), text=PostingsFormat(name=MockSep), _version_=MockFixedIntBlock(blockSize=1204), rnd_b=Pulsing41(freqCutoff=20 minBlockSize=96 maxBlockSize=275), intDefault=MockFixedIntBlock(blockSize=1204), timestamp=PostingsFormat(name=TestBloomFilteredLucene41Postings), id=Pulsing41(freqCutoff=20 minBlockSize=96 maxBlockSize=275), a_t=PostingsFormat(name=TestBloomFilteredLucene41Postings), range_facet_sl=Pulsing41(freqCutoff=20 minBlockSize=96 maxBlockSize=275), range_facet_si=PostingsFormat(name=TestBloomFilteredLucene41Postings), other_tl1=MockFixedIntBlock(blockSize=1204), multiDefault=PostingsFormat(name=TestBloomFilteredLucene41Postings), a_si=MockFixedIntBlock(blockSize=1204)}, docValues:{}, sim=DefaultSimilarity, locale=lt_LT, timezone=Africa/Mogadishu
[junit4:junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=2,threads=1,free=57311480,total=213229568
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestMultiCoreConfBootstrap, TestSystemIdResolver, HighlighterTest, TermVectorComponentTest, TestFaceting, CachingDirectoryFactoryTest, OverseerCollectionProcessorTest, SignatureUpdateProcessorFactoryTest, TestReloadAndDeleteDocs, TestCodecSupport, TestSolrDeletionPolicy1, SpatialFilterTest, SolrIndexSplitterTest, ClusterStateUpdateTest, TestDefaultSearchFieldResource, DateMathParserTest, TestIBSimilarityFactory, TestAnalyzedSuggestions, TestSchemaSimilarityResource, UniqFieldsUpdateProcessorFactoryTest, RAMDirectoryFactoryTest, TestWriterPerf, MinimalSchemaTest, TestSchemaVersionResource, TestGroupingSearch, SuggesterWFSTTest, TestDefaultSimilarityFactory, PathHierarchyTokenizerFactoryTest, TestFieldResource, TestOmitPositions, BasicZkTest, LeaderElectionTest, TestPartialUpdateDeduplication, BasicFunctionalityTest, FileUtilsTest, TestSolr4Spatial, ShowFileRequestHandlerTest, BadComponentTest, QueryParsingTest, TestPropInjectDefaults, IndexSchemaRuntimeFieldTest, TestLMDirichletSimilarityFactory, TestPHPSerializedResponseWriter, TestNumberUtils, MBeansHandlerTest, SampleTest, TestRecovery, TestDynamicFieldCollectionResource, DisMaxRequestHandlerTest, TestRangeQuery, SynonymTokenizerTest, PluginInfoTest, ScriptEngineTest, SimplePostToolTest, XmlUpdateRequestHandlerTest, TestPseudoReturnFields, TestReversedWildcardFilterFactory, TestLazyCores, TestSolrIndexConfig, SuggesterFSTTest, JSONWriterTest, TestRTGBase, QueryEqualityTest, TermVectorComponentDistributedTest, TestQuerySenderNoQuery, TermsComponentTest, BinaryUpdateRequestHandlerTest, TestPhraseSuggestions, URLClassifyProcessorTest, ChaosMonkeyNothingIsSafeTest, DirectUpdateHandlerTest, TestSearchPerf, TestLFUCache, TestSolrXmlPersistence, ResourceLoaderTest, TestComponentsName, TestIndexingPerformance, StatsComponentTest, TestSolrXMLSerializer, BasicDistributedZkTest, SearchHandlerTest, XsltUpdateRequestHandlerTest, SchemaVersionSpecificBehaviorTest, ExternalFileFieldSortTest, TestPerFieldSimilarity, TestQueryUtils, ShardSplitTest, SolrCmdDistributorTest, CircularListTest, TestManagedSchemaFieldResource, SuggesterTest, AutoCommitTest, DebugComponentTest, ResponseLogComponentTest, TestConfig, NoCacheHeaderTest, SimpleFacetsTest, NumericFieldsTest, TestSolrXml, TestBinaryResponseWriter, TestRandomFaceting, TestShardHandlerFactory, TestPostingsSolrHighlighter, TestDocumentBuilder, DirectUpdateHandlerOptimizeTest, PeerSyncTest, TestJoin, QueryResultKeyTest, CurrencyFieldXmlFileTest, TestCoreContainer, TestFoldingMultitermQuery, BasicDistributedZk2Test, UpdateParamsTest, QueryElevationComponentTest, SpellCheckComponentTest, TestDocSet, TestBinaryField, SOLR749Test, TestSchemaNameResource, TestDistributedSearch, TestCharFilters, CoreContainerCoreInitFailuresTest, DocValuesMultiTest, TestRealTimeGet, TestReplicationHandler, CurrencyFieldOpenExchangeTest, DateFieldTest, DOMUtilTest, SolrCoreTest, TestStressRecovery, ZkCLITest, DocumentBuilderTest, TestJmxIntegration, TestQuerySenderListener, TestValueSourceCache, TestFuzzyAnalyzedSuggestions, TestSolrQueryParserResource, DocValuesTest, ChaosMonkeySafeLeaderTest]
[junit4:junit4] Completed in 173.22s, 1 test, 1 failure <<< FAILURES!
[...truncated 483 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:392: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:372: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build.xml:181: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/common-build.xml:437: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:1246: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:890: There were test failures: 298 suites, 1256 tests, 1 failure, 18 ignored (6 assumptions)
Total time: 103 minutes 26 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure