lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Policeman Jenkins Server <jenk...@thetaphi.de>
Subject [JENKINS] Lucene-Solr-trunk-Linux (32bit/ibm-j9-jdk7) - Build # 5969 - Failure!
Date Mon, 03 Jun 2013 20:29:40 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/5969/
Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}

1 tests failed.
FAILED:  org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearch

Error Message:
Server at http://127.0.0.1:40725/rd/o/onenodecollectioncore returned non ok status:404, message:Can not find: /rd/o/onenodecollectioncore/update

Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:40725/rd/o/onenodecollectioncore returned non ok status:404, message:Can not find: /rd/o/onenodecollectioncore/update
	at __randomizedtesting.SeedInfo.seed([D773097047B60FDD:5695876830E96FE1]:0)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
	at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
	at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:198)
	at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:90)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
	at java.lang.reflect.Method.invoke(Method.java:613)
	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:780)




Build Log:
[...truncated 9583 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4]   2> 473304 T1452 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /rd/o
[junit4:junit4]   2> 473308 T1452 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370290581649
[junit4:junit4]   2> 473309 T1452 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 473310 T1453 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 473410 T1452 oasc.ZkTestServer.run start zk server on port:50531
[junit4:junit4]   2> 473411 T1452 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 473444 T1459 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f6b86d25 name:ZooKeeperConnection Watcher:127.0.0.1:50531 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 473445 T1452 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 473445 T1452 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 473462 T1452 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 473463 T1461 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@17b5dab7 name:ZooKeeperConnection Watcher:127.0.0.1:50531/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 473463 T1452 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 473464 T1452 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 473466 T1452 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 473468 T1452 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 473469 T1452 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 473471 T1452 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 473472 T1452 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 473475 T1452 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 473476 T1452 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 473478 T1452 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 473479 T1452 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 473481 T1452 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 473481 T1452 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 473483 T1452 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 473484 T1452 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 473486 T1452 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 473486 T1452 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 473488 T1452 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 473489 T1452 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 473491 T1452 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 473492 T1452 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 473493 T1452 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 473494 T1452 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 473565 T1452 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 473568 T1452 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:39522
[junit4:junit4]   2> 473569 T1452 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 473569 T1452 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 473570 T1452 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370290581836
[junit4:junit4]   2> 473571 T1452 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370290581836/solr.xml
[junit4:junit4]   2> 473571 T1452 oasc.CoreContainer.<init> New CoreContainer 1330369037
[junit4:junit4]   2> 473572 T1452 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370290581836/'
[junit4:junit4]   2> 473572 T1452 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370290581836/'
[junit4:junit4]   2> 473610 T1452 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 473611 T1452 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 473611 T1452 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 473612 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 473612 T1452 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 473613 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 473614 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 473614 T1452 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 473615 T1452 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 473615 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 473620 T1452 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 473621 T1452 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50531/solr
[junit4:junit4]   2> 473621 T1452 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 473622 T1452 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 473624 T1472 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@53d73f85 name:ZooKeeperConnection Watcher:127.0.0.1:50531 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 473624 T1452 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 473625 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 473631 T1452 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 473632 T1474 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7f0de9c8 name:ZooKeeperConnection Watcher:127.0.0.1:50531/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 473632 T1452 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 473633 T1452 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 473636 T1452 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 473638 T1452 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 473640 T1452 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39522_rd%2Fo
[junit4:junit4]   2> 473641 T1452 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39522_rd%2Fo
[junit4:junit4]   2> 473643 T1452 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 473647 T1452 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 473649 T1452 oasc.Overseer.start Overseer (id=89803363559145475-127.0.0.1:39522_rd%2Fo-n_0000000000) starting
[junit4:junit4]   2> 473652 T1452 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 473701 T1452 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 473701 T1476 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 473703 T1452 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 473705 T1452 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 473707 T1475 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 473709 T1477 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370290581836/collection1
[junit4:junit4]   2> 473709 T1477 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 473710 T1477 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 473710 T1477 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 473711 T1477 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370290581836/collection1/'
[junit4:junit4]   2> 473712 T1477 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370290581836/collection1/lib/README' to classloader
[junit4:junit4]   2> 473712 T1477 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370290581836/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 473735 T1477 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 473764 T1477 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 473766 T1477 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 473770 T1477 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 474102 T1477 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 474107 T1477 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 474109 T1477 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 474119 T1477 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 474123 T1477 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 474126 T1477 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 474127 T1477 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 474128 T1477 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 474128 T1477 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 474129 T1477 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 474129 T1477 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 474130 T1477 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 474130 T1477 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370290581836/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/control/data/
[junit4:junit4]   2> 474130 T1477 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@89a4e18
[junit4:junit4]   2> 474131 T1477 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 474132 T1477 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/control/data
[junit4:junit4]   2> 474132 T1477 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/control/data/index/
[junit4:junit4]   2> 474132 T1477 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 474133 T1477 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/control/data/index
[junit4:junit4]   2> 474134 T1477 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@99e27de0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5037b33c),segFN=segments_1,generation=1}
[junit4:junit4]   2> 474135 T1477 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 474136 T1477 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 474136 T1477 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 474137 T1477 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 474137 T1477 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 474138 T1477 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 474138 T1477 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 474139 T1477 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 474139 T1477 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 474139 T1477 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 474141 T1477 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 474142 T1477 oass.SolrIndexSearcher.<init> Opening Searcher@ddf83700 main
[junit4:junit4]   2> 474143 T1477 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/control/data/tlog
[junit4:junit4]   2> 474143 T1477 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 474144 T1477 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 474146 T1478 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ddf83700 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 474147 T1477 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 474147 T1477 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 475210 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 475210 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39522/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39522_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 475211 T1475 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 475211 T1475 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 475214 T1474 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> 476149 T1477 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 476149 T1477 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39522/rd/o collection:control_collection shard:shard1
[junit4:junit4]   2> 476150 T1477 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 476155 T1477 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 476157 T1477 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 476157 T1477 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 476158 T1477 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:39522/rd/o/collection1/
[junit4:junit4]   2> 476158 T1477 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 476158 T1477 oasc.SyncStrategy.syncToMe http://127.0.0.1:39522/rd/o/collection1/ has no replicas
[junit4:junit4]   2> 476159 T1477 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:39522/rd/o/collection1/
[junit4:junit4]   2> 476159 T1477 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 476716 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 476721 T1474 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> 476764 T1477 oasc.ZkController.register We are http://127.0.0.1:39522/rd/o/collection1/ and leader is http://127.0.0.1:39522/rd/o/collection1/
[junit4:junit4]   2> 476765 T1477 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39522/rd/o
[junit4:junit4]   2> 476765 T1477 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 476766 T1477 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 476766 T1477 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 476768 T1477 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 476769 T1452 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 476770 T1452 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 476771 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 476775 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 476777 T1452 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 476778 T1481 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ba9dd7ed name:ZooKeeperConnection Watcher:127.0.0.1:50531/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 476778 T1452 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 476779 T1452 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 476781 T1452 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 476872 T1452 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 476875 T1452 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:41244
[junit4:junit4]   2> 476877 T1452 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 476878 T1452 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 476878 T1452 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370290585122
[junit4:junit4]   2> 476879 T1452 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370290585122/solr.xml
[junit4:junit4]   2> 476880 T1452 oasc.CoreContainer.<init> New CoreContainer 644223873
[junit4:junit4]   2> 476881 T1452 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370290585122/'
[junit4:junit4]   2> 476882 T1452 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370290585122/'
[junit4:junit4]   2> 476922 T1452 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 476923 T1452 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 476923 T1452 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 476924 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 476924 T1452 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 476925 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 476926 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 476926 T1452 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 476927 T1452 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 476928 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 476932 T1452 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 476933 T1452 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50531/solr
[junit4:junit4]   2> 476934 T1452 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 476936 T1452 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 476937 T1492 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@30239f60 name:ZooKeeperConnection Watcher:127.0.0.1:50531 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 476937 T1452 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 476939 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 476944 T1452 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 476945 T1494 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3c87a6a0 name:ZooKeeperConnection Watcher:127.0.0.1:50531/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 476946 T1452 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 476949 T1452 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 477952 T1452 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41244_rd%2Fo
[junit4:junit4]   2> 477953 T1452 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:41244_rd%2Fo
[junit4:junit4]   2> 477956 T1474 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 477956 T1494 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 477956 T1474 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> 477956 T1481 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 477961 T1495 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370290585122/collection1
[junit4:junit4]   2> 477961 T1495 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 477962 T1495 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 477962 T1495 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 477964 T1495 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370290585122/collection1/'
[junit4:junit4]   2> 477964 T1495 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370290585122/collection1/lib/README' to classloader
[junit4:junit4]   2> 477965 T1495 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370290585122/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 477988 T1495 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 478018 T1495 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 478019 T1495 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 478023 T1495 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 478224 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 478225 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39522/rd/o",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:39522_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39522_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 478228 T1474 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> 478228 T1494 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> 478228 T1481 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> 478331 T1495 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 478336 T1495 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 478338 T1495 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 478352 T1495 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 478356 T1495 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 478360 T1495 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 478360 T1495 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 478361 T1495 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 478361 T1495 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 478362 T1495 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 478362 T1495 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 478363 T1495 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 478363 T1495 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370290585122/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty1/
[junit4:junit4]   2> 478363 T1495 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@89a4e18
[junit4:junit4]   2> 478364 T1495 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 478365 T1495 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty1
[junit4:junit4]   2> 478365 T1495 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty1/index/
[junit4:junit4]   2> 478365 T1495 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 478366 T1495 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty1/index
[junit4:junit4]   2> 478367 T1495 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a0eacc03 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6af8240b),segFN=segments_1,generation=1}
[junit4:junit4]   2> 478368 T1495 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 478369 T1495 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 478370 T1495 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 478370 T1495 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 478371 T1495 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 478371 T1495 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 478371 T1495 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 478372 T1495 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 478372 T1495 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 478373 T1495 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 478374 T1495 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 478376 T1495 oass.SolrIndexSearcher.<init> Opening Searcher@181c28c1 main
[junit4:junit4]   2> 478376 T1495 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty1/tlog
[junit4:junit4]   2> 478377 T1495 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 478377 T1495 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 478383 T1496 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@181c28c1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 478385 T1495 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 478385 T1495 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 479733 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 479734 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:41244/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:41244_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 479734 T1475 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 479734 T1475 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 479739 T1474 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> 479739 T1481 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> 479740 T1494 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> 480387 T1495 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 480387 T1495 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:41244/rd/o collection:collection1 shard:shard1
[junit4:junit4]   2> 480388 T1495 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 480394 T1495 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 480397 T1495 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 480397 T1495 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 480397 T1495 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:41244/rd/o/collection1/
[junit4:junit4]   2> 480398 T1495 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 480398 T1495 oasc.SyncStrategy.syncToMe http://127.0.0.1:41244/rd/o/collection1/ has no replicas
[junit4:junit4]   2> 480398 T1495 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:41244/rd/o/collection1/
[junit4:junit4]   2> 480399 T1495 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 481242 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 481250 T1481 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> 481250 T1474 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> 481250 T1494 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> 481257 T1495 oasc.ZkController.register We are http://127.0.0.1:41244/rd/o/collection1/ and leader is http://127.0.0.1:41244/rd/o/collection1/
[junit4:junit4]   2> 481258 T1495 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:41244/rd/o
[junit4:junit4]   2> 481258 T1495 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 481258 T1495 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 481259 T1495 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 481260 T1495 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 481261 T1452 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 481262 T1452 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 481263 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 481336 T1452 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 481338 T1452 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40725
[junit4:junit4]   2> 481339 T1452 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 481340 T1452 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 481340 T1452 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370290589607
[junit4:junit4]   2> 481341 T1452 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370290589607/solr.xml
[junit4:junit4]   2> 481341 T1452 oasc.CoreContainer.<init> New CoreContainer -1512862023
[junit4:junit4]   2> 481342 T1452 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370290589607/'
[junit4:junit4]   2> 481343 T1452 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370290589607/'
[junit4:junit4]   2> 481389 T1452 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 481389 T1452 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 481390 T1452 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 481391 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 481391 T1452 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 481392 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 481392 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 481393 T1452 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 481394 T1452 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 481394 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 481399 T1452 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 481400 T1452 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50531/solr
[junit4:junit4]   2> 481401 T1452 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 481402 T1452 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 481403 T1508 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ee2131e0 name:ZooKeeperConnection Watcher:127.0.0.1:50531 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 481404 T1452 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 481405 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 481411 T1452 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 481412 T1510 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6cd13ee3 name:ZooKeeperConnection Watcher:127.0.0.1:50531/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 481412 T1452 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 481416 T1452 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 482419 T1452 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40725_rd%2Fo
[junit4:junit4]   2> 482420 T1452 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40725_rd%2Fo
[junit4:junit4]   2> 482422 T1494 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> 482422 T1481 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> 482423 T1474 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 482423 T1510 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 482423 T1474 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> 482425 T1494 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 482425 T1481 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 482430 T1511 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370290589607/collection1
[junit4:junit4]   2> 482430 T1511 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 482431 T1511 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 482431 T1511 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 482432 T1511 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370290589607/collection1/'
[junit4:junit4]   2> 482433 T1511 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370290589607/collection1/lib/README' to classloader
[junit4:junit4]   2> 482434 T1511 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370290589607/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 482460 T1511 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 482492 T1511 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 482493 T1511 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 482498 T1511 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 482754 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 482755 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:41244/rd/o",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:41244_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:41244_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 482757 T1474 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> 482757 T1481 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> 482757 T1494 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> 482758 T1510 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> 482828 T1511 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 482833 T1511 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 482836 T1511 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 482845 T1511 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 482848 T1511 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 482852 T1511 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 482853 T1511 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 482853 T1511 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 482853 T1511 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 482854 T1511 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 482855 T1511 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 482855 T1511 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 482855 T1511 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370290589607/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty2/
[junit4:junit4]   2> 482856 T1511 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@89a4e18
[junit4:junit4]   2> 482856 T1511 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 482857 T1511 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty2
[junit4:junit4]   2> 482857 T1511 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty2/index/
[junit4:junit4]   2> 482857 T1511 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 482858 T1511 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty2/index
[junit4:junit4]   2> 482859 T1511 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@11b02d85 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f4f63752),segFN=segments_1,generation=1}
[junit4:junit4]   2> 482859 T1511 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 482861 T1511 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 482861 T1511 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 482861 T1511 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 482862 T1511 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 482863 T1511 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 482863 T1511 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 482863 T1511 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 482864 T1511 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 482864 T1511 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 482865 T1511 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 482867 T1511 oass.SolrIndexSearcher.<init> Opening Searcher@87ecc201 main
[junit4:junit4]   2> 482867 T1511 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty2/tlog
[junit4:junit4]   2> 482868 T1511 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 482868 T1511 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 482872 T1512 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@87ecc201 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 482873 T1511 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 482874 T1511 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 484262 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 484263 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40725/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40725_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 484263 T1475 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 484263 T1475 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4]   2> 484267 T1510 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> 484267 T1494 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> 484267 T1481 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> 484267 T1474 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> 484876 T1511 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 484877 T1511 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40725/rd/o collection:collection1 shard:shard2
[junit4:junit4]   2> 484878 T1511 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 484883 T1511 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 484884 T1511 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 484885 T1511 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 484885 T1511 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:40725/rd/o/collection1/
[junit4:junit4]   2> 484885 T1511 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 484886 T1511 oasc.SyncStrategy.syncToMe http://127.0.0.1:40725/rd/o/collection1/ has no replicas
[junit4:junit4]   2> 484886 T1511 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:40725/rd/o/collection1/
[junit4:junit4]   2> 484886 T1511 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 485772 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 485780 T1494 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> 485780 T1481 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> 485780 T1474 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> 485780 T1510 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> 485794 T1511 oasc.ZkController.register We are http://127.0.0.1:40725/rd/o/collection1/ and leader is http://127.0.0.1:40725/rd/o/collection1/
[junit4:junit4]   2> 485794 T1511 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40725/rd/o
[junit4:junit4]   2> 485795 T1511 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 485795 T1511 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 485795 T1511 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 485797 T1511 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 485798 T1452 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 485799 T1452 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 485800 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 485895 T1452 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 485898 T1452 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:34704
[junit4:junit4]   2> 485899 T1452 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 485900 T1452 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 485900 T1452 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370290594148
[junit4:junit4]   2> 485901 T1452 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370290594148/solr.xml
[junit4:junit4]   2> 485902 T1452 oasc.CoreContainer.<init> New CoreContainer -1325273604
[junit4:junit4]   2> 485903 T1452 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370290594148/'
[junit4:junit4]   2> 485903 T1452 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370290594148/'
[junit4:junit4]   2> 485953 T1452 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 485954 T1452 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 485955 T1452 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 485956 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 485956 T1452 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 485957 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 485958 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 485959 T1452 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 485960 T1452 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 485960 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 485966 T1452 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 485968 T1452 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50531/solr
[junit4:junit4]   2> 485968 T1452 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 485970 T1452 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 485972 T1524 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@445781e9 name:ZooKeeperConnection Watcher:127.0.0.1:50531 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 485972 T1452 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 485974 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 485979 T1452 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 485980 T1526 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@baaf0409 name:ZooKeeperConnection Watcher:127.0.0.1:50531/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 485981 T1452 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 485985 T1452 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 486988 T1452 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34704_rd%2Fo
[junit4:junit4]   2> 486990 T1452 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34704_rd%2Fo
[junit4:junit4]   2> 486992 T1494 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> 486992 T1481 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> 486993 T1474 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 486993 T1526 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 486993 T1510 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 486994 T1474 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> 486994 T1494 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 486994 T1481 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 486994 T1510 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> 486998 T1527 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370290594148/collection1
[junit4:junit4]   2> 486998 T1527 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 486999 T1527 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 486999 T1527 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 487000 T1527 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370290594148/collection1/'
[junit4:junit4]   2> 487000 T1527 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370290594148/collection1/lib/README' to classloader
[junit4:junit4]   2> 487001 T1527 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370290594148/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 487034 T1527 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 487063 T1527 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 487065 T1527 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 487069 T1527 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 487284 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 487285 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40725/rd/o",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:40725_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40725_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 487289 T1510 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> 487289 T1481 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> 487289 T1526 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> 487289 T1474 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> 487289 T1494 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> 487381 T1527 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 487386 T1527 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 487389 T1527 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 487398 T1527 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 487402 T1527 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 487405 T1527 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 487407 T1527 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 487407 T1527 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 487407 T1527 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 487408 T1527 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 487408 T1527 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 487409 T1527 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 487409 T1527 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370290594148/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3/
[junit4:junit4]   2> 487409 T1527 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@89a4e18
[junit4:junit4]   2> 487410 T1527 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 487411 T1527 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3
[junit4:junit4]   2> 487411 T1527 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3/index/
[junit4:junit4]   2> 487411 T1527 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 487412 T1527 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3/index
[junit4:junit4]   2> 487413 T1527 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e3c1b9b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7544e458),segFN=segments_1,generation=1}
[junit4:junit4]   2> 487414 T1527 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 487415 T1527 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 487415 T1527 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 487416 T1527 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 487417 T1527 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 487417 T1527 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 487417 T1527 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 487418 T1527 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 487418 T1527 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 487418 T1527 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 487420 T1527 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 487422 T1527 oass.SolrIndexSearcher.<init> Opening Searcher@2af3efb8 main
[junit4:junit4]   2> 487422 T1527 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3/tlog
[junit4:junit4]   2> 487423 T1527 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 487423 T1527 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 487428 T1528 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2af3efb8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 487430 T1527 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 487430 T1527 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 488794 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 488795 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:34704/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:34704_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 488795 T1475 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 488795 T1475 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 488798 T1474 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> 488798 T1481 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> 488798 T1526 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> 488798 T1510 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> 488798 T1494 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> 489432 T1527 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 489432 T1527 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34704/rd/o collection:collection1 shard:shard1
[junit4:junit4]   2> 489436 T1527 oasc.ZkController.register We are http://127.0.0.1:34704/rd/o/collection1/ and leader is http://127.0.0.1:41244/rd/o/collection1/
[junit4:junit4]   2> 489436 T1527 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34704/rd/o
[junit4:junit4]   2> 489436 T1527 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 489437 T1527 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C510 name=collection1 org.apache.solr.core.SolrCore@c3cde8e0 url=http://127.0.0.1:34704/rd/o/collection1 node=127.0.0.1:34704_rd%2Fo C510_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:34704/rd/o, state=down, node_name=127.0.0.1:34704_rd%2Fo, collection=collection1, core=collection1}
[junit4:junit4]   2> 489438 T1529 C510 P34704 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 489438 T1527 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 489438 T1529 C510 P34704 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 489439 T1529 C510 P34704 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 489439 T1529 C510 P34704 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 489439 T1452 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 489440 T1452 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 489440 T1529 C510 P34704 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 489441 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 489447 T1490 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:34704_rd%2Fo_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 489518 T1452 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 489520 T1452 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:38542
[junit4:junit4]   2> 489521 T1452 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 489521 T1452 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 489522 T1452 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370290597786
[junit4:junit4]   2> 489523 T1452 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370290597786/solr.xml
[junit4:junit4]   2> 489523 T1452 oasc.CoreContainer.<init> New CoreContainer 2139745576
[junit4:junit4]   2> 489524 T1452 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370290597786/'
[junit4:junit4]   2> 489524 T1452 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370290597786/'
[junit4:junit4]   2> 489563 T1452 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 489563 T1452 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 489564 T1452 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 489564 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 489565 T1452 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 489566 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 489566 T1452 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 489567 T1452 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 489567 T1452 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 489568 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 489572 T1452 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 489573 T1452 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50531/solr
[junit4:junit4]   2> 489574 T1452 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 489575 T1452 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 489579 T1541 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4169d6c3 name:ZooKeeperConnection Watcher:127.0.0.1:50531 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 489579 T1452 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 489581 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 489586 T1452 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 489587 T1543 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7639c568 name:ZooKeeperConnection Watcher:127.0.0.1:50531/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 489588 T1452 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 489591 T1452 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 490301 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 490302 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:34704/rd/o",
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:34704_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:34704_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 490306 T1494 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> 490306 T1481 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> 490306 T1526 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> 490306 T1510 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> 490306 T1474 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> 490306 T1543 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> 490448 T1490 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:34704_rd%2Fo_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4]   2> 490449 T1490 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=127.0.0.1:34704_rd%252Fo_collection1&wt=javabin&nodeName=127.0.0.1:34704_rd%252Fo&core=collection1} status=0 QTime=1002 
[junit4:junit4]   2> 490594 T1452 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38542_rd%2Fo
[junit4:junit4]   2> 490596 T1452 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38542_rd%2Fo
[junit4:junit4]   2> 490598 T1526 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> 490598 T1494 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> 490599 T1510 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 490599 T1474 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 490600 T1526 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 490599 T1481 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> 490600 T1474 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> 490600 T1510 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> 490601 T1494 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 490599 T1543 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> 490602 T1481 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 490604 T1543 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 490606 T1544 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370290597786/collection1
[junit4:junit4]   2> 490606 T1544 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 490607 T1544 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 490607 T1544 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 490608 T1544 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370290597786/collection1/'
[junit4:junit4]   2> 490609 T1544 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370290597786/collection1/lib/README' to classloader
[junit4:junit4]   2> 490610 T1544 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370290597786/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 490636 T1544 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 490676 T1544 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 490677 T1544 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 490681 T1544 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 491005 T1544 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 491010 T1544 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 491013 T1544 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 491023 T1544 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 491027 T1544 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 491031 T1544 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 491032 T1544 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 491032 T1544 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 491033 T1544 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 491034 T1544 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 491034 T1544 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 491035 T1544 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 491035 T1544 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370290597786/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4/
[junit4:junit4]   2> 491035 T1544 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@89a4e18
[junit4:junit4]   2> 491036 T1544 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 491036 T1544 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4
[junit4:junit4]   2> 491037 T1544 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4/index/
[junit4:junit4]   2> 491037 T1544 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 491037 T1544 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4/index
[junit4:junit4]   2> 491039 T1544 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@79e078df lockFactory=org.apache.lucene.store.NativeFSLockFactory@fae3e18),segFN=segments_1,generation=1}
[junit4:junit4]   2> 491039 T1544 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 491041 T1544 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 491041 T1544 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 491042 T1544 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 491042 T1544 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 491043 T1544 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 491043 T1544 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 491043 T1544 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 491044 T1544 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 491044 T1544 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 491045 T1544 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 491047 T1544 oass.SolrIndexSearcher.<init> Opening Searcher@d6a337d4 main
[junit4:junit4]   2> 491048 T1544 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4/tlog
[junit4:junit4]   2> 491048 T1544 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 491049 T1544 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 491053 T1545 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d6a337d4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 491055 T1544 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 491055 T1544 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 491810 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 491811 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:38542/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:38542_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 491811 T1475 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 491811 T1475 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4]   2> 491815 T1474 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> 491815 T1543 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> 491815 T1494 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> 491815 T1481 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> 491815 T1526 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> 491815 T1510 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> 492056 T1544 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 492057 T1544 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38542/rd/o collection:collection1 shard:shard2
[junit4:junit4]   2> 492060 T1544 oasc.ZkController.register We are http://127.0.0.1:38542/rd/o/collection1/ and leader is http://127.0.0.1:40725/rd/o/collection1/
[junit4:junit4]   2> 492060 T1544 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38542/rd/o
[junit4:junit4]   2> 492061 T1544 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 492061 T1544 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C511 name=collection1 org.apache.solr.core.SolrCore@56d800ae url=http://127.0.0.1:38542/rd/o/collection1 node=127.0.0.1:38542_rd%2Fo C511_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:38542/rd/o, state=down, node_name=127.0.0.1:38542_rd%2Fo, collection=collection1, core=collection1}
[junit4:junit4]   2> 492061 T1546 C511 P38542 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 492062 T1544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 492062 T1546 C511 P38542 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 492062 T1546 C511 P38542 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 492063 T1546 C511 P38542 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 492063 T1452 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 492064 T1452 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 492064 T1546 C511 P38542 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 492064 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 492071 T1452 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 492071 T1504 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:38542_rd%2Fo_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 492073 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 492078 T1490 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370290585122/onenodecollectioncore
[junit4:junit4]   2> 492079 T1490 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4]   2> 492080 T1490 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4]   2> 492080 T1490 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 492082 T1490 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 492082 T1490 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4]   2> 492084 T1490 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4]   2> 492085 T1490 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370290585122/onenodecollectioncore/'
[junit4:junit4]   2> 492109 T1490 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 492140 T1490 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 492141 T1490 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 492146 T1490 oass.IndexSchema.readSchema [onenodecollectioncore] Schema name=test
[junit4:junit4]   2> ASYNC  NEW_CORE C512 name=collection1 org.apache.solr.core.SolrCore@c3cde8e0 url=http://127.0.0.1:34704/rd/o/collection1 node=127.0.0.1:34704_rd%2Fo C512_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:34704/rd/o, state=recovering, node_name=127.0.0.1:34704_rd%2Fo, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4]   2> 492450 T1529 C512 P34704 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:41244/rd/o/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 492450 T1529 C512 P34704 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34704/rd/o START replicas=[http://127.0.0.1:41244/rd/o/collection1/] nUpdates=100
[junit4:junit4]   2> 492451 T1529 C512 P34704 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 492451 T1529 C512 P34704 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 492451 T1529 C512 P34704 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 492451 T1529 C512 P34704 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 492452 T1529 C512 P34704 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 492452 T1529 C512 P34704 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:41244/rd/o/collection1/. core=collection1
[junit4:junit4]   2> 492452 T1529 C512 P34704 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 492477 T1490 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> ASYNC  NEW_CORE C513 name=collection1 org.apache.solr.core.SolrCore@362387d4 url=http://127.0.0.1:41244/rd/o/collection1 node=127.0.0.1:41244_rd%2Fo C513_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:41244/rd/o, state=active, node_name=127.0.0.1:41244_rd%2Fo, collection=collection1, shard=shard1, core=collection1, leader=true}
[junit4:junit4]   2> 492482 T1488 C513 P41244 oasc.SolrCore.execute [collection1] webapp=/rd/o path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=24 
[junit4:junit4]   2> 492482 T1489 C513 P41244 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 492484 T1489 C513 P41244 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a0eacc03 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6af8240b),segFN=segments_1,generation=1}
[junit4:junit4]   2> 492485 T1489 C513 P41244 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 492484 T1490 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 492485 T1489 C513 P41244 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a0eacc03 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6af8240b),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a0eacc03 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6af8240b),segFN=segments_2,generation=2}
[junit4:junit4]   2> 492486 T1489 C513 P41244 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 492487 T1489 C513 P41244 oass.SolrIndexSearcher.<init> Opening Searcher@1a1ac980 realtime
[junit4:junit4]   2> 492488 T1489 C513 P41244 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 492488 T1489 C513 P41244 oasup.LogUpdateProcessor.finish [collection1] webapp=/rd/o path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 26
[junit4:junit4]   2> 492488 T1490 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 492489 T1529 C512 P34704 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 492490 T1529 C512 P34704 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 492491 T1489 C513 P41244 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 492492 T1489 C513 P41244 oasc.SolrCore.execute [collection1] webapp=/rd/o path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=2 
[junit4:junit4]   2> 492492 T1529 C512 P34704 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 492493 T1529 C512 P34704 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 492493 T1529 C512 P34704 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 492495 T1487 C513 P41244 oasc.SolrCore.execute [collection1] webapp=/rd/o path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=0 
[junit4:junit4]   2> 492496 T1529 C512 P34704 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 492497 T1529 C512 P34704 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3/index.20130603161640836
[junit4:junit4]   2> 492497 T1529 C512 P34704 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@92f6e01e lockFactory=org.apache.lucene.store.NativeFSLockFactory@a382ac9f) fullCopy=false
[junit4:junit4]   2> 492499 T1490 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 492499 T1488 C513 P41244 oasc.SolrCore.execute [collection1] webapp=/rd/o path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=0 
[junit4:junit4]   2> 492501 T1529 C512 P34704 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 492501 T1529 C512 P34704 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 492502 T1529 C512 P34704 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 492503 T1529 C512 P34704 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e3c1b9b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7544e458),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e3c1b9b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7544e458),segFN=segments_2,generation=2}
[junit4:junit4]   2> 492503 T1529 C512 P34704 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 492504 T1529 C512 P34704 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 492504 T1490 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 492504 T1529 C512 P34704 oass.SolrIndexSearcher.<init> Opening Searcher@e76fce65 main
[junit4:junit4]   2> 492506 T1528 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e76fce65 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 492506 T1529 C512 P34704 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3/index.20130603161640836 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3/index.20130603161640836;done=true>>]
[junit4:junit4]   2> 492507 T1529 C512 P34704 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3/index.20130603161640836
[junit4:junit4]   2> 492507 T1529 C512 P34704 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3/index.20130603161640836
[junit4:junit4]   2> 492508 T1529 C512 P34704 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 492508 T1529 C512 P34704 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 492508 T1529 C512 P34704 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 492509 T1529 C512 P34704 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 492509 T1490 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 492510 T1529 C512 P34704 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 492511 T1490 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 492511 T1490 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 492512 T1490 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 492513 T1490 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 492514 T1490 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 492514 T1490 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 492515 T1490 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370290585122/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370290581649/onenodecollection/
[junit4:junit4]   2> 492516 T1490 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@89a4e18
[junit4:junit4]   2> 492516 T1490 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 492518 T1490 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370290581649/onenodecollection
[junit4:junit4]   2> 492518 T1490 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370290581649/onenodecollection/index/
[junit4:junit4]   2> 492519 T1490 oasc.SolrCore.initIndex WARN [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370290581649/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 492519 T1490 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370290581649/onenodecollection/index
[junit4:junit4]   2> 492521 T1490 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@97a231bd lockFactory=org.apache.lucene.store.NativeFSLockFactory@f369dea2),segFN=segments_1,generation=1}
[junit4:junit4]   2> 492522 T1490 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 492524 T1490 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 492524 T1490 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 492525 T1490 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 492526 T1490 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 492527 T1490 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 492527 T1490 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 492528 T1490 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 492528 T1490 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 492529 T1490 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 492531 T1490 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 492533 T1490 oass.SolrIndexSearcher.<init> Opening Searcher@7cd244c7 main
[junit4:junit4]   2> 492534 T1490 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370290581649/onenodecollection/tlog
[junit4:junit4]   2> 492535 T1490 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 492535 T1490 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 492540 T1550 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@7cd244c7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 492540 T1490 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 493319 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 493320 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:38542/rd/o",
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:38542_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:38542_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 493323 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:34704/rd/o",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:34704_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:34704_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 493325 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:41244/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:41244_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"onenodecollectioncore"}
[junit4:junit4]   2> 493325 T1475 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4]   2> 493326 T1475 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 493328 T1474 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> 493328 T1543 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> 493329 T1526 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> 493328 T1510 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> 493329 T1494 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> 493329 T1481 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> 493542 T1490 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4]   2> 493543 T1490 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:41244/rd/o collection:onenodecollection shard:shard1
[junit4:junit4]   2> 493544 T1490 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4]   2> 493550 T1490 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 493552 T1490 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 493553 T1490 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 493554 T1490 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:41244/rd/o/onenodecollectioncore/
[junit4:junit4]   2> 493555 T1490 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 493556 T1490 oasc.SyncStrategy.syncToMe http://127.0.0.1:41244/rd/o/onenodecollectioncore/ has no replicas
[junit4:junit4]   2> 493556 T1490 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:41244/rd/o/onenodecollectioncore/
[junit4:junit4]   2> 493557 T1490 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4]   2> 494073 T1504 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:38542_rd%2Fo_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4]   2> 494074 T1504 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=127.0.0.1:38542_rd%252Fo_collection1&wt=javabin&nodeName=127.0.0.1:38542_rd%252Fo&core=collection1} status=0 QTime=2003 
[junit4:junit4]   2> 494839 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 494844 T1543 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> 494844 T1510 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> 494845 T1494 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> 494845 T1481 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> 494844 T1526 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> 494845 T1474 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> 494865 T1490 oasc.ZkController.register We are http://127.0.0.1:41244/rd/o/onenodecollectioncore/ and leader is http://127.0.0.1:41244/rd/o/onenodecollectioncore/
[junit4:junit4]   2> 494866 T1490 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:41244/rd/o
[junit4:junit4]   2> 494867 T1490 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 494867 T1490 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4]   2> 494869 T1490 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 494870 T1490 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370290581649/onenodecollection&action=CREATE&version=2&numShards=1&name=onenodecollectioncore&wt=javabin&roles=none&collection=onenodecollection} status=0 QTime=2792 
[junit4:junit4]   2> 494870 T1452 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 494871 T1452 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 495873 T1452 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> ASYNC  NEW_CORE C514 name=collection1 org.apache.solr.core.SolrCore@56d800ae url=http://127.0.0.1:38542/rd/o/collection1 node=127.0.0.1:38542_rd%2Fo C514_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:38542/rd/o, state=recovering, node_name=127.0.0.1:38542_rd%2Fo, collection=collection1, shard=shard2, core=collection1}
[junit4:junit4]   2> 496075 T1546 C514 P38542 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:40725/rd/o/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 496075 T1546 C514 P38542 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38542/rd/o START replicas=[http://127.0.0.1:40725/rd/o/collection1/] nUpdates=100
[junit4:junit4]   2> 496076 T1546 C514 P38542 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 496076 T1546 C514 P38542 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 496076 T1546 C514 P38542 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 496076 T1546 C514 P38542 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 496077 T1546 C514 P38542 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 496077 T1546 C514 P38542 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:40725/rd/o/collection1/. core=collection1
[junit4:junit4]   2> 496077 T1546 C514 P38542 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C515 name=collection1 org.apache.solr.core.SolrCore@3b756f64 url=http://127.0.0.1:40725/rd/o/collection1 node=127.0.0.1:40725_rd%2Fo C515_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:40725/rd/o, state=active, node_name=127.0.0.1:40725_rd%2Fo, collection=collection1, shard=shard2, core=collection1, leader=true}
[junit4:junit4]   2> 496081 T1504 C515 P40725 oasc.SolrCore.execute [collection1] webapp=/rd/o path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0 
[junit4:junit4]   2> 496082 T1503 C515 P40725 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 496083 T1503 C515 P40725 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@11b02d85 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f4f63752),segFN=segments_1,generation=1}
[junit4:junit4]   2> 496084 T1503 C515 P40725 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 496085 T1503 C515 P40725 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@11b02d85 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f4f63752),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@11b02d85 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f4f63752),segFN=segments_2,generation=2}
[junit4:junit4]   2> 496085 T1503 C515 P40725 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 496086 T1503 C515 P40725 oass.SolrIndexSearcher.<init> Opening Searcher@48e521f5 realtime
[junit4:junit4]   2> 496087 T1503 C515 P40725 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 496087 T1503 C515 P40725 oasup.LogUpdateProcessor.finish [collection1] webapp=/rd/o path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 5
[junit4:junit4]   2> 496088 T1546 C514 P38542 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 496088 T1546 C514 P38542 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 496090 T1504 C515 P40725 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 496090 T1504 C515 P40725 oasc.SolrCore.execute [collection1] webapp=/rd/o path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=1 
[junit4:junit4]   2> 496091 T1546 C514 P38542 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 496091 T1546 C514 P38542 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 496091 T1546 C514 P38542 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 496093 T1506 C515 P40725 oasc.SolrCore.execute [collection1] webapp=/rd/o path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=0 
[junit4:junit4]   2> 496094 T1546 C514 P38542 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 496094 T1546 C514 P38542 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4/index.20130603161644434
[junit4:junit4]   2> 496095 T1546 C514 P38542 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@509d4b68 lockFactory=org.apache.lucene.store.NativeFSLockFactory@99f70e66) fullCopy=false
[junit4:junit4]   2> 496096 T1503 C515 P40725 oasc.SolrCore.execute [collection1] webapp=/rd/o path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=0 
[junit4:junit4]   2> 496097 T1546 C514 P38542 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 496098 T1546 C514 P38542 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 496098 T1546 C514 P38542 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 496099 T1546 C514 P38542 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@79e078df lockFactory=org.apache.lucene.store.NativeFSLockFactory@fae3e18),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@79e078df lockFactory=org.apache.lucene.store.NativeFSLockFactory@fae3e18),segFN=segments_2,generation=2}
[junit4:junit4]   2> 496099 T1546 C514 P38542 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 496099 T1546 C514 P38542 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 496100 T1546 C514 P38542 oass.SolrIndexSearcher.<init> Opening Searcher@9990870c main
[junit4:junit4]   2> 496101 T1545 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9990870c main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 496101 T1546 C514 P38542 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4/index.20130603161644434 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4/index.20130603161644434;done=true>>]
[junit4:junit4]   2> 496101 T1546 C514 P38542 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4/index.20130603161644434
[junit4:junit4]   2> 496102 T1546 C514 P38542 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4/index.20130603161644434
[junit4:junit4]   2> 496102 T1546 C514 P38542 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 496102 T1546 C514 P38542 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 496102 T1546 C514 P38542 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 496103 T1546 C514 P38542 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 496103 T1546 C514 P38542 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 496350 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 496350 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:41244/rd/o",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:41244_rd%2Fo_onenodecollectioncore",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:41244_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore"}
[junit4:junit4]   2> 496353 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:38542/rd/o",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:38542_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:38542_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 496356 T1474 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> 496356 T1543 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> 496356 T1510 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> 496356 T1526 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> 496356 T1494 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> 496356 T1481 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> 496875 T1452 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 496876 T1452 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4]   2> 496876 T1452 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 496886 T1452 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 496888 T1554 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ec172af2 name:ZooKeeperConnection Watcher:127.0.0.1:50531 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 496888 T1452 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4]   1> / (2)
[junit4:junit4]   1> DATA:
[junit4:junit4]   1>     
[junit4:junit4]   1>  /solr (7)
[junit4:junit4]   1>   /solr/configs (1)
[junit4:junit4]   1>    /solr/configs/conf1 (9)
[junit4:junit4]   1>     /solr/configs/conf1/old_synonyms.txt (0)
[junit4:junit4]   1>     DATA: ...supressed...
[junit4:junit4]   1>     /solr/configs/conf1/protwords.txt (0)
[junit4:junit4]   1>     DATA: ...supressed...
[junit4:junit4]   1>     /solr/configs/conf1/stopwords.txt (0)
[junit4:junit4]   1>     DATA: ...supressed...
[junit4:junit4]   1>     /solr/configs/conf1/synonyms.txt (0)
[junit4:junit4]   1>     DATA: ...supressed...
[junit4:junit4]   1>     /solr/configs/conf1/schema.xml (0)
[junit4:junit4]   1>     DATA: ...supressed...
[junit4:junit4]   1>     /solr/configs/conf1/currency.xml (0)
[junit4:junit4]   1>     DATA: ...supressed...
[junit4:junit4]   1>     /solr/configs/conf1/open-exchange-rates.json (0)
[junit4:junit4]   1>     DATA:
[junit4:junit4]   1>         {
[junit4:junit4]   1>           "disclaimer": "This data is not real, it was synthetically created to match currency.xml.  It is modeled after the data format available from openexchangerates.org.  See https://openexchangerates.org/documentation for details",
[junit4:junit4]   1>           "license": "http://www.apache.org/licenses/LICENSE-2.0",
[junit4:junit4]   1>           "timestamp": 1332070464,
[junit4:junit4]   1>         
[junit4:junit4]   1>         
[junit4:junit4]   1>           "IMPORTANT NOTE": "In order for tests to work, this data must be kept in sync with ./currency.xml",
[junit4:junit4]   1>         
[junit4:junit4]   1>         
[junit4:junit4]   1>           "base": "USD",
[junit4:junit4]   1>           "rates": {
[junit4:junit4]   1>             "USD": 1,
[junit4:junit4]   1>             "JPY": 81.29,
[junit4:junit4]   1>             "EUR": 2.5,
[junit4:junit4]   1>             "GBP": 0.5,
[junit4:junit4]   1>             "MXN": 2.0
[junit4:junit4]   1>           }
[junit4:junit4]   1>         }
[junit4:junit4]   1>         
[junit4:junit4]   1>     /solr/configs/conf1/solrconfig.xml (0)
[junit4:junit4]   1>     DATA: ...supressed...
[junit4:junit4]   1>     /solr/configs/conf1/mapping-ISOLatin1Accent.txt (0)
[junit4:junit4]   1>     DATA: ...supressed...
[junit4:junit4]   1>   /solr/overseer (3)
[junit4:junit4]   1>   DATA:
[junit4:junit4]   1>       
[junit4:junit4]   1>    /solr/overseer/queue (0)
[junit4:junit4]   1>    /solr/overseer/collection-queue-work (0)
[junit4:junit4]   1>    /solr/overseer/queue-work (0)
[junit4:junit4]   1>   /solr/overseer_elect (2)
[junit4:junit4]   1>    /solr/overseer_elect/leader (0)
[junit4:junit4]   1>    DATA:
[junit4:junit4]   1>        {"id":"89803363559145475-127.0.0.1:39522_rd%2Fo-n_0000000000"}
[junit4:junit4]   1>    /solr/overseer_elect/election (5)
[junit4:junit4]   1>     /solr/overseer_elect/election/89803363559145484-127.0.0.1:38542_rd%2Fo-n_0000000004 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89803363559145482-127.0.0.1:34704_rd%2Fo-n_0000000003 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89803363559145478-127.0.0.1:41244_rd%2Fo-n_0000000001 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89803363559145480-127.0.0.1:40725_rd%2Fo-n_0000000002 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89803363559145475-127.0.0.1:39522_rd%2Fo-n_0000000000 (0)
[junit4:junit4]   1>   /solr/collections (3)
[junit4:junit4]   1>    /solr/collections/control_collection (3)
[junit4:junit4]   1>    DATA:
[junit4:junit4]   1>        {"configName":"conf1"}
[junit4:junit4]   1>     /solr/collections/control_collection/leader_elect (1)
[junit4:junit4]   1>      /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4]   1>       /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4:junit4]   1>        /solr/collections/control_collection/leader_elect/shard1/election/89803363559145475-127.0.0.1:39522_rd%2Fo_collection1-n_0000000000 (0)
[junit4:junit4]   1>     /solr/collections/control_collection/leaders (1)
[junit4:junit4]   1>      /solr/collections/control_collection/leaders/shard1 (0)
[junit4:junit4]   1>      DATA:
[junit4:junit4]   1>          {
[junit4:junit4]   1>            "base_url":"http://127.0.0.1:39522/rd/o",
[junit4:junit4]   1>            "node_name":"127.0.0.1:39522_rd%2Fo",
[junit4:junit4]   1>            "core":"collection1"}
[junit4:junit4]   1>     /solr/collections/control_collection/shards (0)
[junit4:junit4]   1>    /solr/collections/collection1 (3)
[junit4:junit4]   1>    DATA:
[junit4:junit4]   1>        {"configName":"conf1"}
[junit4:junit4]   1>     /solr/collections/collection1/leader_elect (2)
[junit4:junit4]   1>      /solr/collections/collection1/leader_elect/shard1 (1)
[junit4:junit4]   1>       /solr/collections/collection1/leader_elect/shard1/election (2)
[junit4:junit4]   1>        /solr/collections/collection1/leader_elect/shard1/election/89803363559145482-127.0.0.1:34704_rd%2Fo_collection1-n_0000000001 (0)
[junit4:junit4]   1>        /solr/collections/collection1/leader_elect/shard1/election/89803363559145478-127.0.0.1:41244_rd%2Fo_collection1-n_0000000000 (0)
[junit4:junit4]   1>      /solr/collections/collection1/leader_elect/shard2 (1)
[junit4:junit4]   1>       /solr/collections/collection1/leader_elect/shard2/election (2)
[junit4:junit4]   1>        /solr/collections/collection1/leader_elect/shard2/election/89803363559145484-127.0.0.1:38542_rd%2Fo_collection1-n_0000000001 (0)
[junit4:junit4]   1>        /solr/collections/collection1/leader_elect/shard2/election/89803363559145480-127.0.0.1:40725_rd%2Fo_collection1-n_0000000000 (0)
[junit4:junit4]   1>     /solr/collections/collection1/leaders (2)
[junit4:junit4]   1>      /solr/collections/collection1/leaders/shard1 (0)
[junit4:junit4]   1>      DATA:
[junit4:junit4]   1>          {
[junit4:junit4]   1>            "base_url":"http://127.0.0.1:41244/rd/o",
[junit4:junit4]   1>            "node_name":"127.0.0.1:41244_rd%2Fo",
[junit4:junit4]   1>            "core":"collection1"}
[junit4:junit4]   1>      /solr/collections/collection1/leaders/shard2 (0)
[junit4:junit4]   1>      DATA:
[junit4:junit4]   1>          {
[junit4:junit4]   1>            "base_url":"http://127.0.0.1:40725/rd/o",
[junit4:junit4]   1>            "node_name":"127.0.0.1:40725_rd%2Fo",
[junit4:junit4]   1>            "core":"collection1"}
[junit4:junit4]   1>     /solr/collections/collection1/shards (0)
[junit4:junit4]   1>    /solr/collections/onenodecollection (2)
[junit4:junit4]   1>    DATA:
[junit4:junit4]   1>        {
[junit4:junit4]   1>          "router":"compositeId",
[junit4:junit4]   1>          "configName":"conf1"}
[junit4:junit4]   1>     /solr/collections/onenodecollection/leader_elect (1)
[junit4:junit4]   1>      /solr/collections/onenodecollection/leader_elect/shard1 (1)
[junit4:junit4]   1>       /solr/collections/onenodecollection/leader_elect/shard1/election (1)
[junit4:junit4]   1>        /solr/collections/onenodecollection/leader_elect/shard1/election/89803363559145478-127.0.0.1:41244_rd%2Fo_onenodecollectioncore-n_0000000000 (0)
[junit4:junit4]   1>     /solr/collections/onenodecollection/leaders (1)
[junit4:junit4]   1>      /solr/collections/onenodecollection/leaders/shard1 (0)
[junit4:junit4]   1>      DATA:
[junit4:junit4]   1>          {
[junit4:junit4]   1>            "base_url":"http://127.0.0.1:41244/rd/o",
[junit4:junit4]   1>            "node_name":"127.0.0.1:41244_rd%2Fo",
[junit4:junit4]   1>            "core":"onenodecollectioncore"}
[junit4:junit4]   1>   /solr/aliases.json (0)
[junit4:junit4]   1>   /solr/live_nodes (5)
[junit4:junit4]   1>    /solr/live_nodes/127.0.0.1:34704_rd%2Fo (0)
[junit4:junit4]   1>    /solr/live_nodes/127.0.0.1:39522_rd%2Fo (0)
[junit4:junit4]   1>    /solr/live_nodes/127.0.0.1:38542_rd%2Fo (0)
[junit4:junit4]   1>    /solr/live_nodes/127.0.0.1:40725_rd%2Fo (0)
[junit4:junit4]   1>    /solr/live_nodes/127.0.0.1:41244_rd%2Fo (0)
[junit4:junit4]   1>   /solr/clusterstate.json (0)
[junit4:junit4]   1>   DATA:
[junit4:junit4]   1>       {
[junit4:junit4]   1>         "control_collection":{
[junit4:junit4]   1>           "shards":{"shard1":{
[junit4:junit4]   1>               "range":"80000000-7fffffff",
[junit4:junit4]   1>               "state":"active",
[junit4:junit4]   1>               "replicas":{"127.0.0.1:39522_rd%2Fo_collection1":{
[junit4:junit4]   1>                   "base_url":"http://127.0.0.1:39522/rd/o",
[junit4:junit4]   1>                   "state":"active",
[junit4:junit4]   1>                   "node_name":"127.0.0.1:39522_rd%2Fo",
[junit4:junit4]   1>                   "collection":"control_collection",
[junit4:junit4]   1>                   "shard":"shard1",
[junit4:junit4]   1>                   "core":"collection1",
[junit4:junit4]   1>                   "leader":"true"}}}},
[junit4:junit4]   1>           "router":"compositeId"},
[junit4:junit4]   1>         "onenodecollection":{
[junit4:junit4]   1>           "shards":{"shard1":{
[junit4:junit4]   1>               "range":"80000000-7fffffff",
[junit4:junit4]   1>               "state":"active",
[junit4:junit4]   1>               "replicas":{"127.0.0.1:41244_rd%2Fo_onenodecollectioncore":{
[junit4:junit4]   1>                   "base_url":"http://127.0.0.1:41244/rd/o",
[junit4:junit4]   1>                   "state":"active",
[junit4:junit4]   1>                   "node_name":"127.0.0.1:41244_rd%2Fo",
[junit4:junit4]   1>                   "roles":"none",
[junit4:junit4]   1>                   "collection":"onenodecollection",
[junit4:junit4]   1>                   "shard":"shard1",
[junit4:junit4]   1>                   "core":"onenodecollectioncore",
[junit4:junit4]   1>                   "leader":"true"}}}},
[junit4:junit4]   1>           "router":"compositeId"},
[junit4:junit4]   1>         "collection1":{
[junit4:junit4]   1>           "shards":{
[junit4:junit4]   1>             "shard1":{
[junit4:junit4]   1>               "range":"80000000-ffffffff",
[junit4:junit4]   1>               "state":"active",
[junit4:junit4]   1>               "replicas":{
[junit4:junit4]   1>                 "127.0.0.1:41244_rd%2Fo_collection1":{
[junit4:junit4]   1>                   "base_url":"http://127.0.0.1:41244/rd/o",
[junit4:junit4]   1>                   "state":"active",
[junit4:junit4]   1>                   "node_name":"127.0.0.1:41244_rd%2Fo",
[junit4:junit4]   1>                   "collection":"collection1",
[junit4:junit4]   1>                   "shard":"shard1",
[junit4:junit4]   1>                   "core":"collection1",
[junit4:junit4]   1>                   "leader":"true"},
[junit4:junit4]   1>                 "127.0.0.1:34704_rd%2Fo_collection1":{
[junit4:junit4]   1>                   "base_url":"http://127.0.0.1:34704/rd/o",
[junit4:junit4]   1>                   "state":"active",
[junit4:junit4]   1>                   "node_name":"127.0.0.1:34704_rd%2Fo",
[junit4:junit4]   1>                   "collection":"collection1",
[junit4:junit4]   1>                   "shard":"shard1",
[junit4:junit4]   1>                   "core":"collection1"}}},
[junit4:junit4]   1>             "shard2":{
[junit4:junit4]   1>               "range":"0-7fffffff",
[junit4:junit4]   1>               "state":"active",
[junit4:junit4]   1>               "replicas":{
[junit4:junit4]   1>                 "127.0.0.1:40725_rd%2Fo_collection1":{
[junit4:junit4]   1>                   "base_url":"http://127.0.0.1:40725/rd/o",
[junit4:junit4]   1>                   "state":"active",
[junit4:junit4]   1>                   "node_name":"127.0.0.1:40725_rd%2Fo",
[junit4:junit4]   1>                   "collection":"collection1",
[junit4:junit4]   1>                   "shard":"shard2",
[junit4:junit4]   1>                   "core":"collection1",
[junit4:junit4]   1>                   "leader":"true"},
[junit4:junit4]   1>                 "127.0.0.1:38542_rd%2Fo_collection1":{
[junit4:junit4]   1>                   "base_url":"http://127.0.0.1:38542/rd/o",
[junit4:junit4]   1>                   "state":"active",
[junit4:junit4]   1>                   "node_name":"127.0.0.1:38542_rd%2Fo",
[junit4:junit4]   2> 496924 T1452 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 39522
[junit4:junit4]   2> 496925 T1452 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1330369037
[junit4:junit4]   2> 497861 T1475 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 497862 T1475 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39522/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:39522_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39522_rd%2Fo",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 497865 T1474 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> 497865 T1510 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> 497865 T1526 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> 497865 T1543 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> 497865 T1494 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> 498926 T1452 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 498927 T1452 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 498928 T1452 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@f704bd47
[junit4:junit4]   2> 498932 T1452 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 498932 T1452 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 498933 T1452 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 498933 T1452 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 498934 T1452 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 498935 T1452 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4]   2> 498935 T1452 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/control/data [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/control/data;done=false>>]
[junit4:junit4]   2> 498936 T1452 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/control/data
[junit4:junit4]   2> 498936 T1452 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/control/data/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/control/data/index;done=false>>]
[junit4:junit4]   2> 498937 T1452 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/control/data/index
[junit4:junit4]   2> 498938 T1475 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89803363559145475-127.0.0.1:39522_rd%2Fo-n_0000000000) am no longer a leader.
[junit4:junit4]   2> 498938 T1543 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> 498938 T1526 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> 498939 T1510 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 498939 T1510 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> 498939 T1494 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 498940 T1543 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 498940 T1526 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 498941 T1494 oasc.Overseer.start Overseer (id=89803363559145478-127.0.0.1:41244_rd%2Fo-n_0000000001) starting
[junit4:junit4]   2> 498944 T1494 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> 498944 T1556 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 498944 T1555 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 498945 T1494 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 498946 T1555 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 498946 T1555 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39522/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:39522_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39522_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 498949 T1543 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> 498949 T1526 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> 498949 T1494 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> 498949 T1510 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> 498959 T1452 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/rd/o,null}
[junit4:junit4]   2> 499011 T1452 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 41244
[junit4:junit4]   2> 499012 T1452 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=644223873
[junit4:junit4]   2> 500239 T1474 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 500239 T1474 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> 500239 T1474 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 500452 T1555 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 500453 T1555 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:41244/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:41244_rd%2Fo_onenodecollectioncore",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:41244_rd%2Fo",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore"}
[junit4:junit4]   2> 500456 T1555 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:41244/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:41244_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:41244_rd%2Fo",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 500459 T1543 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> 500460 T1510 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> 500460 T1526 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> 500460 T1494 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> 502016 T1452 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 502016 T1452 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 502018 T1452 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 502019 T1452 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@362387d4
[junit4:junit4]   2> 502023 T1452 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=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 502023 T1452 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 502024 T1452 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 502024 T1452 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 502025 T1452 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 502026 T1452 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4]   2> 502026 T1452 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty1/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty1/index;done=false>>]
[junit4:junit4]   2> 502027 T1452 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty1/index
[junit4:junit4]   2> 502028 T1452 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty1 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty1;done=false>>]
[junit4:junit4]   2> 502028 T1452 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty1
[junit4:junit4]   2> 502029 T1452 oasc.SolrCore.close [onenodecollectioncore]  CLOSING SolrCore org.apache.solr.core.SolrCore@b50a7c45
[junit4:junit4]   2> 502034 T1452 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 502034 T1452 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 502035 T1452 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 502035 T1452 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 502036 T1452 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4]   2> 502036 T1452 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4]   2> 502037 T1452 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370290581649/onenodecollection/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370290581649/onenodecollection/index;done=false>>]
[junit4:junit4]   2> 502038 T1452 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370290581649/onenodecollection/index
[junit4:junit4]   2> 502038 T1452 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370290581649/onenodecollection [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370290581649/onenodecollection;done=false>>]
[junit4:junit4]   2> 502039 T1452 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370290581649/onenodecollection
[junit4:junit4]   2> 502040 T1555 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89803363559145478-127.0.0.1:41244_rd%2Fo-n_0000000001) am no longer a leader.
[junit4:junit4]   2> 502040 T1543 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> 502040 T1494 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> 502040 T1526 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> 502041 T1494 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 502041 T1510 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 502042 T1543 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 502042 T1494 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 502042 T1526 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 502044 T1510 oasc.Overseer.start Overseer (id=89803363559145480-127.0.0.1:40725_rd%2Fo-n_0000000002) starting
[junit4:junit4]   2> 502044 T1526 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 502045 T1526 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4]   2> 502046 T1526 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4]   2> 502046 T1526 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 502046 T1526 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:34704/rd/o/collection1/
[junit4:junit4]   2> 502046 T1526 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 502047 T1526 oasc.SyncStrategy.syncToMe http://127.0.0.1:34704/rd/o/collection1/ has no replicas
[junit4:junit4]   2> 502047 T1558 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 502047 T1510 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 502047 T1526 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:34704/rd/o/collection1/
[junit4:junit4]   2> 502048 T1510 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> 502048 T1557 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 502048 T1526 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 502050 T1557 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 502050 T1557 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:41244/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:41244_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:41244_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 502053 T1557 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:41244/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:41244_rd%2Fo_onenodecollectioncore",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:41244_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore"}
[junit4:junit4]   2> 502058 T1510 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> 502058 T1543 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> 502058 T1526 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> 502062 T1452 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/rd/o,null}
[junit4:junit4]   2> 502113 T1452 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 40725
[junit4:junit4]   2> 502114 T1452 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-1512862023
[junit4:junit4]   2> 503116 T1452 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 503116 T1452 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 503118 T1452 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@3b756f64
[junit4:junit4]   2> 503121 T1452 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=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 503122 T1452 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 503122 T1452 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 503123 T1452 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 503124 T1452 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 503124 T1452 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4]   2> 503125 T1452 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty2 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty2;done=false>>]
[junit4:junit4]   2> 503125 T1452 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty2
[junit4:junit4]   2> 503126 T1452 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty2/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty2/index;done=false>>]
[junit4:junit4]   2> 503126 T1452 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty2/index
[junit4:junit4]   2> 503127 T1557 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89803363559145480-127.0.0.1:40725_rd%2Fo-n_0000000002) am no longer a leader.
[junit4:junit4]   2> 503129 T1543 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 503130 T1526 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 503131 T1543 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4]   2> 503132 T1543 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4]   2> 503132 T1543 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 503132 T1526 oasc.Overseer.start Overseer (id=89803363559145482-127.0.0.1:34704_rd%2Fo-n_0000000003) starting
[junit4:junit4]   2> 503132 T1543 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:38542/rd/o/collection1/
[junit4:junit4]   2> 503133 T1543 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38542/rd/o START replicas=[http://127.0.0.1:40725/rd/o/collection1/] nUpdates=100
[junit4:junit4]   2> 503133 T1543 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38542/rd/o DONE.  We have no versions.  sync failed.
[junit4:junit4]   2> 503134 T1543 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4]   2> 503134 T1543 oasc.ShardLeaderElectionContext.runLeaderProcess We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4:junit4]   2> 503134 T1543 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:38542/rd/o/collection1/
[junit4:junit4]   2> 503134 T1543 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 503136 T1526 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> 503136 T1561 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 503138 T1560 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 503138 T1526 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 503139 T1452 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/rd/o,null}
[junit4:junit4]   2> 503140 T1543 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> 503140 T1560 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 503141 T1560 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40725/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:40725_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40725_rd%2Fo",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 503141 T1543 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 503143 T1560 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40725/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:40725_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40725_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 503150 T1543 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> 503151 T1526 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> 503190 T1452 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 34704
[junit4:junit4]   2> 503191 T1452 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-1325273604
[junit4:junit4]   2> 504192 T1452 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 504194 T1452 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 504196 T1452 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@c3cde8e0
[junit4:junit4]   2> 504201 T1452 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 504202 T1452 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 504203 T1452 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 504204 T1452 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 504206 T1452 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 504207 T1452 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4]   2> 504208 T1452 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3/index;done=false>>]
[junit4:junit4]   2> 504209 T1452 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3/index
[junit4:junit4]   2> 504209 T1452 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3;done=false>>]
[junit4:junit4]   2> 504210 T1452 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty3
[junit4:junit4]   2> 504211 T1560 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89803363559145482-127.0.0.1:34704_rd%2Fo-n_0000000003) am no longer a leader.
[junit4:junit4]   2> 504211 T1526 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> 504212 T1526 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 504212 T1526 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 504213 T1543 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 504215 T1543 oasc.Overseer.start Overseer (id=89803363559145484-127.0.0.1:38542_rd%2Fo-n_0000000004) starting
[junit4:junit4]   2> 504219 T1543 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> 504219 T1563 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 504220 T1562 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 504221 T1562 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 504222 T1562 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:34704/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:34704_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:34704_rd%2Fo",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 504224 T1562 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:34704/rd/o",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:34704_rd%2Fo_collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:34704_rd%2Fo",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 504228 T1543 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4:junit4]   2> 504228 T1543 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> 504232 T1452 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/rd/o,null}
[junit4:junit4]   2> 504285 T1452 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 38542
[junit4:junit4]   2> 504285 T1452 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=2139745576
[junit4:junit4]   2> 504428 T1510 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 504429 T1510 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> 504429 T1510 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 505287 T1452 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 505288 T1452 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 505289 T1452 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@56d800ae
[junit4:junit4]   2> 505295 T1452 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 505296 T1452 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 505296 T1452 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 505297 T1452 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 505298 T1452 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 505298 T1452 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4]   2> 505299 T1452 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4/index;done=false>>]
[junit4:junit4]   2> 505299 T1452 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4/index
[junit4:junit4]   2> 505300 T1452 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4;done=false>>]
[junit4:junit4]   2> 505300 T1452 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370290581649/jetty4
[junit4:junit4]   2> 505301 T1562 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89803363559145484-127.0.0.1:38542_rd%2Fo-n_0000000004) am no longer a leader.
[junit4:junit4]   2> 505302 T1543 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> 505302 T1543 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 505303 T1543 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 505323 T1452 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/rd/o,null}
[junit4:junit4]   2> 505381 T1452 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4]   2> 505383 T1452 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:50531 50531
[junit4:junit4]   1>                   "collection":"collection1",
[junit4:junit4]   1>                   "shard":"shard2",
[junit4:junit4]   1>                   "core":"collection1"}}}},
[junit4:junit4]   1>           "router":"compositeId"}}
[junit4:junit4]   1>  /zookeeper (1)
[junit4:junit4]   1>  DATA:
[junit4:junit4]   1>      
[junit4:junit4]   1> 
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=BasicDistributedZk2Test -Dtests.method=testDistribSearch -Dtests.seed=D773097047B60FDD -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_QA -Dtests.timezone=America/Asuncion -Dtests.file.encoding=US-ASCII
[junit4:junit4] ERROR   32.1s J1 | BasicDistributedZk2Test.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:40725/rd/o/onenodecollectioncore returned non ok status:404, message:Can not find: /rd/o/onenodecollectioncore/update
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([D773097047B60FDD:5695876830E96FE1]:0)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
[junit4:junit4]    > 	at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:198)
[junit4:junit4]    > 	at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:90)
[junit4:junit4]    > 	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4]    > 	at java.lang.Thread.run(Thread.java:780)
[junit4:junit4]   2> 505397 T1452 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 32098 T1451 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4]   2> NOTE: test params are: codec=Lucene42: {}, docValues:{}, sim=DefaultSimilarity, locale=ar_QA, timezone=America/Asuncion
[junit4:junit4]   2> NOTE: Linux 3.2.0-45-generic x86/IBM Corporation 1.7.0 (32-bit)/cpus=8,threads=2,free=33074896,total=225181696
[junit4:junit4]   2> NOTE: All tests run in this JVM: [SolrCmdDistributorTest, StandardRequestHandlerTest, DateMathParserTest, HighlighterConfigTest, TestAtomicUpdateErrorCases, TestSchemaVersionResource, TestLuceneMatchVersion, TestSolrXml, TestPartialUpdateDeduplication, ClusterStateTest, TestSchemaNameResource, DirectUpdateHandlerTest, TestFastOutputStream, IndexBasedSpellCheckerTest, CurrencyFieldXmlFileTest, SampleTest, TestCodecSupport, NotRequiredUniqueKeyTest, TestRecovery, SuggesterTSTTest, HardAutoCommitTest, TestSolrXMLSerializer, TestBinaryResponseWriter, HighlighterTest, SpellPossibilityIteratorTest, ConvertedLegacyTest, SolrIndexConfigTest, TestCSVResponseWriter, TestDFRSimilarityFactory, PathHierarchyTokenizerFactoryTest, FieldAnalysisRequestHandlerTest, RequiredFieldsTest, NumericFieldsTest, TestDistributedGrouping, TestWordDelimiterFilterFactory, TestSolr4Spatial, XsltUpdateRequestHandlerTest, DocValuesMultiTest, TestShardHandlerFactory, BadIndexSchemaTest, BasicZkTest, URLClassifyProcessorTest, TestSchemaSimilarityResource, CollectionsAPIDistributedZkTest, TestQueryTypes, TestStressReorder, TestHashPartitioner, ShardRoutingCustomTest, FullSolrCloudDistribCmdsTest, XmlUpdateRequestHandlerTest, TestJmxIntegration, TestRangeQuery, TestReload, AliasIntegrationTest, TestMergePolicyConfig, SpellCheckComponentTest, TestBM25SimilarityFactory, IndexSchemaRuntimeFieldTest, TestSolrJ, TestFieldResource, TestOmitPositions, UpdateParamsTest, TestNumberUtils, TestSolrQueryParserResource, JSONWriterTest, TestStressLucene, CoreContainerCoreInitFailuresTest, TestAddFieldRealTimeGet, BasicDistributedZk2Test]
[junit4:junit4] Completed on J1 in 32.63s, 1 test, 1 error <<< FAILURES!

[...truncated 540 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:380: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:373: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1240: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:884: There were test failures: 296 suites, 1235 tests, 1 error, 14 ignored (8 assumptions)

Total time: 43 minutes 37 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message