You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/06/01 16:34:50 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1673 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1673/
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.testDistribSearch
Error Message:
shard3 is not consistent. Got 43 from http://127.0.0.1:25146/qr_r/collection1lastClient and got 21 from http://127.0.0.1:35643/qr_r/collection1
Stack Trace:
java.lang.AssertionError: shard3 is not consistent. Got 43 from http://127.0.0.1:25146/qr_r/collection1lastClient and got 21 from http://127.0.0.1:35643/qr_r/collection1
at __randomizedtesting.SeedInfo.seed([305D3204895F8723:B1BBBC1CFE00E71F]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
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:679)
Build Log:
[...truncated 9003 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
[junit4:junit4] 2> 639727 T1270 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /qr_r/
[junit4:junit4] 2> 639739 T1270 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeySafeLeaderTest-1370095993718
[junit4:junit4] 2> 639741 T1270 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 639741 T1271 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 639842 T1270 oasc.ZkTestServer.run start zk server on port:47708
[junit4:junit4] 2> 639843 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 639873 T1277 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a495642 name:ZooKeeperConnection Watcher:127.0.0.1:47708 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 639874 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 639875 T1270 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 639880 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 639906 T1279 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@25598c5a name:ZooKeeperConnection Watcher:127.0.0.1:47708/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 639906 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 639907 T1270 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 639948 T1270 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 639967 T1270 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 640007 T1270 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 640011 T1270 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 640012 T1270 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 640107 T1270 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 640108 T1270 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 640215 T1270 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 640216 T1270 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 640220 T1270 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 640220 T1270 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 640234 T1270 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 640235 T1270 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 640238 T1270 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 640239 T1270 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 640242 T1270 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 640243 T1270 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 640247 T1270 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 640248 T1270 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 640257 T1270 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 640258 T1270 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 640528 T1270 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 640532 T1270 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:47711
[junit4:junit4] 2> 640532 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 640533 T1270 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 640533 T1270 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1370095994244
[junit4:junit4] 2> 640534 T1270 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1370095994244/solr.xml
[junit4:junit4] 2> 640534 T1270 oasc.CoreContainer.<init> New CoreContainer 909187139
[junit4:junit4] 2> 640535 T1270 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1370095994244/'
[junit4:junit4] 2> 640535 T1270 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1370095994244/'
[junit4:junit4] 2> 640653 T1270 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 640654 T1270 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 640654 T1270 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 640655 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 640655 T1270 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 640656 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 640656 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 640657 T1270 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 640657 T1270 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 640658 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 640673 T1270 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 640674 T1270 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:47708/solr
[junit4:junit4] 2> 640675 T1270 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 640676 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 640679 T1290 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@22d9db24 name:ZooKeeperConnection Watcher:127.0.0.1:47708 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 640679 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 640692 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 640702 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 640704 T1292 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2ce70449 name:ZooKeeperConnection Watcher:127.0.0.1:47708/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 640704 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 640707 T1270 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 640717 T1270 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 640721 T1270 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 640723 T1270 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47711_qr_r
[junit4:junit4] 2> 640731 T1270 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47711_qr_r
[junit4:junit4] 2> 640735 T1270 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 640749 T1270 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 640753 T1270 oasc.Overseer.start Overseer (id=89790611044827139-127.0.0.1:47711_qr_r-n_0000000000) starting
[junit4:junit4] 2> 640763 T1270 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 640775 T1294 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 640777 T1270 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 640779 T1270 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 640782 T1270 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 640789 T1293 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 640794 T1295 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1370095994244/collection1
[junit4:junit4] 2> 640794 T1295 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 640795 T1295 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 640795 T1295 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 640797 T1295 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1370095994244/collection1/'
[junit4:junit4] 2> 640798 T1295 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1370095994244/collection1/lib/README' to classloader
[junit4:junit4] 2> 640799 T1295 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1370095994244/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 640851 T1295 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 640912 T1295 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 641013 T1295 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 641020 T1295 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 641657 T1295 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 641672 T1295 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 641682 T1295 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 641699 T1295 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 641705 T1295 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 641710 T1295 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 641711 T1295 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 641712 T1295 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 641712 T1295 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 641713 T1295 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 641713 T1295 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 641714 T1295 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 641765 T1295 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1370095994244/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/control/data/
[junit4:junit4] 2> 641765 T1295 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@407e75d2
[junit4:junit4] 2> 641766 T1295 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 641767 T1295 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/control/data
[junit4:junit4] 2> 641768 T1295 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/control/data/index/
[junit4:junit4] 2> 641769 T1295 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 641770 T1295 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/control/data/index
[junit4:junit4] 2> 641803 T1295 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 641803 T1295 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 641806 T1295 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 641806 T1295 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 641807 T1295 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 641808 T1295 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 641808 T1295 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 641809 T1295 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 641809 T1295 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 641809 T1295 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 641810 T1295 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 641820 T1295 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 641831 T1295 oass.SolrIndexSearcher.<init> Opening Searcher@132a54c main
[junit4:junit4] 2> 641832 T1295 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 641832 T1295 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 641836 T1296 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@132a54c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 641837 T1295 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 641837 T1295 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 642294 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 642295 T1293 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:47711_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47711/qr_r"}
[junit4:junit4] 2> 642295 T1293 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 642295 T1293 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 642309 T1292 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> 642840 T1295 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 642840 T1295 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47711/qr_r collection:control_collection shard:shard1
[junit4:junit4] 2> 642841 T1295 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 642863 T1295 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 642875 T1295 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 642875 T1295 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 642876 T1295 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:47711/qr_r/collection1/
[junit4:junit4] 2> 642876 T1295 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 642876 T1295 oasc.SyncStrategy.syncToMe http://127.0.0.1:47711/qr_r/collection1/ has no replicas
[junit4:junit4] 2> 642876 T1295 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:47711/qr_r/collection1/
[junit4:junit4] 2> 642877 T1295 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 643815 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 643843 T1292 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> 643863 T1295 oasc.ZkController.register We are http://127.0.0.1:47711/qr_r/collection1/ and leader is http://127.0.0.1:47711/qr_r/collection1/
[junit4:junit4] 2> 643863 T1295 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47711/qr_r
[junit4:junit4] 2> 643863 T1295 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 643863 T1295 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 643864 T1295 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 643870 T1295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 643872 T1270 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 643873 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 643873 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 643889 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 643890 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 643893 T1299 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@609f8676 name:ZooKeeperConnection Watcher:127.0.0.1:47708/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 643893 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 643895 T1270 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 643898 T1270 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 644175 T1270 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 644177 T1270 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:47715
[junit4:junit4] 2> 644178 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 644179 T1270 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 644179 T1270 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1370095997876
[junit4:junit4] 2> 644180 T1270 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1370095997876/solr.xml
[junit4:junit4] 2> 644180 T1270 oasc.CoreContainer.<init> New CoreContainer 696008476
[junit4:junit4] 2> 644181 T1270 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1370095997876/'
[junit4:junit4] 2> 644181 T1270 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1370095997876/'
[junit4:junit4] 2> 644297 T1270 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 644298 T1270 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 644298 T1270 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 644299 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 644299 T1270 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 644300 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 644300 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 644301 T1270 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 644301 T1270 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 644302 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 644319 T1270 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 644320 T1270 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:47708/solr
[junit4:junit4] 2> 644321 T1270 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 644322 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 644325 T1310 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3b20b813 name:ZooKeeperConnection Watcher:127.0.0.1:47708 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 644325 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 644336 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 644347 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 644350 T1312 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@266a10b4 name:ZooKeeperConnection Watcher:127.0.0.1:47708/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 644350 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 644362 T1270 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 645357 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 645358 T1293 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:47711_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47711/qr_r"}
[junit4:junit4] 2> 645388 T1270 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47715_qr_r
[junit4:junit4] 2> 645390 T1270 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47715_qr_r
[junit4:junit4] 2> 645404 T1312 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> 645404 T1299 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> 645404 T1292 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> 645412 T1312 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 645413 T1299 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 645414 T1292 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> 645416 T1292 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 645419 T1313 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1370095997876/collection1
[junit4:junit4] 2> 645419 T1313 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 645420 T1313 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 645420 T1313 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 645422 T1313 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1370095997876/collection1/'
[junit4:junit4] 2> 645423 T1313 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1370095997876/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 645424 T1313 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1370095997876/collection1/lib/README' to classloader
[junit4:junit4] 2> 645476 T1313 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 645536 T1313 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 645638 T1313 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 645645 T1313 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 646288 T1313 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 646301 T1313 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 646306 T1313 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 646323 T1313 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 646328 T1313 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 646333 T1313 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 646335 T1313 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 646335 T1313 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 646336 T1313 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 646337 T1313 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 646337 T1313 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 646337 T1313 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 646338 T1313 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1370095997876/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty1/
[junit4:junit4] 2> 646338 T1313 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@407e75d2
[junit4:junit4] 2> 646339 T1313 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 646340 T1313 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty1
[junit4:junit4] 2> 646340 T1313 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty1/index/
[junit4:junit4] 2> 646341 T1313 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 646342 T1313 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty1/index
[junit4:junit4] 2> 646373 T1313 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 646374 T1313 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 646377 T1313 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 646377 T1313 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 646378 T1313 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 646379 T1313 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 646379 T1313 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 646379 T1313 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 646380 T1313 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 646380 T1313 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 646381 T1313 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 646391 T1313 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 646401 T1313 oass.SolrIndexSearcher.<init> Opening Searcher@8667645 main
[junit4:junit4] 2> 646402 T1313 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 646403 T1313 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 646408 T1314 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8667645 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 646411 T1313 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 646411 T1313 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 646915 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 646916 T1293 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:47715_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47715/qr_r"}
[junit4:junit4] 2> 646916 T1293 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 3
[junit4:junit4] 2> 646916 T1293 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 646950 T1292 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> 646950 T1312 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> 646950 T1299 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> 647414 T1313 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 647414 T1313 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47715/qr_r collection:collection1 shard:shard1
[junit4:junit4] 2> 647415 T1313 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 647437 T1313 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 647448 T1313 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 647448 T1313 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 647448 T1313 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:47715/qr_r/collection1/
[junit4:junit4] 2> 647448 T1313 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 647449 T1313 oasc.SyncStrategy.syncToMe http://127.0.0.1:47715/qr_r/collection1/ has no replicas
[junit4:junit4] 2> 647449 T1313 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:47715/qr_r/collection1/
[junit4:junit4] 2> 647449 T1313 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 648455 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 648474 T1292 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> 648474 T1312 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> 648474 T1299 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> 648483 T1313 oasc.ZkController.register We are http://127.0.0.1:47715/qr_r/collection1/ and leader is http://127.0.0.1:47715/qr_r/collection1/
[junit4:junit4] 2> 648483 T1313 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47715/qr_r
[junit4:junit4] 2> 648483 T1313 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 648483 T1313 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 648484 T1313 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 648485 T1313 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 648487 T1270 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 648487 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 648488 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 648786 T1270 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 648790 T1270 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:47718
[junit4:junit4] 2> 648791 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 648791 T1270 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 648792 T1270 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1370096002481
[junit4:junit4] 2> 648792 T1270 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1370096002481/solr.xml
[junit4:junit4] 2> 648793 T1270 oasc.CoreContainer.<init> New CoreContainer 2105582754
[junit4:junit4] 2> 648793 T1270 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1370096002481/'
[junit4:junit4] 2> 648794 T1270 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1370096002481/'
[junit4:junit4] 2> 648911 T1270 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 648911 T1270 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 648912 T1270 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 648912 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 648913 T1270 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 648913 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 648914 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 648914 T1270 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 648915 T1270 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 648915 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 648931 T1270 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 648932 T1270 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:47708/solr
[junit4:junit4] 2> 648932 T1270 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 648934 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 648937 T1326 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b55d1f4 name:ZooKeeperConnection Watcher:127.0.0.1:47708 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 648937 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 648951 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 648962 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 648965 T1328 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@70410355 name:ZooKeeperConnection Watcher:127.0.0.1:47708/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 648965 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 648974 T1270 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 649978 T1270 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47718_qr_r
[junit4:junit4] 2> 649994 T1270 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47718_qr_r
[junit4:junit4] 2> 649995 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 649996 T1293 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:47715_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47715/qr_r"}
[junit4:junit4] 2> 650019 T1292 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> 650019 T1299 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> 650021 T1328 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 650021 T1312 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 650021 T1312 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> 650077 T1299 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 650078 T1312 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> 650078 T1328 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> 650078 T1299 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> 650082 T1329 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1370096002481/collection1
[junit4:junit4] 2> 650083 T1329 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 650129 T1329 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 650129 T1329 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 650130 T1292 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 650131 T1329 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1370096002481/collection1/'
[junit4:junit4] 2> 650131 T1292 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> 650132 T1329 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1370096002481/collection1/lib/README' to classloader
[junit4:junit4] 2> 650133 T1329 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1370096002481/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 650186 T1329 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 650247 T1329 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 650349 T1329 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 650356 T1329 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 651003 T1329 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 651018 T1329 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 651022 T1329 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 651038 T1329 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 651043 T1329 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 651048 T1329 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 651049 T1329 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 651050 T1329 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 651050 T1329 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 651051 T1329 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 651051 T1329 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 651052 T1329 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 651052 T1329 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1370096002481/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty2/
[junit4:junit4] 2> 651052 T1329 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@407e75d2
[junit4:junit4] 2> 651053 T1329 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 651054 T1329 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty2
[junit4:junit4] 2> 651055 T1329 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty2/index/
[junit4:junit4] 2> 651056 T1329 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 651057 T1329 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty2/index
[junit4:junit4] 2> 651088 T1329 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 651089 T1329 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 651092 T1329 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 651092 T1329 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 651093 T1329 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 651094 T1329 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 651094 T1329 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 651095 T1329 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 651095 T1329 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 651096 T1329 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 651096 T1329 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 651106 T1329 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 651117 T1329 oass.SolrIndexSearcher.<init> Opening Searcher@26e3cabe main
[junit4:junit4] 2> 651118 T1329 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 651118 T1329 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 651123 T1330 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@26e3cabe main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 651125 T1329 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 651125 T1329 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 651632 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 651633 T1293 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:47718_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47718/qr_r"}
[junit4:junit4] 2> 651633 T1293 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 651633 T1293 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 651642 T1312 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> 651642 T1292 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> 651642 T1299 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> 651642 T1328 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> 652128 T1329 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 652128 T1329 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47718/qr_r collection:collection1 shard:shard2
[junit4:junit4] 2> 652129 T1329 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 652146 T1329 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 652155 T1329 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 652155 T1329 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 652156 T1329 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:47718/qr_r/collection1/
[junit4:junit4] 2> 652156 T1329 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 652156 T1329 oasc.SyncStrategy.syncToMe http://127.0.0.1:47718/qr_r/collection1/ has no replicas
[junit4:junit4] 2> 652156 T1329 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:47718/qr_r/collection1/
[junit4:junit4] 2> 652157 T1329 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 653158 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 653181 T1328 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> 653181 T1292 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> 653181 T1312 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> 653181 T1299 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> 653190 T1329 oasc.ZkController.register We are http://127.0.0.1:47718/qr_r/collection1/ and leader is http://127.0.0.1:47718/qr_r/collection1/
[junit4:junit4] 2> 653190 T1329 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47718/qr_r
[junit4:junit4] 2> 653190 T1329 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 653190 T1329 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 653191 T1329 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 653193 T1329 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 653194 T1270 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 653194 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 653195 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 653469 T1270 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 653473 T1270 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:47721
[junit4:junit4] 2> 653473 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 653474 T1270 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 653474 T1270 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1370096007188
[junit4:junit4] 2> 653475 T1270 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1370096007188/solr.xml
[junit4:junit4] 2> 653475 T1270 oasc.CoreContainer.<init> New CoreContainer 1770478373
[junit4:junit4] 2> 653476 T1270 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1370096007188/'
[junit4:junit4] 2> 653476 T1270 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1370096007188/'
[junit4:junit4] 2> 653591 T1270 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 653592 T1270 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 653593 T1270 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 653593 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 653594 T1270 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 653594 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 653595 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 653595 T1270 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 653595 T1270 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 653596 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 653613 T1270 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 653614 T1270 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:47708/solr
[junit4:junit4] 2> 653615 T1270 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 653616 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 653619 T1342 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11e2ba1e name:ZooKeeperConnection Watcher:127.0.0.1:47708 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 653620 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 653633 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 653645 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 653648 T1344 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3ca64453 name:ZooKeeperConnection Watcher:127.0.0.1:47708/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 653648 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 653659 T1270 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 654663 T1270 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47721_qr_r
[junit4:junit4] 2> 654665 T1270 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47721_qr_r
[junit4:junit4] 2> 654668 T1299 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> 654669 T1312 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 654669 T1344 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 654669 T1292 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> 654669 T1312 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> 654669 T1328 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 654671 T1328 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> 654671 T1299 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 654679 T1292 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 654684 T1345 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1370096007188/collection1
[junit4:junit4] 2> 654685 T1345 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 654685 T1345 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 654686 T1345 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 654687 T1345 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1370096007188/collection1/'
[junit4:junit4] 2> 654688 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 654689 T1345 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1370096007188/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 654689 T1293 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:47718_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47718/qr_r"}
[junit4:junit4] 2> 654690 T1345 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1370096007188/collection1/lib/README' to classloader
[junit4:junit4] 2> 654700 T1312 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> 654700 T1328 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> 654700 T1292 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> 654700 T1299 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> 654700 T1344 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> 654741 T1345 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 654808 T1345 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 654910 T1345 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 654917 T1345 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 655558 T1345 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 655572 T1345 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 655576 T1345 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 655592 T1345 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 655597 T1345 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 655602 T1345 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 655604 T1345 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 655604 T1345 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 655604 T1345 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 655606 T1345 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 655606 T1345 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 655606 T1345 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 655606 T1345 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1370096007188/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty3/
[junit4:junit4] 2> 655607 T1345 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@407e75d2
[junit4:junit4] 2> 655607 T1345 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 655608 T1345 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty3
[junit4:junit4] 2> 655609 T1345 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty3/index/
[junit4:junit4] 2> 655610 T1345 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 655611 T1345 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty3/index
[junit4:junit4] 2> 655622 T1345 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 655622 T1345 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 655626 T1345 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 655626 T1345 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 655627 T1345 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 655627 T1345 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 655628 T1345 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 655628 T1345 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 655629 T1345 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 655629 T1345 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 655630 T1345 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 655639 T1345 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 655650 T1345 oass.SolrIndexSearcher.<init> Opening Searcher@3d363a02 main
[junit4:junit4] 2> 655651 T1345 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 655651 T1345 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 655656 T1346 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3d363a02 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 655659 T1345 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 655659 T1345 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 656206 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 656207 T1293 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:47721_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47721/qr_r"}
[junit4:junit4] 2> 656207 T1293 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 656207 T1293 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 656238 T1312 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> 656238 T1292 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> 656238 T1299 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> 656238 T1328 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> 656238 T1344 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> 656662 T1345 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 656662 T1345 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47721/qr_r collection:collection1 shard:shard3
[junit4:junit4] 2> 656663 T1345 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4:junit4] 2> 656680 T1345 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 656691 T1345 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 656691 T1345 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 656692 T1345 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:47721/qr_r/collection1/
[junit4:junit4] 2> 656692 T1345 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 656692 T1345 oasc.SyncStrategy.syncToMe http://127.0.0.1:47721/qr_r/collection1/ has no replicas
[junit4:junit4] 2> 656692 T1345 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:47721/qr_r/collection1/
[junit4:junit4] 2> 656693 T1345 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4:junit4] 2> 657754 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 657775 T1299 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> 657775 T1292 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> 657775 T1328 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> 657775 T1312 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> 657775 T1344 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> 657778 T1345 oasc.ZkController.register We are http://127.0.0.1:47721/qr_r/collection1/ and leader is http://127.0.0.1:47721/qr_r/collection1/
[junit4:junit4] 2> 657778 T1345 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47721/qr_r
[junit4:junit4] 2> 657778 T1345 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 657778 T1345 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 657779 T1345 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 657780 T1345 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 657782 T1270 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 657782 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 657783 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 658061 T1270 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 658064 T1270 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:47724
[junit4:junit4] 2> 658065 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 658065 T1270 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 658066 T1270 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1370096011777
[junit4:junit4] 2> 658066 T1270 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1370096011777/solr.xml
[junit4:junit4] 2> 658067 T1270 oasc.CoreContainer.<init> New CoreContainer 827900953
[junit4:junit4] 2> 658068 T1270 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1370096011777/'
[junit4:junit4] 2> 658068 T1270 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1370096011777/'
[junit4:junit4] 2> 658189 T1270 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 658189 T1270 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 658190 T1270 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 658190 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 658191 T1270 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 658191 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 658192 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 658192 T1270 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 658193 T1270 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 658193 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 658208 T1270 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 658209 T1270 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:47708/solr
[junit4:junit4] 2> 658210 T1270 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 658211 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 658214 T1358 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@51bde277 name:ZooKeeperConnection Watcher:127.0.0.1:47708 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 658214 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 658217 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 658228 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 658230 T1360 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5cebe66d name:ZooKeeperConnection Watcher:127.0.0.1:47708/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 658230 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 658242 T1270 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 659246 T1270 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47724_qr_r
[junit4:junit4] 2> 659248 T1270 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47724_qr_r
[junit4:junit4] 2> 659251 T1299 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> 659252 T1292 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> 659252 T1344 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 659253 T1360 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 659253 T1328 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 659252 T1312 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 659253 T1328 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> 659253 T1344 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> 659254 T1299 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 659253 T1312 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> 659264 T1292 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 659269 T1361 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1370096011777/collection1
[junit4:junit4] 2> 659269 T1361 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 659270 T1361 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 659270 T1361 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 659272 T1361 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1370096011777/collection1/'
[junit4:junit4] 2> 659273 T1361 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1370096011777/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 659274 T1361 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1370096011777/collection1/lib/README' to classloader
[junit4:junit4] 2> 659282 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 659282 T1293 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:47721_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47721/qr_r"}
[junit4:junit4] 2> 659293 T1299 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> 659293 T1292 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> 659293 T1360 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> 659293 T1344 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> 659293 T1328 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> 659293 T1312 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> 659326 T1361 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 659386 T1361 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 659487 T1361 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 659493 T1361 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 660141 T1361 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 660155 T1361 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 660160 T1361 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 660176 T1361 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 660181 T1361 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 660186 T1361 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 660188 T1361 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 660188 T1361 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 660189 T1361 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 660190 T1361 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 660190 T1361 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 660190 T1361 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 660191 T1361 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1370096011777/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty4/
[junit4:junit4] 2> 660191 T1361 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@407e75d2
[junit4:junit4] 2> 660192 T1361 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 660193 T1361 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty4
[junit4:junit4] 2> 660194 T1361 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty4/index/
[junit4:junit4] 2> 660194 T1361 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 660195 T1361 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty4/index
[junit4:junit4] 2> 660206 T1361 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 660206 T1361 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 660209 T1361 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 660210 T1361 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 660210 T1361 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 660211 T1361 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 660212 T1361 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 660212 T1361 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 660212 T1361 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 660213 T1361 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 660213 T1361 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 660225 T1361 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 660234 T1361 oass.SolrIndexSearcher.<init> Opening Searcher@627d12d8 main
[junit4:junit4] 2> 660236 T1361 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 660236 T1361 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 660241 T1362 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@627d12d8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 660243 T1361 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 660243 T1361 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 660799 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 660800 T1293 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:47724_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47724/qr_r"}
[junit4:junit4] 2> 660800 T1293 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 660800 T1293 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 660821 T1299 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> 660821 T1328 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> 660821 T1344 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> 660821 T1292 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> 660821 T1312 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> 660821 T1360 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> 661247 T1361 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 661247 T1361 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47724/qr_r collection:collection1 shard:shard1
[junit4:junit4] 2> 661251 T1361 oasc.ZkController.register We are http://127.0.0.1:47724/qr_r/collection1/ and leader is http://127.0.0.1:47715/qr_r/collection1/
[junit4:junit4] 2> 661251 T1361 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47724/qr_r
[junit4:junit4] 2> 661252 T1361 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 661252 T1361 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1504 name=collection1 org.apache.solr.core.SolrCore@3decdd7c url=http://127.0.0.1:47724/qr_r/collection1 node=127.0.0.1:47724_qr_r C1504_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:47724_qr_r, base_url=http://127.0.0.1:47724/qr_r}
[junit4:junit4] 2> 661252 T1363 C1504 P47724 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 661253 T1361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 661254 T1363 C1504 P47724 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 661254 T1363 C1504 P47724 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 661254 T1363 C1504 P47724 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 661255 T1270 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 661256 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 661256 T1363 C1504 P47724 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 661256 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 661276 T1302 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 661546 T1270 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 661549 T1270 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:47728
[junit4:junit4] 2> 661550 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 661550 T1270 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 661551 T1270 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1370096015252
[junit4:junit4] 2> 661551 T1270 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1370096015252/solr.xml
[junit4:junit4] 2> 661552 T1270 oasc.CoreContainer.<init> New CoreContainer 1179515427
[junit4:junit4] 2> 661552 T1270 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1370096015252/'
[junit4:junit4] 2> 661553 T1270 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1370096015252/'
[junit4:junit4] 2> 661668 T1270 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 661669 T1270 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 661669 T1270 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 661670 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 661670 T1270 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 661671 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 661671 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 661672 T1270 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 661673 T1270 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 661673 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 661690 T1270 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 661691 T1270 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:47708/solr
[junit4:junit4] 2> 661692 T1270 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 661694 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 661697 T1375 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@204ce9b1 name:ZooKeeperConnection Watcher:127.0.0.1:47708 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 661697 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 661701 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 661712 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 661715 T1377 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@32af0c94 name:ZooKeeperConnection Watcher:127.0.0.1:47708/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 661715 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 661727 T1270 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 662329 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 662330 T1293 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:47724_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47724/qr_r"}
[junit4:junit4] 2> 662377 T1299 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> 662377 T1292 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> 662377 T1360 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> 662377 T1312 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> 662377 T1328 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> 662377 T1377 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> 662377 T1344 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> 662731 T1270 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47728_qr_r
[junit4:junit4] 2> 662734 T1270 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47728_qr_r
[junit4:junit4] 2> 662736 T1299 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> 662736 T1292 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> 662737 T1312 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 662737 T1328 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 662736 T1377 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> 662737 T1328 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> 662737 T1312 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> 662737 T1344 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 662737 T1360 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 662738 T1344 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> 662738 T1360 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> 662739 T1299 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 662739 T1292 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 662740 T1377 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 662745 T1378 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1370096015252/collection1
[junit4:junit4] 2> 662745 T1378 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 662746 T1378 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 662746 T1378 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 662748 T1378 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1370096015252/collection1/'
[junit4:junit4] 2> 662750 T1378 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1370096015252/collection1/lib/README' to classloader
[junit4:junit4] 2> 662750 T1378 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1370096015252/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 662803 T1378 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 662864 T1378 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 662866 T1378 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 662872 T1378 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 663278 T1302 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 663278 T1302 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:47724_qr_r&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 663515 T1378 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 663530 T1378 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 663535 T1378 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 663550 T1378 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 663555 T1378 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 663560 T1378 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 663561 T1378 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 663562 T1378 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 663562 T1378 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 663563 T1378 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 663564 T1378 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 663564 T1378 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 663564 T1378 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1370096015252/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty5/
[junit4:junit4] 2> 663565 T1378 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@407e75d2
[junit4:junit4] 2> 663565 T1378 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 663567 T1378 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty5
[junit4:junit4] 2> 663568 T1378 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty5/index/
[junit4:junit4] 2> 663568 T1378 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 663569 T1378 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty5/index
[junit4:junit4] 2> 663600 T1378 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 663601 T1378 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 663604 T1378 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 663605 T1378 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 663605 T1378 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 663606 T1378 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 663607 T1378 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 663607 T1378 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 663607 T1378 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 663608 T1378 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 663608 T1378 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 663619 T1378 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 663629 T1378 oass.SolrIndexSearcher.<init> Opening Searcher@7f633327 main
[junit4:junit4] 2> 663630 T1378 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 663630 T1378 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 663635 T1379 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7f633327 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 663638 T1378 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 663638 T1378 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 663883 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 663884 T1293 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:47728_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47728/qr_r"}
[junit4:junit4] 2> 663884 T1293 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 663884 T1293 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 663916 T1312 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> 663916 T1328 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> 663916 T1292 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> 663916 T1360 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> 663916 T1344 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> 663916 T1299 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> 663916 T1377 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> 664641 T1378 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 664641 T1378 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47728/qr_r collection:collection1 shard:shard2
[junit4:junit4] 2> 664671 T1378 oasc.ZkController.register We are http://127.0.0.1:47728/qr_r/collection1/ and leader is http://127.0.0.1:47718/qr_r/collection1/
[junit4:junit4] 2> 664672 T1378 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47728/qr_r
[junit4:junit4] 2> 664672 T1378 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 664672 T1378 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1505 name=collection1 org.apache.solr.core.SolrCore@3dd8d04b url=http://127.0.0.1:47728/qr_r/collection1 node=127.0.0.1:47728_qr_r C1505_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:47728_qr_r, base_url=http://127.0.0.1:47728/qr_r}
[junit4:junit4] 2> 664672 T1380 C1505 P47728 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 664673 T1378 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 664673 T1380 C1505 P47728 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 664674 T1380 C1505 P47728 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 664674 T1380 C1505 P47728 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 664674 T1270 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 664675 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 664675 T1380 C1505 P47728 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 664676 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 664699 T1318 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 664974 T1270 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 664977 T1270 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:47732
[junit4:junit4] 2> 664978 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 664978 T1270 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 664979 T1270 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1370096018676
[junit4:junit4] 2> 664979 T1270 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1370096018676/solr.xml
[junit4:junit4] 2> 664980 T1270 oasc.CoreContainer.<init> New CoreContainer 360609244
[junit4:junit4] 2> 664980 T1270 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1370096018676/'
[junit4:junit4] 2> 664981 T1270 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1370096018676/'
[junit4:junit4] 2> 665103 T1270 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 665104 T1270 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 665104 T1270 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 665105 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 665105 T1270 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 665106 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 665106 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 665107 T1270 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 665107 T1270 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 665108 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 665124 T1270 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 665124 T1270 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:47708/solr
[junit4:junit4] 2> 665125 T1270 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 665126 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 665133 T1392 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7919bb1e name:ZooKeeperConnection Watcher:127.0.0.1:47708 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 665134 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 665157 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 665169 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 665171 T1394 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@53c1cd9b name:ZooKeeperConnection Watcher:127.0.0.1:47708/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 665171 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 665245 T1270 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C1506 name=collection1 org.apache.solr.core.SolrCore@3decdd7c url=http://127.0.0.1:47724/qr_r/collection1 node=127.0.0.1:47724_qr_r C1506_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:47724_qr_r, base_url=http://127.0.0.1:47724/qr_r}
[junit4:junit4] 2> 665280 T1363 C1506 P47724 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:47715/qr_r/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 665280 T1363 C1506 P47724 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:47724/qr_r START replicas=[http://127.0.0.1:47715/qr_r/collection1/] nUpdates=100
[junit4:junit4] 2> 665281 T1363 C1506 P47724 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 665281 T1363 C1506 P47724 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 665281 T1363 C1506 P47724 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 665282 T1363 C1506 P47724 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 665282 T1363 C1506 P47724 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 665282 T1363 C1506 P47724 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:47715/qr_r/collection1/. core=collection1
[junit4:junit4] 2> 665282 T1363 C1506 P47724 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1507 name=collection1 org.apache.solr.core.SolrCore@48f8d32e url=http://127.0.0.1:47715/qr_r/collection1 node=127.0.0.1:47715_qr_r C1507_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:47715_qr_r, base_url=http://127.0.0.1:47715/qr_r, leader=true}
[junit4:junit4] 2> 665290 T1303 C1507 P47715 oasc.SolrCore.execute [collection1] webapp=/qr_r path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 665293 T1304 C1507 P47715 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 665298 T1304 C1507 P47715 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 665299 T1304 C1507 P47715 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 665303 T1304 C1507 P47715 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 665303 T1304 C1507 P47715 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 665305 T1304 C1507 P47715 oass.SolrIndexSearcher.<init> Opening Searcher@68850e14 realtime
[junit4:junit4] 2> 665305 T1304 C1507 P47715 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 665306 T1304 C1507 P47715 oasup.LogUpdateProcessor.finish [collection1] webapp=/qr_r path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 13
[junit4:junit4] 2> 665307 T1363 C1506 P47724 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 665307 T1363 C1506 P47724 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 665309 T1305 C1507 P47715 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 665309 T1305 C1507 P47715 oasc.SolrCore.execute [collection1] webapp=/qr_r path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 665310 T1363 C1506 P47724 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 665310 T1363 C1506 P47724 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 665310 T1363 C1506 P47724 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 665314 T1305 C1507 P47715 oasc.SolrCore.execute [collection1] webapp=/qr_r path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 665314 T1363 C1506 P47724 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 665316 T1363 C1506 P47724 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty4/index.20130601111339293
[junit4:junit4] 2> 665317 T1363 C1506 P47724 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty4/index.20130601111339293 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4161bf5f fullCopy=false
[junit4:junit4] 2> 665321 T1305 C1507 P47715 oasc.SolrCore.execute [collection1] webapp=/qr_r path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 665323 T1363 C1506 P47724 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 665325 T1363 C1506 P47724 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 665326 T1363 C1506 P47724 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 665330 T1363 C1506 P47724 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty4/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 665331 T1363 C1506 P47724 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 665331 T1363 C1506 P47724 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 665332 T1363 C1506 P47724 oass.SolrIndexSearcher.<init> Opening Searcher@13746a10 main
[junit4:junit4] 2> 665334 T1362 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@13746a10 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 665334 T1363 C1506 P47724 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty4/index.20130601111339293 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty4/index.20130601111339293;done=true>>]
[junit4:junit4] 2> 665334 T1363 C1506 P47724 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty4/index.20130601111339293
[junit4:junit4] 2> 665335 T1363 C1506 P47724 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty4/index.20130601111339293
[junit4:junit4] 2> 665336 T1363 C1506 P47724 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 665336 T1363 C1506 P47724 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 665336 T1363 C1506 P47724 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 665336 T1363 C1506 P47724 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 665338 T1363 C1506 P47724 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 665430 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 665431 T1293 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:47728_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47728/qr_r"}
[junit4:junit4] 2> 665438 T1293 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:47724_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47724/qr_r"}
[junit4:junit4] 2> 665454 T1299 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> 665454 T1360 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> 665454 T1292 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> 665454 T1377 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> 665454 T1312 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> 665454 T1394 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> 665454 T1328 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> 665454 T1344 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> 665701 T1318 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 665701 T1318 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=6&state=recovering&nodeName=127.0.0.1:47728_qr_r&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 666249 T1270 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47732_qr_r
[junit4:junit4] 2> 666277 T1270 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47732_qr_r
[junit4:junit4] 2> 666280 T1299 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> 666280 T1292 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> 666280 T1328 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 666280 T1377 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> 666281 T1328 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> 666281 T1360 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 666280 T1344 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 666280 T1312 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 666280 T1394 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 666282 T1312 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> 666282 T1299 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 666282 T1344 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> 666282 T1360 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> 666283 T1292 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 666282 T1394 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> 666284 T1377 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 666293 T1397 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1370096018676/collection1
[junit4:junit4] 2> 666293 T1397 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 666294 T1397 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 666294 T1397 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 666296 T1397 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1370096018676/collection1/'
[junit4:junit4] 2> 666297 T1397 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1370096018676/collection1/lib/README' to classloader
[junit4:junit4] 2> 666298 T1397 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1370096018676/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 666378 T1397 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 666439 T1397 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 666541 T1397 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 666547 T1397 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 667191 T1397 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 667204 T1397 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 667208 T1397 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 667222 T1397 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 667228 T1397 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 667232 T1397 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 667233 T1397 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 667234 T1397 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 667234 T1397 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 667235 T1397 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 667235 T1397 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 667236 T1397 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 667236 T1397 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1370096018676/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty6/
[junit4:junit4] 2> 667236 T1397 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@407e75d2
[junit4:junit4] 2> 667237 T1397 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 667238 T1397 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty6
[junit4:junit4] 2> 667238 T1397 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty6/index/
[junit4:junit4] 2> 667239 T1397 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty6/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 667240 T1397 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty6/index
[junit4:junit4] 2> 667245 T1397 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 667246 T1397 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 667249 T1397 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 667249 T1397 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 667249 T1397 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 667250 T1397 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 667251 T1397 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 667251 T1397 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 667251 T1397 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 667252 T1397 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 667252 T1397 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 667261 T1397 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 667271 T1397 oass.SolrIndexSearcher.<init> Opening Searcher@46f9030c main
[junit4:junit4] 2> 667272 T1397 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 667272 T1397 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 667277 T1398 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@46f9030c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 667279 T1397 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 667279 T1397 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> ASYNC NEW_CORE C1508 name=collection1 org.apache.solr.core.SolrCore@3dd8d04b url=http://127.0.0.1:47728/qr_r/collection1 node=127.0.0.1:47728_qr_r C1508_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:47728_qr_r, base_url=http://127.0.0.1:47728/qr_r}
[junit4:junit4] 2> 667703 T1380 C1508 P47728 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:47718/qr_r/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 667703 T1380 C1508 P47728 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:47728/qr_r START replicas=[http://127.0.0.1:47718/qr_r/collection1/] nUpdates=100
[junit4:junit4] 2> 667704 T1380 C1508 P47728 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 667704 T1380 C1508 P47728 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 667704 T1380 C1508 P47728 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 667704 T1380 C1508 P47728 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 667704 T1380 C1508 P47728 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 667705 T1380 C1508 P47728 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:47718/qr_r/collection1/. core=collection1
[junit4:junit4] 2> 667705 T1380 C1508 P47728 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1509 name=collection1 org.apache.solr.core.SolrCore@3237d41c url=http://127.0.0.1:47718/qr_r/collection1 node=127.0.0.1:47718_qr_r C1509_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:47718_qr_r, base_url=http://127.0.0.1:47718/qr_r, leader=true}
[junit4:junit4] 2> 667712 T1319 C1509 P47718 oasc.SolrCore.execute [collection1] webapp=/qr_r path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 667722 T1320 C1509 P47718 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 667727 T1320 C1509 P47718 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 667728 T1320 C1509 P47718 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 667731 T1320 C1509 P47718 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 667732 T1320 C1509 P47718 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 667733 T1320 C1509 P47718 oass.SolrIndexSearcher.<init> Opening Searcher@36adafd7 realtime
[junit4:junit4] 2> 667734 T1320 C1509 P47718 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 667734 T1320 C1509 P47718 oasup.LogUpdateProcessor.finish [collection1] webapp=/qr_r path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 12
[junit4:junit4] 2> 667735 T1380 C1508 P47728 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 667735 T1380 C1508 P47728 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 667737 T1321 C1509 P47718 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 667737 T1321 C1509 P47718 oasc.SolrCore.execute [collection1] webapp=/qr_r path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 667738 T1380 C1508 P47728 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 667738 T1380 C1508 P47728 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 667738 T1380 C1508 P47728 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 667741 T1321 C1509 P47718 oasc.SolrCore.execute [collection1] webapp=/qr_r path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 667742 T1380 C1508 P47728 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 667743 T1380 C1508 P47728 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty5/index.20130601111341720
[junit4:junit4] 2> 667744 T1380 C1508 P47728 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty5/index.20130601111341720 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e716208 fullCopy=false
[junit4:junit4] 2> 667748 T1321 C1509 P47718 oasc.SolrCore.execute [collection1] webapp=/qr_r path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 667750 T1380 C1508 P47728 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 667752 T1380 C1508 P47728 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 667752 T1380 C1508 P47728 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 667757 T1380 C1508 P47728 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty5/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 667757 T1380 C1508 P47728 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 667758 T1380 C1508 P47728 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 667759 T1380 C1508 P47728 oass.SolrIndexSearcher.<init> Opening Searcher@6ffa3401 main
[junit4:junit4] 2> 667760 T1379 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6ffa3401 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 667760 T1380 C1508 P47728 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty5/index.20130601111341720 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty5/index.20130601111341720;done=true>>]
[junit4:junit4] 2> 667761 T1380 C1508 P47728 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty5/index.20130601111341720
[junit4:junit4] 2> 667761 T1380 C1508 P47728 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty5/index.20130601111341720
[junit4:junit4] 2> 667762 T1380 C1508 P47728 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 667762 T1380 C1508 P47728 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 667762 T1380 C1508 P47728 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 667762 T1380 C1508 P47728 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 667764 T1380 C1508 P47728 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 668469 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 668470 T1293 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:47732_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47732/qr_r"}
[junit4:junit4] 2> 668470 T1293 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 668470 T1293 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 668489 T1293 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:47728_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47728/qr_r"}
[junit4:junit4] 2> 668504 T1312 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> 668504 T1328 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> 668504 T1360 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> 668505 T1292 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> 668504 T1344 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> 668504 T1377 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> 668504 T1299 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> 668504 T1394 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> 669283 T1397 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 669283 T1397 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47732/qr_r collection:collection1 shard:shard3
[junit4:junit4] 2> 669287 T1397 oasc.ZkController.register We are http://127.0.0.1:47732/qr_r/collection1/ and leader is http://127.0.0.1:47721/qr_r/collection1/
[junit4:junit4] 2> 669287 T1397 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47732/qr_r
[junit4:junit4] 2> 669287 T1397 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 669287 T1397 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1510 name=collection1 org.apache.solr.core.SolrCore@27b2533d url=http://127.0.0.1:47732/qr_r/collection1 node=127.0.0.1:47732_qr_r C1510_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:47732_qr_r, base_url=http://127.0.0.1:47732/qr_r}
[junit4:junit4] 2> 669288 T1401 C1510 P47732 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 669288 T1397 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 669289 T1401 C1510 P47732 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 669289 T1401 C1510 P47732 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 669290 T1401 C1510 P47732 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 669290 T1270 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 669291 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 669291 T1401 C1510 P47732 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 669291 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 669310 T1334 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 669578 T1270 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 669581 T1270 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:47742
[junit4:junit4] 2> 669582 T1270 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 669582 T1270 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 669583 T1270 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1370096023287
[junit4:junit4] 2> 669583 T1270 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1370096023287/solr.xml
[junit4:junit4] 2> 669584 T1270 oasc.CoreContainer.<init> New CoreContainer 1231528934
[junit4:junit4] 2> 669584 T1270 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1370096023287/'
[junit4:junit4] 2> 669585 T1270 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1370096023287/'
[junit4:junit4] 2> 669708 T1270 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 669709 T1270 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 669709 T1270 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 669710 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 669710 T1270 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 669711 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 669711 T1270 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 669712 T1270 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 669712 T1270 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 669713 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 669730 T1270 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 669730 T1270 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:47708/solr
[junit4:junit4] 2> 669731 T1270 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 669732 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 669736 T1413 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6ba48686 name:ZooKeeperConnection Watcher:127.0.0.1:47708 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 669736 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 669752 T1270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 669765 T1270 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 669767 T1415 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2294143b name:ZooKeeperConnection Watcher:127.0.0.1:47708/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 669768 T1270 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 669773 T1270 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 670019 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 670020 T1293 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:47732_qr_r",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47732/qr_r"}
[junit4:junit4] 2> 670081 T1312 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> 670081 T1360 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> 670081 T1415 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> 670081 T1328 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> 670081 T1377 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> 670081 T1344 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> 670081 T1394 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> 670081 T1299 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> 670082 T1292 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> 670312 T1334 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 670312 T1334 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=7&state=recovering&nodeName=127.0.0.1:47732_qr_r&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 670777 T1270 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47742_qr_r
[junit4:junit4] 2> 670806 T1270 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47742_qr_r
[junit4:junit4] 2> 670809 T1299 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> 670809 T1292 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> 670809 T1312 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 670810 T1415 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 670809 T1377 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> 670810 T1415 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> 670810 T1312 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> 670810 T1360 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 670810 T1344 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 670810 T1328 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 670809 T1394 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 670812 T1328 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> 670811 T1292 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 670811 T1344 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> 670811 T1299 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 670813 T1377 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 670811 T1360 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> 670812 T1394 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> 670818 T1416 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1370096023287/collection1
[junit4:junit4] 2> 670819 T1416 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 670819 T1416 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 670819 T1416 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 670821 T1416 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1370096023287/collection1/'
[junit4:junit4] 2> 670822 T1416 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1370096023287/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 670823 T1416 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1370096023287/collection1/lib/README' to classloader
[junit4:junit4] 2> 670876 T1416 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 670937 T1416 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 671038 T1416 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 671044 T1416 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 671673 T1416 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 671682 T1416 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 671685 T1416 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 671697 T1416 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 671701 T1416 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 671704 T1416 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 671705 T1416 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 671706 T1416 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 671706 T1416 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 671707 T1416 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 671707 T1416 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 671707 T1416 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 671707 T1416 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1370096023287/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty7/
[junit4:junit4] 2> 671707 T1416 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@407e75d2
[junit4:junit4] 2> 671708 T1416 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 671709 T1416 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty7
[junit4:junit4] 2> 671710 T1416 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty7/index/
[junit4:junit4] 2> 671710 T1416 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty7/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 671711 T1416 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty7/index
[junit4:junit4] 2> 671715 T1416 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty7/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 671716 T1416 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 671718 T1416 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 671718 T1416 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 671718 T1416 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 671719 T1416 oasc.RequestHandlers.initHandlersFromConfig cr
[...truncated too long message...]
4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> 808892 T1491 oasu.PeerSync.handleResponse WARN PeerSync: core=collection1 url=http://127.0.0.1:25447/qr_r couldn't connect to http://127.0.0.1:47749/qr_r/collection1/, counting as success
[junit4:junit4] 2> 808892 T1491 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:25447/qr_r DONE. sync succeeded
[junit4:junit4] 2> 808893 T1491 oasc.SyncStrategy.syncReplicas We have been closed, won't attempt to sync replicas back to leader
[junit4:junit4] 2> 808893 T1491 oasc.ShardLeaderElectionContext.rejoinLeaderElection Not rejoining election because CoreContainer is shutdown
[junit4:junit4] 2> 808894 T1491 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@287ab5fe
[junit4:junit4] 2> 808895 T1491 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=83,cumulative_deletesById=41,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 808895 T1491 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 808895 T1491 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 808895 T1491 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 808898 T1491 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 808899 T1491 oasc.CachingDirectoryFactory.close Closing StandardDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 808900 T1491 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty11/index [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty11/index;done=false>>]
[junit4:junit4] 2> 808900 T1491 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty11/index
[junit4:junit4] 2> 808900 T1491 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty11 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty11;done=false>>]
[junit4:junit4] 2> 808900 T1491 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1370095993717/jetty11
[junit4:junit4] 2> 808901 T1491 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> 808901 T1491 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 808901 T1491 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 808901 T1491 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> 808902 T1491 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 808902 T1491 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {range_facet_l=PostingsFormat(name=TestBloomFilteredLucene41Postings), text=MockFixedIntBlock(blockSize=943), _version_=PostingsFormat(name=TestBloomFilteredLucene41Postings), rnd_b=PostingsFormat(name=Memory doPackFST= false), intDefault=PostingsFormat(name=TestBloomFilteredLucene41Postings), id=PostingsFormat(name=Memory doPackFST= false), timestamp=PostingsFormat(name=TestBloomFilteredLucene41Postings), a_t=PostingsFormat(name=TestBloomFilteredLucene41Postings), range_facet_sl=MockFixedIntBlock(blockSize=943), range_facet_si=PostingsFormat(name=SimpleText), other_tl1=PostingsFormat(name=TestBloomFilteredLucene41Postings), multiDefault=PostingsFormat(name=SimpleText), a_si=PostingsFormat(name=SimpleText)}, docValues:{}, sim=DefaultSimilarity, locale=et, timezone=Canada/Atlantic
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=4,free=177088064,total=408158208
[junit4:junit4] 2> NOTE: All tests run in this JVM: [PingRequestHandlerTest, DateMathParserTest, SolrPluginUtilsTest, DisMaxRequestHandlerTest, TestRecovery, SuggesterWFSTTest, TestCSVLoader, IndexReaderFactoryTest, ClusterStateTest, TestStressLucene, SampleTest, ZkSolrClientTest, NumericFieldsTest, TestBinaryResponseWriter, SuggesterTSTTest, CurrencyFieldOpenExchangeTest, TestSolr4Spatial, TestStressReorder, TestDynamicFieldCollectionResource, DirectUpdateHandlerTest, TestLazyCores, OpenCloseCoreStressTest, TestWordDelimiterFilterFactory, UpdateParamsTest, TestFoldingMultitermQuery, TestCSVResponseWriter, NotRequiredUniqueKeyTest, HighlighterTest, RequiredFieldsTest, DOMUtilTest, TestLuceneMatchVersion, TestManagedSchemaFieldResource, DefaultValueUpdateProcessorTest, CollectionsAPIDistributedZkTest, BasicZkTest, TestComponentsName, TestMergePolicyConfig, TestFiltering, TestPropInject, XmlUpdateRequestHandlerTest, TestJmxMonitoredMap, OpenExchangeRatesOrgProviderTest, TestSystemIdResolver, DirectSolrSpellCheckerTest, TestLMJelinekMercerSimilarityFactory, SolrCmdDistributorTest, TestRTGBase, TestUpdate, BadIndexSchemaTest, SignatureUpdateProcessorFactoryTest, ChaosMonkeySafeLeaderTest]
[junit4:junit4] Completed on J1 in 169.21s, 1 test, 1 failure <<< FAILURES!
[...truncated 577 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:386: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:366: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:887: There were test failures: 297 suites, 1238 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 51 minutes 56 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure