You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/05/17 03:20:25 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/ibm-j9-jdk7) - Build # 5629
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/5629/
Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
1 tests failed.
REGRESSION: org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearch
Error Message:
Server at http://127.0.0.1:54136/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:54136/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
at __randomizedtesting.SeedInfo.seed([49DFCF95986A8EAC:C839418DEF35EE90]: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 9596 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4] 2> 624727 T1589 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 624731 T1589 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1368752904379
[junit4:junit4] 2> 624732 T1589 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 624733 T1590 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 624833 T1589 oasc.ZkTestServer.run start zk server on port:46577
[junit4:junit4] 2> 624834 T1589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 625151 T1596 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4150301d name:ZooKeeperConnection Watcher:127.0.0.1:46577 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 625152 T1589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 625153 T1589 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 625170 T1589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 625171 T1598 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@87606857 name:ZooKeeperConnection Watcher:127.0.0.1:46577/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 625171 T1589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 625172 T1589 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 625174 T1589 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 625176 T1589 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 625178 T1589 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 625180 T1589 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 625180 T1589 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 625183 T1589 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 625184 T1589 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 625186 T1589 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 625187 T1589 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 625189 T1589 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 625190 T1589 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 625192 T1589 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 625192 T1589 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 625195 T1589 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 625195 T1589 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 625197 T1589 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 625198 T1589 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 625200 T1589 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 625200 T1589 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 625202 T1589 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 625203 T1589 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 625273 T1589 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 625277 T1589 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:41328
[junit4:junit4] 2> 625278 T1589 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 625278 T1589 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 625279 T1589 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1368752904852
[junit4:junit4] 2> 625280 T1589 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1368752904852/solr.xml
[junit4:junit4] 2> 625280 T1589 oasc.CoreContainer.<init> New CoreContainer 1179259968
[junit4:junit4] 2> 625281 T1589 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1368752904852/'
[junit4:junit4] 2> 625281 T1589 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1368752904852/'
[junit4:junit4] 2> 625324 T1589 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 625325 T1589 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 625326 T1589 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 625326 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 625327 T1589 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 625327 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 625328 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 625329 T1589 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 625329 T1589 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 625330 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 625334 T1589 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 625335 T1589 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:46577/solr
[junit4:junit4] 2> 625336 T1589 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 625337 T1589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 625338 T1609 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@bcbb6ea0 name:ZooKeeperConnection Watcher:127.0.0.1:46577 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 625339 T1589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 625340 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 625345 T1589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 625347 T1611 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f7ec924 name:ZooKeeperConnection Watcher:127.0.0.1:46577/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 625347 T1589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 625348 T1589 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 625351 T1589 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 625353 T1589 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 625355 T1589 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41328_
[junit4:junit4] 2> 625356 T1589 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:41328_
[junit4:junit4] 2> 625359 T1589 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 625363 T1589 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 625366 T1589 oasc.Overseer.start Overseer (id=89702590341578755-127.0.0.1:41328_-n_0000000000) starting
[junit4:junit4] 2> 625368 T1589 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 625371 T1613 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 625372 T1589 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 625374 T1589 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 625376 T1589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 625379 T1612 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 625381 T1614 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1368752904852/collection1
[junit4:junit4] 2> 625382 T1614 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 625382 T1614 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 625383 T1614 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 625383 T1614 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1368752904852/collection1/'
[junit4:junit4] 2> 625384 T1614 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1368752904852/collection1/lib/README' to classloader
[junit4:junit4] 2> 625385 T1614 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1368752904852/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 625409 T1614 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 625440 T1614 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 625442 T1614 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 625446 T1614 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 625760 T1614 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 625766 T1614 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 625769 T1614 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 625784 T1614 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 625788 T1614 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 625791 T1614 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 625792 T1614 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 625793 T1614 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 625793 T1614 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 625794 T1614 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 625794 T1614 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 625795 T1614 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 625795 T1614 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1368752904852/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/control/data/
[junit4:junit4] 2> 625796 T1614 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@141ab172
[junit4:junit4] 2> 625796 T1614 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 625797 T1614 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/control/data
[junit4:junit4] 2> 625797 T1614 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/control/data/index/
[junit4:junit4] 2> 625798 T1614 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 625798 T1614 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/control/data/index
[junit4:junit4] 2> 625800 T1614 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e81e8de8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@746048e1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 625801 T1614 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 625803 T1614 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 625803 T1614 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 625804 T1614 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 625804 T1614 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 625805 T1614 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 625805 T1614 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 625806 T1614 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 625806 T1614 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 625807 T1614 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 625808 T1614 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 625811 T1614 oass.SolrIndexSearcher.<init> Opening Searcher@b838bdbe main
[junit4:junit4] 2> 625811 T1614 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/control/data/tlog
[junit4:junit4] 2> 625812 T1614 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 625813 T1614 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 625816 T1615 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@b838bdbe main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 625817 T1614 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 625818 T1614 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 626882 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 626882 T1612 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:41328",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:41328_",
[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> 626883 T1612 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 626883 T1612 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 626886 T1611 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> 627819 T1614 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 627820 T1614 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:41328 collection:control_collection shard:shard1
[junit4:junit4] 2> 627821 T1614 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 627827 T1614 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 627830 T1614 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 627831 T1614 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 627831 T1614 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:41328/collection1/
[junit4:junit4] 2> 627831 T1614 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 627832 T1614 oasc.SyncStrategy.syncToMe http://127.0.0.1:41328/collection1/ has no replicas
[junit4:junit4] 2> 627832 T1614 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:41328/collection1/
[junit4:junit4] 2> 627832 T1614 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 628390 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 628398 T1611 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> 628439 T1614 oasc.ZkController.register We are http://127.0.0.1:41328/collection1/ and leader is http://127.0.0.1:41328/collection1/
[junit4:junit4] 2> 628440 T1614 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:41328
[junit4:junit4] 2> 628440 T1614 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 628440 T1614 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 628441 T1614 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 628444 T1614 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 628445 T1589 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 628445 T1589 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 628446 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 628450 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 628451 T1589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 628453 T1618 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@be3e010c name:ZooKeeperConnection Watcher:127.0.0.1:46577/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 628453 T1589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 628454 T1589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 628456 T1589 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 628524 T1589 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 628527 T1589 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:43026
[junit4:junit4] 2> 628527 T1589 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 628528 T1589 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 628529 T1589 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1368752908104
[junit4:junit4] 2> 628529 T1589 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1368752908104/solr.xml
[junit4:junit4] 2> 628530 T1589 oasc.CoreContainer.<init> New CoreContainer -1538632010
[junit4:junit4] 2> 628530 T1589 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1368752908104/'
[junit4:junit4] 2> 628531 T1589 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1368752908104/'
[junit4:junit4] 2> 628569 T1589 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 628570 T1589 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 628570 T1589 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 628571 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 628571 T1589 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 628572 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 628572 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 628573 T1589 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 628573 T1589 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 628574 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 628579 T1589 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 628580 T1589 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:46577/solr
[junit4:junit4] 2> 628580 T1589 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 628582 T1589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 628583 T1629 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@325f4121 name:ZooKeeperConnection Watcher:127.0.0.1:46577 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 628583 T1589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 628585 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 628590 T1589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 628591 T1631 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@697d830e name:ZooKeeperConnection Watcher:127.0.0.1:46577/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 628592 T1589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 628595 T1589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 629598 T1589 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43026_
[junit4:junit4] 2> 629600 T1589 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43026_
[junit4:junit4] 2> 629602 T1631 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 629602 T1618 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 629602 T1611 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 629603 T1611 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> 629608 T1632 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1368752908104/collection1
[junit4:junit4] 2> 629608 T1632 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 629609 T1632 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 629610 T1632 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 629611 T1632 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1368752908104/collection1/'
[junit4:junit4] 2> 629611 T1632 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1368752908104/collection1/lib/README' to classloader
[junit4:junit4] 2> 629612 T1632 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1368752908104/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 629638 T1632 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 629667 T1632 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 629669 T1632 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 629673 T1632 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 629903 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 629904 T1612 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:41328",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:41328_",
[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> 629907 T1631 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> 629907 T1611 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> 629907 T1618 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> 630001 T1632 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 630007 T1632 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 630010 T1632 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 630022 T1632 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 630026 T1632 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 630029 T1632 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 630030 T1632 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 630031 T1632 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 630031 T1632 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 630032 T1632 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 630032 T1632 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 630033 T1632 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 630033 T1632 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1368752908104/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty1/
[junit4:junit4] 2> 630033 T1632 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@141ab172
[junit4:junit4] 2> 630034 T1632 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 630034 T1632 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty1
[junit4:junit4] 2> 630035 T1632 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty1/index/
[junit4:junit4] 2> 630035 T1632 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 630035 T1632 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty1/index
[junit4:junit4] 2> 630037 T1632 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3fced0f1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@284ab057),segFN=segments_1,generation=1}
[junit4:junit4] 2> 630037 T1632 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 630038 T1632 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 630039 T1632 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 630039 T1632 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 630040 T1632 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 630040 T1632 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 630041 T1632 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 630041 T1632 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 630042 T1632 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 630042 T1632 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 630043 T1632 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 630045 T1632 oass.SolrIndexSearcher.<init> Opening Searcher@12004b57 main
[junit4:junit4] 2> 630045 T1632 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty1/tlog
[junit4:junit4] 2> 630046 T1632 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 630046 T1632 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 630051 T1633 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12004b57 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 630053 T1632 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 630053 T1632 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 631412 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 631413 T1612 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:43026",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:43026_",
[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> 631413 T1612 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 631413 T1612 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 631417 T1631 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> 631417 T1611 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> 631417 T1618 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> 632055 T1632 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 632055 T1632 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43026 collection:collection1 shard:shard1
[junit4:junit4] 2> 632056 T1632 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 632064 T1632 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 632066 T1632 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 632066 T1632 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 632067 T1632 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:43026/collection1/
[junit4:junit4] 2> 632067 T1632 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 632067 T1632 oasc.SyncStrategy.syncToMe http://127.0.0.1:43026/collection1/ has no replicas
[junit4:junit4] 2> 632068 T1632 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:43026/collection1/
[junit4:junit4] 2> 632068 T1632 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 632921 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 632940 T1631 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> 632940 T1618 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> 632941 T1611 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> 632975 T1632 oasc.ZkController.register We are http://127.0.0.1:43026/collection1/ and leader is http://127.0.0.1:43026/collection1/
[junit4:junit4] 2> 632975 T1632 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43026
[junit4:junit4] 2> 632976 T1632 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 632976 T1632 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 632976 T1632 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 632978 T1632 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 632978 T1589 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 632979 T1589 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 632980 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 633053 T1589 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 633055 T1589 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54136
[junit4:junit4] 2> 633056 T1589 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 633056 T1589 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 633057 T1589 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1368752912631
[junit4:junit4] 2> 633057 T1589 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1368752912631/solr.xml
[junit4:junit4] 2> 633058 T1589 oasc.CoreContainer.<init> New CoreContainer -1760032723
[junit4:junit4] 2> 633059 T1589 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1368752912631/'
[junit4:junit4] 2> 633059 T1589 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1368752912631/'
[junit4:junit4] 2> 633097 T1589 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 633098 T1589 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 633098 T1589 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 633099 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 633099 T1589 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 633100 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 633100 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 633101 T1589 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 633102 T1589 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 633102 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 633107 T1589 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 633107 T1589 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:46577/solr
[junit4:junit4] 2> 633108 T1589 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 633109 T1589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 633110 T1645 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@aa0e0141 name:ZooKeeperConnection Watcher:127.0.0.1:46577 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 633111 T1589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 633112 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 633117 T1589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 633119 T1647 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ebc0cab name:ZooKeeperConnection Watcher:127.0.0.1:46577/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 633119 T1589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 633124 T1589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 634127 T1589 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54136_
[junit4:junit4] 2> 634128 T1589 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54136_
[junit4:junit4] 2> 634130 T1618 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> 634131 T1631 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 634131 T1611 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 634131 T1631 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> 634132 T1611 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> 634132 T1647 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 634132 T1618 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 634137 T1648 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1368752912631/collection1
[junit4:junit4] 2> 634137 T1648 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 634138 T1648 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 634138 T1648 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 634139 T1648 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1368752912631/collection1/'
[junit4:junit4] 2> 634140 T1648 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1368752912631/collection1/lib/README' to classloader
[junit4:junit4] 2> 634140 T1648 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1368752912631/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 634176 T1648 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 634208 T1648 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 634209 T1648 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 634217 T1648 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 634446 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 634447 T1612 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:43026",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:43026_",
[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> 634450 T1647 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> 634450 T1631 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> 634450 T1611 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> 634450 T1618 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> 634577 T1648 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 634582 T1648 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 634585 T1648 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 634596 T1648 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 634601 T1648 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 634605 T1648 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 634606 T1648 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 634607 T1648 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 634607 T1648 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 634608 T1648 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 634609 T1648 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 634609 T1648 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 634609 T1648 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1368752912631/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty2/
[junit4:junit4] 2> 634610 T1648 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@141ab172
[junit4:junit4] 2> 634610 T1648 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 634611 T1648 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty2
[junit4:junit4] 2> 634611 T1648 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty2/index/
[junit4:junit4] 2> 634612 T1648 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 634612 T1648 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty2/index
[junit4:junit4] 2> 634614 T1648 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5d893ab5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a08b15fd),segFN=segments_1,generation=1}
[junit4:junit4] 2> 634614 T1648 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 634616 T1648 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 634616 T1648 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 634617 T1648 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 634618 T1648 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 634618 T1648 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 634619 T1648 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 634619 T1648 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 634620 T1648 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 634620 T1648 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 634621 T1648 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 634624 T1648 oass.SolrIndexSearcher.<init> Opening Searcher@afbcf53b main
[junit4:junit4] 2> 634624 T1648 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty2/tlog
[junit4:junit4] 2> 634625 T1648 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 634625 T1648 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 634642 T1649 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@afbcf53b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 634644 T1648 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 634644 T1648 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 635955 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 635956 T1612 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:54136",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:54136_",
[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> 635956 T1612 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 635956 T1612 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 635960 T1631 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> 635960 T1647 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> 635960 T1618 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> 635960 T1611 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> 636646 T1648 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 636646 T1648 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54136 collection:collection1 shard:shard2
[junit4:junit4] 2> 636647 T1648 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 636652 T1648 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 636654 T1648 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 636655 T1648 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 636655 T1648 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54136/collection1/
[junit4:junit4] 2> 636655 T1648 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 636656 T1648 oasc.SyncStrategy.syncToMe http://127.0.0.1:54136/collection1/ has no replicas
[junit4:junit4] 2> 636656 T1648 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54136/collection1/
[junit4:junit4] 2> 636656 T1648 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 637465 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 637470 T1647 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> 637470 T1631 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> 637470 T1611 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> 637471 T1618 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> 637512 T1648 oasc.ZkController.register We are http://127.0.0.1:54136/collection1/ and leader is http://127.0.0.1:54136/collection1/
[junit4:junit4] 2> 637512 T1648 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54136
[junit4:junit4] 2> 637513 T1648 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 637513 T1648 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 637514 T1648 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 637516 T1648 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 637517 T1589 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 637518 T1589 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 637518 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 637588 T1589 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 637590 T1589 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52795
[junit4:junit4] 2> 637591 T1589 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 637592 T1589 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 637592 T1589 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1368752917170
[junit4:junit4] 2> 637593 T1589 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1368752917170/solr.xml
[junit4:junit4] 2> 637594 T1589 oasc.CoreContainer.<init> New CoreContainer 1993079635
[junit4:junit4] 2> 637594 T1589 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1368752917170/'
[junit4:junit4] 2> 637595 T1589 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1368752917170/'
[junit4:junit4] 2> 637632 T1589 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 637633 T1589 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 637633 T1589 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 637634 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 637634 T1589 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 637635 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 637635 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 637636 T1589 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 637637 T1589 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 637637 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 637641 T1589 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 637642 T1589 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:46577/solr
[junit4:junit4] 2> 637643 T1589 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 637644 T1589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 637646 T1661 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@53e2080f name:ZooKeeperConnection Watcher:127.0.0.1:46577 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 637646 T1589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 637647 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 637652 T1589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 637653 T1663 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6568692 name:ZooKeeperConnection Watcher:127.0.0.1:46577/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 637653 T1589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 637656 T1589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 638659 T1589 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52795_
[junit4:junit4] 2> 638661 T1589 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52795_
[junit4:junit4] 2> 638663 T1618 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> 638663 T1631 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 638663 T1663 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 638663 T1647 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 638663 T1631 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> 638663 T1611 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 638665 T1611 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> 638664 T1618 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 638664 T1647 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> 638667 T1664 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1368752917170/collection1
[junit4:junit4] 2> 638668 T1664 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 638668 T1664 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 638669 T1664 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 638670 T1664 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1368752917170/collection1/'
[junit4:junit4] 2> 638671 T1664 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1368752917170/collection1/lib/README' to classloader
[junit4:junit4] 2> 638671 T1664 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1368752917170/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 638698 T1664 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 638728 T1664 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 638729 T1664 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 638735 T1664 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 638975 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 638976 T1612 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:54136",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:54136_",
[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> 638979 T1647 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> 638979 T1663 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> 638979 T1631 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> 638979 T1611 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> 638979 T1618 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> 639048 T1664 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 639053 T1664 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 639056 T1664 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 639067 T1664 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 639072 T1664 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 639076 T1664 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 639077 T1664 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 639078 T1664 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 639078 T1664 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 639079 T1664 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 639079 T1664 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 639080 T1664 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 639080 T1664 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1368752917170/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3/
[junit4:junit4] 2> 639081 T1664 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@141ab172
[junit4:junit4] 2> 639081 T1664 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 639082 T1664 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3
[junit4:junit4] 2> 639082 T1664 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3/index/
[junit4:junit4] 2> 639083 T1664 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 639083 T1664 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3/index
[junit4:junit4] 2> 639085 T1664 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@68ae4039 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ea7e6ff4),segFN=segments_1,generation=1}
[junit4:junit4] 2> 639085 T1664 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 639087 T1664 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 639087 T1664 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 639088 T1664 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 639088 T1664 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 639089 T1664 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 639089 T1664 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 639089 T1664 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 639090 T1664 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 639090 T1664 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 639092 T1664 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 639094 T1664 oass.SolrIndexSearcher.<init> Opening Searcher@868a3830 main
[junit4:junit4] 2> 639094 T1664 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3/tlog
[junit4:junit4] 2> 639095 T1664 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 639095 T1664 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 639099 T1665 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@868a3830 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 639100 T1664 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 639101 T1664 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 640482 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 640482 T1612 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:52795",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:52795_",
[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> 640483 T1612 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 640483 T1612 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 640503 T1647 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> 640503 T1663 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> 640503 T1618 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> 640503 T1611 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> 640503 T1631 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> 641102 T1664 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 641102 T1664 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52795 collection:collection1 shard:shard1
[junit4:junit4] 2> 641107 T1664 oasc.ZkController.register We are http://127.0.0.1:52795/collection1/ and leader is http://127.0.0.1:43026/collection1/
[junit4:junit4] 2> 641107 T1664 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52795
[junit4:junit4] 2> 641108 T1664 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 641109 T1664 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C106 name=collection1 org.apache.solr.core.SolrCore@ccc347df url=http://127.0.0.1:52795/collection1 node=127.0.0.1:52795_ C106_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:52795, state=down, node_name=127.0.0.1:52795_, collection=collection1, core=collection1}
[junit4:junit4] 2> 641111 T1666 C106 P52795 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 641111 T1664 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 641111 T1666 C106 P52795 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 641112 T1666 C106 P52795 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 641113 T1666 C106 P52795 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 641113 T1589 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 641114 T1589 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 641114 T1666 C106 P52795 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 641115 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 641181 T1589 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 641183 T1589 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:36570
[junit4:junit4] 2> 641184 T1589 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 641185 T1589 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 641185 T1589 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1368752920766
[junit4:junit4] 2> 641186 T1589 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1368752920766/solr.xml
[junit4:junit4] 2> 641186 T1589 oasc.CoreContainer.<init> New CoreContainer -532272959
[junit4:junit4] 2> 641187 T1589 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1368752920766/'
[junit4:junit4] 2> 641187 T1589 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1368752920766/'
[junit4:junit4] 2> 641225 T1589 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 641226 T1589 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 641226 T1589 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 641227 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 641227 T1589 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 641228 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 641228 T1589 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 641229 T1589 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 641230 T1589 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 641230 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 641235 T1589 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 641236 T1589 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:46577/solr
[junit4:junit4] 2> 641236 T1589 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 641237 T1589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 641239 T1678 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2e057bbb name:ZooKeeperConnection Watcher:127.0.0.1:46577 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 641240 T1589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 641241 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 641246 T1589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 641248 T1680 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@105219b name:ZooKeeperConnection Watcher:127.0.0.1:46577/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 641248 T1589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 641251 T1589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 641355 T1625 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 642007 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 642008 T1612 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:52795",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:52795_",
[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> 642040 T1647 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> 642040 T1611 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> 642040 T1663 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> 642040 T1618 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> 642040 T1680 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> 642040 T1631 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> 642254 T1589 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36570_
[junit4:junit4] 2> 642257 T1589 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:36570_
[junit4:junit4] 2> 642261 T1618 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> 642261 T1680 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> 642261 T1611 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 642262 T1663 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 642262 T1647 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 642262 T1631 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 642263 T1611 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> 642264 T1618 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 642264 T1663 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> 642264 T1647 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> 642265 T1631 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> 642266 T1680 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 642272 T1681 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1368752920766/collection1
[junit4:junit4] 2> 642273 T1681 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 642273 T1681 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 642274 T1681 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 642275 T1681 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1368752920766/collection1/'
[junit4:junit4] 2> 642276 T1681 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1368752920766/collection1/lib/README' to classloader
[junit4:junit4] 2> 642276 T1681 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1368752920766/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 642304 T1681 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 642335 T1681 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 642337 T1681 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 642341 T1681 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 642357 T1625 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 642677 T1681 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 642682 T1681 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 642685 T1681 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 642696 T1681 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 642699 T1681 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 642703 T1681 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 642704 T1681 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 642704 T1681 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 642705 T1681 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 642706 T1681 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 642706 T1681 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 642707 T1681 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 642707 T1681 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1368752920766/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4/
[junit4:junit4] 2> 642707 T1681 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@141ab172
[junit4:junit4] 2> 642708 T1681 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 642708 T1681 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4
[junit4:junit4] 2> 642709 T1681 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4/index/
[junit4:junit4] 2> 642709 T1681 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 642709 T1681 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4/index
[junit4:junit4] 2> 642711 T1681 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75a25757 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c626618b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 642711 T1681 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 642713 T1681 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 642713 T1681 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 642714 T1681 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 642714 T1681 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 642715 T1681 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 642715 T1681 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 642716 T1681 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 642716 T1681 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 642716 T1681 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 642718 T1681 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 642719 T1681 oass.SolrIndexSearcher.<init> Opening Searcher@978f7a71 main
[junit4:junit4] 2> 642720 T1681 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4/tlog
[junit4:junit4] 2> 642721 T1681 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 642721 T1681 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 642724 T1682 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@978f7a71 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 642725 T1681 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 642726 T1681 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 642850 T1625 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=4&wt=javabin&nodeName=127.0.0.1:52795_&core=collection1} status=0 QTime=1731
[junit4:junit4] 2> 643546 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 643546 T1612 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:36570",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:36570_",
[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> 643547 T1612 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 643547 T1612 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 643550 T1647 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> 643550 T1631 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> 643550 T1680 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> 643550 T1611 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> 643551 T1663 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> 643550 T1618 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> 643727 T1681 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 643728 T1681 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:36570 collection:collection1 shard:shard2
[junit4:junit4] 2> 643731 T1681 oasc.ZkController.register We are http://127.0.0.1:36570/collection1/ and leader is http://127.0.0.1:54136/collection1/
[junit4:junit4] 2> 643732 T1681 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:36570
[junit4:junit4] 2> 643732 T1681 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 643733 T1681 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C107 name=collection1 org.apache.solr.core.SolrCore@d375cbe9 url=http://127.0.0.1:36570/collection1 node=127.0.0.1:36570_ C107_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:36570, state=down, node_name=127.0.0.1:36570_, collection=collection1, core=collection1}
[junit4:junit4] 2> 643733 T1683 C107 P36570 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 643734 T1681 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 643734 T1683 C107 P36570 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 643734 T1683 C107 P36570 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 643735 T1683 C107 P36570 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 643735 T1589 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 643736 T1589 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 643737 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 643740 T1683 C107 P36570 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 643742 T1589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 643743 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 643746 T1643 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 643749 T1627 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1368752908104/onenodecollectioncore
[junit4:junit4] 2> 643750 T1627 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4] 2> 643751 T1627 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4] 2> 643752 T1627 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 643754 T1627 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 643755 T1627 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4] 2> 643759 T1627 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4] 2> 643760 T1627 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1368752908104/onenodecollectioncore/'
[junit4:junit4] 2> 643799 T1627 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 643834 T1627 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 643836 T1627 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 643841 T1627 oass.IndexSchema.readSchema [onenodecollectioncore] Schema name=test
[junit4:junit4] 2> 644177 T1627 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 644182 T1627 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 644185 T1627 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 644195 T1627 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 644199 T1627 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 644203 T1627 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 644205 T1627 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 644205 T1627 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 644206 T1627 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 644208 T1627 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 644208 T1627 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 644209 T1627 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 644210 T1627 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1368752908104/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1368752904379/onenodecollection/
[junit4:junit4] 2> 644211 T1627 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@141ab172
[junit4:junit4] 2> 644212 T1627 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 644213 T1627 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1368752904379/onenodecollection
[junit4:junit4] 2> 644214 T1627 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1368752904379/onenodecollection/index/
[junit4:junit4] 2> 644215 T1627 oasc.SolrCore.initIndex WARN [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1368752904379/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 644216 T1627 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1368752904379/onenodecollection/index
[junit4:junit4] 2> 644218 T1627 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e853714 lockFactory=org.apache.lucene.store.NativeFSLockFactory@55b93d03),segFN=segments_1,generation=1}
[junit4:junit4] 2> 644218 T1627 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 644220 T1627 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 644221 T1627 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 644222 T1627 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 644223 T1627 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 644224 T1627 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 644224 T1627 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 644225 T1627 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 644226 T1627 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 644227 T1627 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 644229 T1627 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 644231 T1627 oass.SolrIndexSearcher.<init> Opening Searcher@25877e76 main
[junit4:junit4] 2> 644232 T1627 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1368752904379/onenodecollection/tlog
[junit4:junit4] 2> 644233 T1627 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 644234 T1627 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 644238 T1685 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@25877e76 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 644239 T1627 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4] 2> C106_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:52795, state=recovering, node_name=127.0.0.1:52795_, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4] 2> 644887 T1666 C106 P52795 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:43026/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 644888 T1666 C106 P52795 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52795 START replicas=[http://127.0.0.1:43026/collection1/] nUpdates=100
[junit4:junit4] 2> 644889 T1666 C106 P52795 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 644889 T1666 C106 P52795 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 644890 T1666 C106 P52795 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 644890 T1666 C106 P52795 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 644890 T1666 C106 P52795 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 644891 T1666 C106 P52795 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:43026/collection1/. core=collection1
[junit4:junit4] 2> 644891 T1666 C106 P52795 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C108 name=collection1 org.apache.solr.core.SolrCore@4594ce1e url=http://127.0.0.1:43026/collection1 node=127.0.0.1:43026_ C108_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:43026, state=active, node_name=127.0.0.1:43026_, collection=collection1, shard=shard1, core=collection1, leader=true}
[junit4:junit4] 2> 644896 T1624 C108 P43026 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 644898 T1624 C108 P43026 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3fced0f1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@284ab057),segFN=segments_1,generation=1}
[junit4:junit4] 2> 644899 T1624 C108 P43026 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 644900 T1624 C108 P43026 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3fced0f1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@284ab057),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3fced0f1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@284ab057),segFN=segments_2,generation=2}
[junit4:junit4] 2> 644900 T1624 C108 P43026 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 644901 T1624 C108 P43026 oass.SolrIndexSearcher.<init> Opening Searcher@7b574a8 realtime
[junit4:junit4] 2> 644902 T1624 C108 P43026 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 644903 T1624 C108 P43026 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 7
[junit4:junit4] 2> 645054 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 645055 T1612 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:36570",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:36570_",
[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> 645058 T1612 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:43026",
[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:43026_",
[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> 645059 T1612 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4] 2> 645059 T1612 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 645063 T1647 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> 645063 T1618 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> 645064 T1631 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> 645064 T1680 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> 645063 T1663 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> 645063 T1611 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> 645241 T1627 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4] 2> 645242 T1627 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:43026 collection:onenodecollection shard:shard1
[junit4:junit4] 2> 645243 T1627 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4] 2> 645249 T1627 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 645251 T1627 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 645252 T1627 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 645253 T1627 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:43026/onenodecollectioncore/
[junit4:junit4] 2> 645254 T1627 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 645255 T1627 oasc.SyncStrategy.syncToMe http://127.0.0.1:43026/onenodecollectioncore/ has no replicas
[junit4:junit4] 2> 645256 T1627 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:43026/onenodecollectioncore/
[junit4:junit4] 2> 645256 T1627 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4] 2> 645408 T1666 C106 P52795 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 645409 T1666 C106 P52795 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 645411 T1626 C108 P43026 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 645412 T1626 C108 P43026 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=2
[junit4:junit4] 2> 645412 T1666 C106 P52795 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 645413 T1666 C106 P52795 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 645413 T1666 C106 P52795 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 645415 T1624 C108 P43026 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 645415 T1666 C106 P52795 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 645416 T1625 C108 P43026 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=521
[junit4:junit4] 2> 645416 T1666 C106 P52795 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3/index.20130517070845063
[junit4:junit4] 2> 645417 T1666 C106 P52795 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@fb3b381f lockFactory=org.apache.lucene.store.NativeFSLockFactory@6fced230) fullCopy=false
[junit4:junit4] 2> 645418 T1626 C108 P43026 oasc.SolrCore.execute [collection1] webapp= path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=0
[junit4:junit4] 2> 645421 T1666 C106 P52795 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 645421 T1666 C106 P52795 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 645421 T1666 C106 P52795 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 645422 T1666 C106 P52795 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@68ae4039 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ea7e6ff4),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@68ae4039 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ea7e6ff4),segFN=segments_2,generation=2}
[junit4:junit4] 2> 645423 T1666 C106 P52795 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 645423 T1666 C106 P52795 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 645423 T1666 C106 P52795 oass.SolrIndexSearcher.<init> Opening Searcher@c57c7bfa main
[junit4:junit4] 2> 645424 T1665 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c57c7bfa main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 645425 T1666 C106 P52795 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3/index.20130517070845063 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3/index.20130517070845063;done=true>>]
[junit4:junit4] 2> 645425 T1666 C106 P52795 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3/index.20130517070845063
[junit4:junit4] 2> 645425 T1666 C106 P52795 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3/index.20130517070845063
[junit4:junit4] 2> 645426 T1666 C106 P52795 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 645426 T1666 C106 P52795 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 645426 T1666 C106 P52795 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 645426 T1666 C106 P52795 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 645427 T1666 C106 P52795 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 645747 T1643 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 645748 T1643 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=5&wt=javabin&nodeName=127.0.0.1:36570_&core=collection1} status=0 QTime=2002
[junit4:junit4] 2> 646569 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 646575 T1612 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:52795",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:52795_",
[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> 646578 T1647 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> 646578 T1663 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> 646578 T1611 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> 646578 T1618 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> 646578 T1631 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> 646578 T1680 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> 646615 T1627 oasc.ZkController.register We are http://127.0.0.1:43026/onenodecollectioncore/ and leader is http://127.0.0.1:43026/onenodecollectioncore/
[junit4:junit4] 2> 646615 T1627 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:43026
[junit4:junit4] 2> 646616 T1627 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 646617 T1627 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4] 2> 646619 T1627 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 646620 T1627 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1368752904379/onenodecollection&action=CREATE&version=2&numShards=1&name=onenodecollectioncore&wt=javabin&roles=none&collection=onenodecollection} status=0 QTime=2871
[junit4:junit4] 2> 646621 T1589 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 646622 T1589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 647624 T1589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C107_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:36570, state=recovering, node_name=127.0.0.1:36570_, collection=collection1, shard=shard2, core=collection1}
[junit4:junit4] 2> 647749 T1683 C107 P36570 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:54136/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 647750 T1683 C107 P36570 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:36570 START replicas=[http://127.0.0.1:54136/collection1/] nUpdates=100
[junit4:junit4] 2> 647750 T1683 C107 P36570 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 647750 T1683 C107 P36570 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 647751 T1683 C107 P36570 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 647751 T1683 C107 P36570 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 647751 T1683 C107 P36570 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 647751 T1683 C107 P36570 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:54136/collection1/. core=collection1
[junit4:junit4] 2> 647752 T1683 C107 P36570 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C109 name=collection1 org.apache.solr.core.SolrCore@8a16c4a4 url=http://127.0.0.1:54136/collection1 node=127.0.0.1:54136_ C109_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:54136, state=active, node_name=127.0.0.1:54136_, collection=collection1, shard=shard2, core=collection1, leader=true}
[junit4:junit4] 2> 647755 T1643 C109 P54136 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 647757 T1641 C109 P54136 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 647759 T1641 C109 P54136 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5d893ab5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a08b15fd),segFN=segments_1,generation=1}
[junit4:junit4] 2> 647760 T1641 C109 P54136 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 647761 T1641 C109 P54136 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5d893ab5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a08b15fd),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5d893ab5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a08b15fd),segFN=segments_2,generation=2}
[junit4:junit4] 2> 647761 T1641 C109 P54136 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 647762 T1641 C109 P54136 oass.SolrIndexSearcher.<init> Opening Searcher@b096bdab realtime
[junit4:junit4] 2> 647763 T1641 C109 P54136 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 647764 T1641 C109 P54136 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 7
[junit4:junit4] 2> 647765 T1683 C107 P36570 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 647765 T1683 C107 P36570 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 647766 T1642 C109 P54136 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 647767 T1642 C109 P54136 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 647768 T1683 C107 P36570 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 647768 T1683 C107 P36570 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 647768 T1683 C107 P36570 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 647770 T1643 C109 P54136 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 647771 T1683 C107 P36570 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 647771 T1683 C107 P36570 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4/index.20130517070847418
[junit4:junit4] 2> 647772 T1683 C107 P36570 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2bd67ed lockFactory=org.apache.lucene.store.NativeFSLockFactory@12583fe3) fullCopy=false
[junit4:junit4] 2> 647773 T1641 C109 P54136 oasc.SolrCore.execute [collection1] webapp= path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=0
[junit4:junit4] 2> 647775 T1683 C107 P36570 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 647775 T1683 C107 P36570 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 647776 T1683 C107 P36570 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 647777 T1683 C107 P36570 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75a25757 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c626618b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75a25757 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c626618b),segFN=segments_2,generation=2}
[junit4:junit4] 2> 647777 T1683 C107 P36570 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 647778 T1683 C107 P36570 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 647778 T1683 C107 P36570 oass.SolrIndexSearcher.<init> Opening Searcher@3511ab92 main
[junit4:junit4] 2> 647779 T1682 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3511ab92 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 647779 T1683 C107 P36570 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4/index.20130517070847418 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4/index.20130517070847418;done=true>>]
[junit4:junit4] 2> 647780 T1683 C107 P36570 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4/index.20130517070847418
[junit4:junit4] 2> 647780 T1683 C107 P36570 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4/index.20130517070847418
[junit4:junit4] 2> 647780 T1683 C107 P36570 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 647780 T1683 C107 P36570 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 647780 T1683 C107 P36570 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 647781 T1683 C107 P36570 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 647783 T1683 C107 P36570 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 648084 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 648085 T1612 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:43026",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:43026__onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:43026_",
[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> 648088 T1612 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:36570",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:36570_",
[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> 648093 T1647 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> 648093 T1663 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> 648093 T1618 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> 648093 T1611 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> 648093 T1680 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> 648093 T1631 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> 648625 T1589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 648627 T1589 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4] 2> 648627 T1589 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 648639 T1589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 648640 T1691 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ee78d333 name:ZooKeeperConnection Watcher:127.0.0.1:46577 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 648641 T1589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 648678 T1589 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 41328
[junit4:junit4] 2> 648678 T1589 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1179259968
[junit4:junit4] 2> 649598 T1612 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 649599 T1612 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41328",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:41328_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 649620 T1647 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> 649620 T1631 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> 649620 T1611 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> 649620 T1663 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> 649620 T1680 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> 650680 T1589 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 650681 T1589 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 650683 T1589 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@4daeacbf
[junit4:junit4] 2> 650688 T1589 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> 650689 T1589 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 650690 T1589 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 650690 T1589 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 650691 T1589 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 650692 T1589 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 650692 T1589 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/control/data [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/control/data;done=false>>]
[junit4:junit4] 2> 650693 T1589 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/control/data
[junit4:junit4] 2> 650694 T1589 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/control/data/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/control/data/index;done=false>>]
[junit4:junit4] 2> 650694 T1589 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/control/data/index
[junit4:junit4] 2> 650695 T1612 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89702590341578755-127.0.0.1:41328_-n_0000000000) am no longer a leader.
[junit4:junit4] 2> 650695 T1680 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> 650696 T1611 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 650696 T1663 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 650697 T1647 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 650696 T1611 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> 650697 T1663 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> 650697 T1611 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 650697 T1647 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> 650697 T1680 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 650697 T1631 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 650699 T1631 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> 650700 T1631 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 650702 T1631 oasc.Overseer.start Overseer (id=89702590341578758-127.0.0.1:43026_-n_0000000001) starting
[junit4:junit4] 2> 650705 T1693 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 650706 T1692 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 650707 T1692 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 650708 T1692 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:41328",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:41328_",
[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> 650711 T1647 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> 650711 T1663 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> 650711 T1631 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> 650711 T1680 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> 650717 T1589 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 650769 T1589 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 43026
[junit4:junit4] 2> 650770 T1589 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-1538632010
[junit4:junit4] 2> 652216 T1692 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 652217 T1692 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43026",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:43026__onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:43026_",
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 652220 T1692 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43026",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:43026_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 652223 T1647 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> 652223 T1663 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> 652223 T1680 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> 652224 T1631 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> 653772 T1589 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 653773 T1589 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 653775 T1589 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4] 2> 653776 T1589 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@4594ce1e
[junit4:junit4] 2> 653781 T1589 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> 653781 T1589 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 653782 T1589 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 653783 T1589 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 653784 T1589 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 653785 T1589 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 653786 T1589 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty1 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty1;done=false>>]
[junit4:junit4] 2> 653786 T1589 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty1
[junit4:junit4] 2> 653791 T1589 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty1/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty1/index;done=false>>]
[junit4:junit4] 2> 653792 T1589 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty1/index
[junit4:junit4] 2> 653793 T1589 oasc.SolrCore.close [onenodecollectioncore] CLOSING SolrCore org.apache.solr.core.SolrCore@a14abdb3
[junit4:junit4] 2> 653799 T1589 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> 653800 T1589 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 653801 T1589 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 653801 T1589 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 653802 T1589 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4] 2> 653803 T1589 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 653804 T1589 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1368752904379/onenodecollection/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1368752904379/onenodecollection/index;done=false>>]
[junit4:junit4] 2> 653804 T1589 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1368752904379/onenodecollection/index
[junit4:junit4] 2> 653805 T1589 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1368752904379/onenodecollection [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1368752904379/onenodecollection;done=false>>]
[junit4:junit4] 2> 653806 T1589 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1368752904379/onenodecollection
[junit4:junit4] 2> 653807 T1692 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89702590341578758-127.0.0.1:43026_-n_0000000001) am no longer a leader.
[junit4:junit4] 2> 653809 T1680 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> 653809 T1631 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 653809 T1631 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> 653810 T1647 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 653810 T1631 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 653810 T1663 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 653811 T1680 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 653812 T1663 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4] 2> 653813 T1663 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4] 2> 653813 T1663 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 653812 T1647 oasc.Overseer.start Overseer (id=89702590341578760-127.0.0.1:54136_-n_0000000002) starting
[junit4:junit4] 2> 653813 T1663 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52795/collection1/
[junit4:junit4] 2> 653814 T1663 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52795 START replicas=[http://127.0.0.1:43026/collection1/] nUpdates=100
[junit4:junit4] 2> 653814 T1663 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52795 DONE. We have no versions. sync failed.
[junit4:junit4] 2> 653814 T1663 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4] 2> 653815 T1663 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> 653815 T1663 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52795/collection1/
[junit4:junit4] 2> 653815 T1663 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 653817 T1696 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 653817 T1647 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 653818 T1647 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> 653819 T1663 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 653819 T1663 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> 653820 T1695 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 653822 T1695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 653823 T1695 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:43026",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:43026_",
[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> 653825 T1695 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:43026",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:43026__onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:43026_",
[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> 653829 T1589 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 653833 T1663 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> 653833 T1647 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> 653833 T1680 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> 653881 T1589 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 54136
[junit4:junit4] 2> 653882 T1589 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-1760032723
[junit4:junit4] 2> 654884 T1589 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 654884 T1589 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 654886 T1589 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@8a16c4a4
[junit4:junit4] 2> 654889 T1589 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> 654890 T1589 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 654890 T1589 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 654891 T1589 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 654892 T1589 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 654892 T1589 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 654893 T1589 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty2 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty2;done=false>>]
[junit4:junit4] 2> 654893 T1589 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty2
[junit4:junit4] 2> 654894 T1589 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty2/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty2/index;done=false>>]
[junit4:junit4] 2> 654894 T1589 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty2/index
[junit4:junit4] 2> 654895 T1695 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89702590341578760-127.0.0.1:54136_-n_0000000002) am no longer a leader.
[junit4:junit4] 2> 654897 T1680 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> 654897 T1663 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 654897 T1663 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> 654899 T1680 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 654899 T1663 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 654900 T1680 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 654901 T1663 oasc.Overseer.start Overseer (id=89702590341578762-127.0.0.1:52795_-n_0000000003) starting
[junit4:junit4] 2> 654901 T1680 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4] 2> 654902 T1680 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4] 2> 654902 T1680 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 654902 T1680 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:36570/collection1/
[junit4:junit4] 2> 654903 T1680 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 654903 T1680 oasc.SyncStrategy.syncToMe http://127.0.0.1:36570/collection1/ has no replicas
[junit4:junit4] 2> 654904 T1680 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:36570/collection1/
[junit4:junit4] 2> 654904 T1680 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 654904 T1698 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 654905 T1697 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 654907 T1697 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 654908 T1697 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54136",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:54136_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 654911 T1697 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:54136",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:54136_",
[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> 654917 T1589 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 654921 T1680 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> 654921 T1663 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> 654970 T1589 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 52795
[junit4:junit4] 2> 654970 T1589 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1993079635
[junit4:junit4] 2> 655972 T1589 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 655973 T1589 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 655975 T1589 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@ccc347df
[junit4:junit4] 2> 655980 T1589 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> 655981 T1589 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 655982 T1589 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 655983 T1589 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 655985 T1589 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 655987 T1589 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 655988 T1589 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3/index;done=false>>]
[junit4:junit4] 2> 655989 T1589 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3/index
[junit4:junit4] 2> 655990 T1589 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3;done=false>>]
[junit4:junit4] 2> 655991 T1589 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty3
[junit4:junit4] 2> 655992 T1697 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89702590341578762-127.0.0.1:52795_-n_0000000003) am no longer a leader.
[junit4:junit4] 2> 655993 T1680 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> 655993 T1591 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eb007d8be000a, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:780)
[junit4:junit4] 2>
[junit4:junit4] 2> 655995 T1680 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4:junit4] 2> 655996 T1680 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 655997 T1680 oasc.Overseer.start Overseer (id=89702590341578764-127.0.0.1:36570_-n_0000000004) starting
[junit4:junit4] 2> 656000 T1700 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 656001 T1699 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 656002 T1699 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 656003 T1699 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52795",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:52795_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 656005 T1699 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:52795",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:52795_",
[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> 656008 T1680 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> 656013 T1589 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 656066 T1589 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 36570
[junit4:junit4] 2> 656066 T1589 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-532272959
[junit4:junit4] 2> 656197 T1647 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 656197 T1647 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> 656198 T1647 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 657068 T1589 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 657068 T1589 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 657070 T1589 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@d375cbe9
[junit4:junit4] 2> 657075 T1589 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> 657076 T1589 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 657076 T1589 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 657077 T1589 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 657078 T1589 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 657078 T1589 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 657079 T1589 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4/index;done=false>>]
[junit4:junit4] 2> 657079 T1589 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4/index
[junit4:junit4] 2> 657080 T1589 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4;done=false>>]
[junit4:junit4] 2> 657080 T1589 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1368752904379/jetty4
[junit4:junit4] 2> 657081 T1699 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89702590341578764-127.0.0.1:36570_-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 657082 T1680 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> 657082 T1680 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 657082 T1680 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 657102 T1589 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 657160 T1589 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 657161 T1589 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:46577 46577
[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":"89702590341578755-127.0.0.1:41328_-n_0000000000"}
[junit4:junit4] 1> /solr/overseer_elect/election (5)
[junit4:junit4] 1> /solr/overseer_elect/election/89702590341578760-127.0.0.1:54136_-n_0000000002 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89702590341578758-127.0.0.1:43026_-n_0000000001 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89702590341578755-127.0.0.1:41328_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89702590341578764-127.0.0.1:36570_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89702590341578762-127.0.0.1:52795_-n_0000000003 (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/89702590341578755-1-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:41328",
[junit4:junit4] 1> "node_name":"127.0.0.1:41328_",
[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/89702590341578758-2-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89702590341578762-4-n_0000000001 (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/89702590341578760-3-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard2/election/89702590341578764-5-n_0000000001 (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:43026",
[junit4:junit4] 1> "node_name":"127.0.0.1:43026_",
[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:54136",
[junit4:junit4] 1> "node_name":"127.0.0.1:54136_",
[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/89702590341578758-127.0.0.1:43026__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:43026",
[junit4:junit4] 1> "node_name":"127.0.0.1:43026_",
[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:41328_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:36570_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:52795_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:54136_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:43026_ (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":{"1":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:41328",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:41328_",
[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:43026__onenodecollectioncore":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:43026",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:43026_",
[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> "2":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:43026",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:43026_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"},
[junit4:junit4] 1> "4":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:52795",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:52795_",
[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> "3":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54136",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:54136_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"},
[junit4:junit4] 1> "5":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:36570",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:36570_",
[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=49DFCF95986A8EAC -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_UY -Dtests.timezone=Asia/Qyzylorda -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR 32.5s J1 | BasicDistributedZk2Test.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:54136/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([49DFCF95986A8EAC:C839418DEF35EE90]: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> 657220 T1589 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 32497 T1588 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> 657293 T1663 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 657294 T1663 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> 657294 T1663 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene3x, sim=DefaultSimilarity, locale=es_UY, timezone=Asia/Qyzylorda
[junit4:junit4] 2> NOTE: Linux 3.2.0-41-generic x86/IBM Corporation 1.7.0 (32-bit)/cpus=8,threads=2,free=75774872,total=169476096
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestSolr4Spatial, SolrCmdDistributorTest, OpenCloseCoreStressTest, ChaosMonkeyShardSplitTest, DefaultValueUpdateProcessorTest, SolrIndexConfigTest, FullSolrCloudDistribCmdsTest, CoreContainerCoreInitFailuresTest, ClusterStateTest, TestRTGBase, TestMaxScoreQueryParser, SolrRequestParserTest, CopyFieldTest, TestRandomFaceting, SuggesterTSTTest, TestSolrJ, BasicZkTest, NumericFieldsTest, TestSchemaVersionResource, TestUpdate, TestLuceneMatchVersion, TestFieldTypeCollectionResource, TestArbitraryIndexDir, TestCopyFieldCollectionResource, TestAddFieldRealTimeGet, TestJmxMonitoredMap, DOMUtilTest, TestFoldingMultitermQuery, TermVectorComponentDistributedTest, TestNumberUtils, TestZkChroot, ConvertedLegacyTest, TestSolrXMLSerializer, SpellCheckComponentTest, IndexSchemaRuntimeFieldTest, TestJmxIntegration, CachingDirectoryFactoryTest, TestCSVResponseWriter, ZkSolrClientTest, TestUtils, TestCoreDiscovery, TestWordDelimiterFilterFactory, TestFieldCollectionResource, XmlUpdateRequestHandlerTest, TestManagedSchema, TestMultiCoreConfBootstrap, StandardRequestHandlerTest, QueryResultKeyTest, RequestHandlersTest, FileUtilsTest, BadIndexSchemaTest, StatsComponentTest, TestDistributedGrouping, TestSchemaSimilarityResource, SimplePostToolTest, TestPartialUpdateDeduplication, OpenExchangeRatesOrgProviderTest, BasicDistributedZk2Test]
[junit4:junit4] Completed on J1 in 32.78s, 1 test, 1 error <<< FAILURES!
[...truncated 602 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:383: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:376: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1243: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:887: There were test failures: 296 suites, 1234 tests, 1 error, 14 ignored (8 assumptions)
Total time: 45 minutes 45 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