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/07/17 17:10:37 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/ibm-j9-jdk6) - Build # 6530
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/6530/
Java: 32bit/ibm-j9-jdk6 -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:50954/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:50954/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
at __randomizedtesting.SeedInfo.seed([7B374360BB4D6C3B:FAD1CD78CC120C07]: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:196)
at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:88)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
at java.lang.reflect.Method.invoke(Method.java:611)
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:738)
Build Log:
[...truncated 9190 lines...]
[junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4] 2> 882879 T2725 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4] 2> 882884 T2725 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1374072971490
[junit4] 2> 882886 T2725 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 882887 T2726 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 882987 T2725 oasc.ZkTestServer.run start zk server on port:59952
[junit4] 2> 882989 T2725 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 883062 T2732 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@66806680 name:ZooKeeperConnection Watcher:127.0.0.1:59952 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 883063 T2725 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 883064 T2725 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 883074 T2725 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 883084 T2734 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3ab73ab7 name:ZooKeeperConnection Watcher:127.0.0.1:59952/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 883086 T2725 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 883087 T2725 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4] 2> 883107 T2725 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4] 2> 883117 T2725 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4] 2> 883123 T2725 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4] 2> 883135 T2725 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] 2> 883136 T2725 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4] 2> 883162 T2725 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] 2> 883163 T2725 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4] 2> 883176 T2725 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] 2> 883178 T2725 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4] 2> 883190 T2725 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] 2> 883191 T2725 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4] 2> 883202 T2725 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] 2> 883204 T2725 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4] 2> 883214 T2725 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] 2> 883216 T2725 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4] 2> 883258 T2725 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] 2> 883260 T2725 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 883269 T2725 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] 2> 883271 T2725 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4] 2> 883281 T2725 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] 2> 883282 T2725 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4] 2> 883601 T2725 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 883604 T2725 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:60973
[junit4] 2> 883606 T2725 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 883608 T2725 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 883609 T2725 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-1374072971908
[junit4] 2> 883610 T2725 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-1374072971908/'
[junit4] 2> 883623 T2725 oasc.ConfigSolr.fromFile Loading container configuration from /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1374072971908/solr.xml
[junit4] 2> 883670 T2725 oasc.CoreContainer.<init> New CoreContainer 1786931842
[junit4] 2> 883672 T2725 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1374072971908/]
[junit4] 2> 883674 T2725 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 883675 T2725 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 883676 T2725 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 883677 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 883678 T2725 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 883679 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 883680 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 883681 T2725 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 883682 T2725 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 883683 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 883692 T2725 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 883694 T2725 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:59952/solr
[junit4] 2> 883696 T2725 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 883698 T2725 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 883703 T2745 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6d2a6d2a name:ZooKeeperConnection Watcher:127.0.0.1:59952 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 883703 T2725 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 883708 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 883717 T2725 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 883721 T2747 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3ab03ab0 name:ZooKeeperConnection Watcher:127.0.0.1:59952/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 883751 T2725 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 883757 T2725 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 883770 T2725 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 883783 T2725 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 883790 T2725 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60973_
[junit4] 2> 883793 T2725 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60973_
[junit4] 2> 883806 T2725 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 883823 T2725 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 883833 T2725 oasc.Overseer.start Overseer (id=90051246261796867-127.0.0.1:60973_-n_0000000000) starting
[junit4] 2> 883853 T2725 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 883879 T2749 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 883880 T2725 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 883891 T2725 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 883897 T2725 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 883915 T2748 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 883916 T2750 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 883917 T2750 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 883922 T2750 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 885432 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 885437 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:60973",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "node_name":"127.0.0.1:60973_",
[junit4] 2> "numShards":"1",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"control_collection",
[junit4] 2> "shard":null,
[junit4] 2> "core":"collection1"}
[junit4] 2> 885438 T2748 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4] 2> 885439 T2748 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 885454 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 885923 T2750 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 885924 T2750 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-1374072971908/collection1
[junit4] 2> 885924 T2750 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4] 2> 885927 T2750 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 885927 T2750 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4] 2> 885953 T2750 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-1374072971908/collection1/'
[junit4] 2> 885955 T2750 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-1374072971908/collection1/lib/README' to classloader
[junit4] 2> 885955 T2750 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-1374072971908/collection1/lib/classes/' to classloader
[junit4] 2> 886014 T2750 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 886067 T2750 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 886071 T2750 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 886078 T2750 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 886738 T2750 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 886739 T2750 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 886740 T2750 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 886748 T2750 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 886752 T2750 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 886811 T2750 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 886825 T2750 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 886836 T2750 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 886863 T2750 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 886864 T2750 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 886865 T2750 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 886887 T2750 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 886888 T2750 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 886888 T2750 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 886889 T2750 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-1374072971908/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/control/data/
[junit4] 2> 886890 T2750 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@73167316
[junit4] 2> 886892 T2750 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/control/data
[junit4] 2> 886893 T2750 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/control/data/index/
[junit4] 2> 886894 T2750 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/control/data/index' doesn't exist. Creating new index...
[junit4] 2> 886895 T2750 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/control/data/index
[junit4] 2> 886904 T2750 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@57385738 lockFactory=org.apache.lucene.store.NativeFSLockFactory@716e716e),segFN=segments_1,generation=1}
[junit4] 2> 886905 T2750 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 886912 T2750 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 886913 T2750 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 886914 T2750 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 886915 T2750 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 886916 T2750 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 886917 T2750 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 886918 T2750 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 886919 T2750 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 886920 T2750 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 886922 T2750 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 886925 T2750 oass.SolrIndexSearcher.<init> Opening Searcher@33033303 main
[junit4] 2> 886926 T2750 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 886927 T2750 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 886933 T2751 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@33033303 main{StandardDirectoryReader(segments_1:1)}
[junit4] 2> 886938 T2750 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 886938 T2750 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:60973 collection:control_collection shard:shard1
[junit4] 2> 886939 T2750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4] 2> 886950 T2750 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4] 2> 886985 T2750 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4] 2> 886997 T2750 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 886997 T2750 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> 886998 T2750 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:60973/collection1/
[junit4] 2> 886999 T2750 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 887000 T2750 oasc.SyncStrategy.syncToMe http://127.0.0.1:60973/collection1/ has no replicas
[junit4] 2> 887001 T2750 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:60973/collection1/ shard1
[junit4] 2> 887002 T2750 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4] 2> 888487 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 888523 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 888600 T2750 oasc.ZkController.register We are http://127.0.0.1:60973/collection1/ and leader is http://127.0.0.1:60973/collection1/
[junit4] 2> 888601 T2750 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60973
[junit4] 2> 888601 T2750 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 888602 T2750 oasc.ZkController.publish publishing core=collection1 state=active
[junit4] 2> 888603 T2750 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 888608 T2750 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 888611 T2725 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4] 2> 888611 T2725 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 888613 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 888622 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4] 2> 888624 T2725 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 888628 T2754 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@24f824f8 name:ZooKeeperConnection Watcher:127.0.0.1:59952/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 888629 T2725 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 888633 T2725 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 888665 T2725 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4] 2> 888928 T2725 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 888934 T2725 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49722
[junit4] 2> 888935 T2725 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 888937 T2725 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 888938 T2725 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-1374072977270
[junit4] 2> 888939 T2725 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-1374072977270/'
[junit4] 2> 888956 T2725 oasc.ConfigSolr.fromFile Loading container configuration from /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1374072977270/solr.xml
[junit4] 2> 889063 T2725 oasc.CoreContainer.<init> New CoreContainer 1617518697
[junit4] 2> 889065 T2725 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1374072977270/]
[junit4] 2> 889067 T2725 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 889068 T2725 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 889069 T2725 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 889070 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 889072 T2725 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 889073 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 889074 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 889075 T2725 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 889076 T2725 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 889078 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 889087 T2725 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 889090 T2725 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:59952/solr
[junit4] 2> 889092 T2725 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 889093 T2725 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 889095 T2765 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@238d238d name:ZooKeeperConnection Watcher:127.0.0.1:59952 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 889096 T2725 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 889103 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 889111 T2725 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 889128 T2767 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@63216321 name:ZooKeeperConnection Watcher:127.0.0.1:59952/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 889128 T2725 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 889156 T2725 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 890083 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 890088 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:60973",
[junit4] 2> "state":"active",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "node_name":"127.0.0.1:60973_",
[junit4] 2> "numShards":"1",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"control_collection",
[junit4] 2> "shard":"shard1",
[junit4] 2> "core":"collection1"}
[junit4] 2> 890103 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 890103 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 890108 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 890168 T2725 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49722_
[junit4] 2> 890171 T2725 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49722_
[junit4] 2> 890177 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 890178 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 890180 T2747 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 890181 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 890188 T2754 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 890195 T2767 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 890207 T2768 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 890207 T2768 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 890210 T2768 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 891658 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 891662 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:49722",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "node_name":"127.0.0.1:49722_",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":null,
[junit4] 2> "core":"collection1"}
[junit4] 2> 891663 T2748 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4] 2> 891664 T2748 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 891679 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 891680 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 891680 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 892214 T2768 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 892215 T2768 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-1374072977270/collection1
[junit4] 2> 892216 T2768 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 892218 T2768 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 892219 T2768 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 892224 T2768 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-1374072977270/collection1/'
[junit4] 2> 892226 T2768 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-1374072977270/collection1/lib/README' to classloader
[junit4] 2> 892227 T2768 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-1374072977270/collection1/lib/classes/' to classloader
[junit4] 2> 892282 T2768 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 892355 T2768 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 892360 T2768 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 892368 T2768 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 893157 T2768 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 893157 T2768 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 893158 T2768 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 893165 T2768 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 893170 T2768 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 893244 T2768 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 893254 T2768 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 893261 T2768 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 893267 T2768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 893268 T2768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 893269 T2768 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 893275 T2768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 893275 T2768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 893276 T2768 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 893277 T2768 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-1374072977270/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty1/
[junit4] 2> 893278 T2768 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@73167316
[junit4] 2> 893279 T2768 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty1
[junit4] 2> 893279 T2768 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty1/index/
[junit4] 2> 893280 T2768 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty1/index' doesn't exist. Creating new index...
[junit4] 2> 893281 T2768 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty1/index
[junit4] 2> 893284 T2768 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1dce1dce lockFactory=org.apache.lucene.store.NativeFSLockFactory@54b954b9),segFN=segments_1,generation=1}
[junit4] 2> 893291 T2768 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 893301 T2768 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 893302 T2768 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 893303 T2768 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 893304 T2768 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 893306 T2768 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 893306 T2768 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 893307 T2768 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 893308 T2768 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 893309 T2768 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 893311 T2768 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 893314 T2768 oass.SolrIndexSearcher.<init> Opening Searcher@2f2f2f2f main
[junit4] 2> 893316 T2768 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 893316 T2768 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 893353 T2769 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2f2f2f2f main{StandardDirectoryReader(segments_1:1)}
[junit4] 2> 893356 T2768 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 893357 T2768 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49722 collection:collection1 shard:shard1
[junit4] 2> 893358 T2768 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4] 2> 893372 T2768 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 893413 T2768 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4] 2> 893423 T2768 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 893424 T2768 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> 893424 T2768 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49722/collection1/
[junit4] 2> 893425 T2768 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 893426 T2768 oasc.SyncStrategy.syncToMe http://127.0.0.1:49722/collection1/ has no replicas
[junit4] 2> 893427 T2768 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49722/collection1/ shard1
[junit4] 2> 893427 T2768 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 894716 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 894775 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 894776 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 894782 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 894813 T2768 oasc.ZkController.register We are http://127.0.0.1:49722/collection1/ and leader is http://127.0.0.1:49722/collection1/
[junit4] 2> 894814 T2768 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49722
[junit4] 2> 894815 T2768 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 894815 T2768 oasc.ZkController.publish publishing core=collection1 state=active
[junit4] 2> 894816 T2768 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 894822 T2768 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 894827 T2725 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4] 2> 894828 T2725 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 894830 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 895128 T2725 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 895130 T2725 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50954
[junit4] 2> 895131 T2725 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 895132 T2725 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 895133 T2725 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-1374072983442
[junit4] 2> 895134 T2725 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-1374072983442/'
[junit4] 2> 895149 T2725 oasc.ConfigSolr.fromFile Loading container configuration from /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1374072983442/solr.xml
[junit4] 2> 895194 T2725 oasc.CoreContainer.<init> New CoreContainer 408688732
[junit4] 2> 895195 T2725 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1374072983442/]
[junit4] 2> 895198 T2725 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 895199 T2725 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 895200 T2725 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 895201 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 895202 T2725 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 895203 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 895204 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 895205 T2725 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 895206 T2725 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 895207 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 895215 T2725 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 895217 T2725 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:59952/solr
[junit4] 2> 895218 T2725 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 895220 T2725 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 895224 T2781 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11761176 name:ZooKeeperConnection Watcher:127.0.0.1:59952 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 895225 T2725 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 895262 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 895270 T2725 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 895274 T2783 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@111f111f name:ZooKeeperConnection Watcher:127.0.0.1:59952/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 895275 T2725 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 895293 T2725 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 896308 T2725 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50954_
[junit4] 2> 896312 T2725 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50954_
[junit4] 2> 896321 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 896322 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 896327 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 896333 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:49722",
[junit4] 2> "state":"active",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "node_name":"127.0.0.1:49722_",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "core":"collection1"}
[junit4] 2> 896338 T2754 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 896341 T2767 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 896346 T2783 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 896350 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 896351 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 896377 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 896392 T2747 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 896393 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4] 2> 896399 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 896407 T2784 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 896408 T2784 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 896410 T2784 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 897897 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 897902 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:50954",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node2",
[junit4] 2> "node_name":"127.0.0.1:50954_",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":null,
[junit4] 2> "core":"collection1"}
[junit4] 2> 897903 T2748 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4] 2> 897903 T2748 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 897925 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 897925 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 897927 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 897933 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 898411 T2784 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 898412 T2784 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-1374072983442/collection1
[junit4] 2> 898413 T2784 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 898415 T2784 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 898416 T2784 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 898421 T2784 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-1374072983442/collection1/'
[junit4] 2> 898423 T2784 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-1374072983442/collection1/lib/README' to classloader
[junit4] 2> 898424 T2784 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-1374072983442/collection1/lib/classes/' to classloader
[junit4] 2> 898475 T2784 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 898562 T2784 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 898567 T2784 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 898578 T2784 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 899156 T2784 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 899157 T2784 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 899158 T2784 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 899166 T2784 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 899170 T2784 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 899216 T2784 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 899223 T2784 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 899230 T2784 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 899234 T2784 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 899235 T2784 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 899235 T2784 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 899239 T2784 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 899240 T2784 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 899241 T2784 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 899241 T2784 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-1374072983442/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty2/
[junit4] 2> 899265 T2784 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@73167316
[junit4] 2> 899266 T2784 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty2
[junit4] 2> 899267 T2784 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty2/index/
[junit4] 2> 899267 T2784 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty2/index' doesn't exist. Creating new index...
[junit4] 2> 899268 T2784 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty2/index
[junit4] 2> 899270 T2784 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@22d022d0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@573a573a),segFN=segments_1,generation=1}
[junit4] 2> 899270 T2784 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 899278 T2784 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 899278 T2784 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 899280 T2784 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 899280 T2784 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 899281 T2784 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 899282 T2784 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 899283 T2784 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 899284 T2784 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 899285 T2784 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 899287 T2784 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 899290 T2784 oass.SolrIndexSearcher.<init> Opening Searcher@3ec13ec1 main
[junit4] 2> 899291 T2784 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 899292 T2784 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 899303 T2785 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3ec13ec1 main{StandardDirectoryReader(segments_1:1)}
[junit4] 2> 899305 T2784 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 899306 T2784 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50954 collection:collection1 shard:shard2
[junit4] 2> 899306 T2784 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4] 2> 899323 T2784 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 899353 T2784 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
[junit4] 2> 899365 T2784 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 899366 T2784 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> 899367 T2784 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50954/collection1/
[junit4] 2> 899368 T2784 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 899368 T2784 oasc.SyncStrategy.syncToMe http://127.0.0.1:50954/collection1/ has no replicas
[junit4] 2> 899369 T2784 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50954/collection1/ shard2
[junit4] 2> 899370 T2784 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4] 2> 899478 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 899543 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 899543 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 899544 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 899551 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 899599 T2784 oasc.ZkController.register We are http://127.0.0.1:50954/collection1/ and leader is http://127.0.0.1:50954/collection1/
[junit4] 2> 899600 T2784 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50954
[junit4] 2> 899601 T2784 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 899602 T2784 oasc.ZkController.publish publishing core=collection1 state=active
[junit4] 2> 899603 T2784 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 899608 T2784 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 899611 T2725 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4] 2> 899613 T2725 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 899615 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 899868 T2725 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 899871 T2725 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:60078
[junit4] 2> 899872 T2725 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 899873 T2725 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 899874 T2725 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-1374072988228
[junit4] 2> 899875 T2725 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-1374072988228/'
[junit4] 2> 899892 T2725 oasc.ConfigSolr.fromFile Loading container configuration from /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1374072988228/solr.xml
[junit4] 2> 899946 T2725 oasc.CoreContainer.<init> New CoreContainer 476322916
[junit4] 2> 899953 T2725 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1374072988228/]
[junit4] 2> 899956 T2725 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 899957 T2725 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 899959 T2725 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 899960 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 899961 T2725 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 899963 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 899964 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 899965 T2725 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 899966 T2725 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 899967 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 899974 T2725 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 899977 T2725 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:59952/solr
[junit4] 2> 899978 T2725 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 900025 T2725 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 900034 T2797 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4b314b31 name:ZooKeeperConnection Watcher:127.0.0.1:59952 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 900041 T2725 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 900046 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 900058 T2725 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 900062 T2799 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@530b530b name:ZooKeeperConnection Watcher:127.0.0.1:59952/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 900063 T2725 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 900102 T2725 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 901088 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 901094 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:50954",
[junit4] 2> "state":"active",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node2",
[junit4] 2> "node_name":"127.0.0.1:50954_",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":"shard2",
[junit4] 2> "core":"collection1"}
[junit4] 2> 901116 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 901116 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 901116 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 901117 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 901116 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 901125 T2725 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60078_
[junit4] 2> 901133 T2725 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60078_
[junit4] 2> 901162 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4] 2> 901163 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4] 2> 901163 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4] 2> 901169 T2799 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 901169 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4] 2> 901182 T2754 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 901183 T2783 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 901189 T2767 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 901191 T2747 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 901192 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4] 2> 901209 T2800 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 901210 T2800 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 901213 T2800 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 902687 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 902693 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:60078",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node3",
[junit4] 2> "node_name":"127.0.0.1:60078_",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":null,
[junit4] 2> "core":"collection1"}
[junit4] 2> 902693 T2748 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4] 2> 902694 T2748 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 902717 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 902717 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 902717 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 902720 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 902728 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 903214 T2800 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 903215 T2800 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-1374072988228/collection1
[junit4] 2> 903216 T2800 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 903219 T2800 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 903220 T2800 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 903226 T2800 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-1374072988228/collection1/'
[junit4] 2> 903227 T2800 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-1374072988228/collection1/lib/README' to classloader
[junit4] 2> 903228 T2800 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-1374072988228/collection1/lib/classes/' to classloader
[junit4] 2> 903271 T2800 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 903342 T2800 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 903346 T2800 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 903354 T2800 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 903910 T2800 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 903911 T2800 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 903912 T2800 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 903918 T2800 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 903922 T2800 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 903991 T2800 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 904002 T2800 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 904013 T2800 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 904018 T2800 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 904019 T2800 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 904019 T2800 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 904025 T2800 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 904025 T2800 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 904026 T2800 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 904027 T2800 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-1374072988228/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty3/
[junit4] 2> 904028 T2800 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@73167316
[junit4] 2> 904030 T2800 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty3
[junit4] 2> 904031 T2800 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty3/index/
[junit4] 2> 904031 T2800 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty3/index' doesn't exist. Creating new index...
[junit4] 2> 904032 T2800 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty3/index
[junit4] 2> 904035 T2800 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@6e386e38 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7cee7cee),segFN=segments_1,generation=1}
[junit4] 2> 904036 T2800 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 904049 T2800 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 904050 T2800 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 904051 T2800 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 904052 T2800 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 904054 T2800 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 904054 T2800 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 904056 T2800 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 904057 T2800 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 904058 T2800 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 904060 T2800 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 904064 T2800 oass.SolrIndexSearcher.<init> Opening Searcher@7e507e50 main
[junit4] 2> 904065 T2800 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 904066 T2800 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 904075 T2801 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7e507e50 main{StandardDirectoryReader(segments_1:1)}
[junit4] 2> 904081 T2800 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 904082 T2800 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:60078 collection:collection1 shard:shard1
[junit4] 2> 904083 T2800 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4] 2> 904157 T2800 oasc.ZkController.register We are http://127.0.0.1:60078/collection1/ and leader is http://127.0.0.1:49722/collection1/
[junit4] 2> 904157 T2800 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60078
[junit4] 2> 904158 T2800 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4] 2> 904159 T2800 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4] 2> 904163 T2800 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 904167 T2725 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4] 2> 904168 T2725 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> ASYNC NEW_CORE C7546 name=collection1 org.apache.solr.core.SolrCore@6f426f42 url=http://127.0.0.1:60078/collection1 node=127.0.0.1:60078_ C7546_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:60078, state=down, node_name=127.0.0.1:60078_, core=collection1}
[junit4] 2> 904167 T2802 C7546 P60078 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4] 2> 904170 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 904170 T2802 C7546 P60078 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4] 2> 904172 T2802 C7546 P60078 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4] 2> 904173 T2802 C7546 P60078 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 904178 T2802 C7546 P60078 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 904199 T2763 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4] 2> 904330 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 904337 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:60078",
[junit4] 2> "state":"recovering",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node3",
[junit4] 2> "node_name":"127.0.0.1:60078_",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "core":"collection1"}
[junit4] 2> 904355 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 904355 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 904357 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 904356 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 904362 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 904474 T2725 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 904477 T2725 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40034
[junit4] 2> 904478 T2725 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 904479 T2725 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 904481 T2725 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-1374072992785
[junit4] 2> 904482 T2725 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-1374072992785/'
[junit4] 2> 904498 T2725 oasc.ConfigSolr.fromFile Loading container configuration from /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1374072992785/solr.xml
[junit4] 2> 904548 T2725 oasc.CoreContainer.<init> New CoreContainer 1041514004
[junit4] 2> 904550 T2725 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1374072992785/]
[junit4] 2> 904552 T2725 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 904553 T2725 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 904554 T2725 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 904555 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 904556 T2725 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 904557 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 904558 T2725 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 904559 T2725 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 904560 T2725 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 904562 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 904572 T2725 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 904574 T2725 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:59952/solr
[junit4] 2> 904576 T2725 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 904577 T2725 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 904580 T2814 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3ea83ea8 name:ZooKeeperConnection Watcher:127.0.0.1:59952 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 904581 T2725 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 904587 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 904597 T2725 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 904604 T2816 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@700f700f name:ZooKeeperConnection Watcher:127.0.0.1:59952/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 904631 T2725 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 904652 T2725 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 905200 T2763 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4] 2> 905201 T2763 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=core_node3&wt=javabin&nodeName=127.0.0.1:60078_&core=collection1} status=0 QTime=1002
[junit4] 2> 905668 T2725 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40034_
[junit4] 2> 905672 T2725 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40034_
[junit4] 2> 905680 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4] 2> 905680 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4] 2> 905682 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4] 2> 905684 T2816 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 905689 T2799 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 905689 T2747 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 905689 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4] 2> 905690 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4] 2> 905697 T2767 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 905719 T2754 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 905722 T2783 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 905726 T2817 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 905726 T2817 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 905731 T2817 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 905894 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 905898 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:40034",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node4",
[junit4] 2> "node_name":"127.0.0.1:40034_",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":null,
[junit4] 2> "core":"collection1"}
[junit4] 2> 905899 T2748 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4] 2> 905899 T2748 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 906011 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 906011 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 906012 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 906012 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 906013 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 906011 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 906732 T2817 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 906732 T2817 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-1374072992785/collection1
[junit4] 2> 906733 T2817 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 906735 T2817 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 906736 T2817 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 906742 T2817 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-1374072992785/collection1/'
[junit4] 2> 906744 T2817 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-1374072992785/collection1/lib/README' to classloader
[junit4] 2> 906745 T2817 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-1374072992785/collection1/lib/classes/' to classloader
[junit4] 2> 906792 T2817 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 906868 T2817 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 906873 T2817 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 906885 T2817 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> ASYNC NEW_CORE C7547 name=collection1 org.apache.solr.core.SolrCore@6f426f42 url=http://127.0.0.1:60078/collection1 node=127.0.0.1:60078_ C7547_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:60078, state=recovering, node_name=127.0.0.1:60078_, core=collection1}
[junit4] 2> 907203 T2802 C7547 P60078 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49722/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4] 2> 907203 T2802 C7547 P60078 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:60078 START replicas=[http://127.0.0.1:49722/collection1/] nUpdates=100
[junit4] 2> 907204 T2802 C7547 P60078 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4] 2> 907205 T2802 C7547 P60078 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4] 2> 907205 T2802 C7547 P60078 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4] 2> 907206 T2802 C7547 P60078 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4] 2> 907207 T2802 C7547 P60078 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4] 2> 907207 T2802 C7547 P60078 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49722/collection1/. core=collection1
[junit4] 2> 907208 T2802 C7547 P60078 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> ASYNC NEW_CORE C7548 name=collection1 org.apache.solr.core.SolrCore@5f305f30 url=http://127.0.0.1:49722/collection1 node=127.0.0.1:49722_ C7548_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:49722, state=active, node_name=127.0.0.1:49722_, core=collection1, leader=true}
[junit4] 2> 907220 T2762 C7548 P49722 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4] 2> 907226 T2761 C7548 P49722 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 907229 T2761 C7548 P49722 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1dce1dce lockFactory=org.apache.lucene.store.NativeFSLockFactory@54b954b9),segFN=segments_1,generation=1}
[junit4] 2> 907230 T2761 C7548 P49722 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 907232 T2761 C7548 P49722 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4] 2> 907233 T2761 C7548 P49722 oass.SolrIndexSearcher.<init> Opening Searcher@7e407e40 realtime
[junit4] 2> 907235 T2761 C7548 P49722 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 907236 T2761 C7548 P49722 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 10
[junit4] 2> 907238 T2802 C7547 P60078 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 907238 T2802 C7547 P60078 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4] 2> 907241 T2760 C7548 P49722 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 907243 T2760 C7548 P49722 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=2
[junit4] 2> 907244 T2802 C7547 P60078 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4] 2> 907244 T2802 C7547 P60078 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4] 2> 907245 T2802 C7547 P60078 oasc.ZkController.publish publishing core=collection1 state=active
[junit4] 2> 907246 T2802 C7547 P60078 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 907248 T2802 C7547 P60078 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4] 2> 907483 T2817 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 907484 T2817 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 907485 T2817 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 907494 T2817 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 907498 T2817 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 907546 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 907548 T2817 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 907552 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:60078",
[junit4] 2> "state":"active",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node3",
[junit4] 2> "node_name":"127.0.0.1:60078_",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "core":"collection1"}
[junit4] 2> 907558 T2817 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 907567 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 907567 T2817 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 907567 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 907567 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 907567 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 907569 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 907596 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 907602 T2817 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 907603 T2817 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 907604 T2817 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 907609 T2817 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 907610 T2817 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 907611 T2817 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 907611 T2817 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-1374072992785/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty4/
[junit4] 2> 907612 T2817 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@73167316
[junit4] 2> 907613 T2817 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty4
[junit4] 2> 907613 T2817 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty4/index/
[junit4] 2> 907614 T2817 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty4/index' doesn't exist. Creating new index...
[junit4] 2> 907615 T2817 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty4/index
[junit4] 2> 907617 T2817 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@675c675c lockFactory=org.apache.lucene.store.NativeFSLockFactory@39803980),segFN=segments_1,generation=1}
[junit4] 2> 907617 T2817 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 907625 T2817 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 907625 T2817 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 907626 T2817 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 907627 T2817 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 907628 T2817 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 907628 T2817 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 907629 T2817 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 907630 T2817 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 907631 T2817 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 907633 T2817 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 907635 T2817 oass.SolrIndexSearcher.<init> Opening Searcher@46c346c3 main
[junit4] 2> 907636 T2817 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 907637 T2817 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 907643 T2819 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@46c346c3 main{StandardDirectoryReader(segments_1:1)}
[junit4] 2> 907647 T2817 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 907647 T2817 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40034 collection:collection1 shard:shard2
[junit4] 2> 907648 T2817 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4] 2> 907671 T2817 oasc.ZkController.register We are http://127.0.0.1:40034/collection1/ and leader is http://127.0.0.1:50954/collection1/
[junit4] 2> 907671 T2817 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40034
[junit4] 2> 907672 T2817 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4] 2> 907672 T2817 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4] 2> ASYNC NEW_CORE C7549 name=collection1 org.apache.solr.core.SolrCore@70627062 url=http://127.0.0.1:40034/collection1 node=127.0.0.1:40034_ C7549_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:40034, state=down, node_name=127.0.0.1:40034_, core=collection1}
[junit4] 2> 907673 T2820 C7549 P40034 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4] 2> 907674 T2820 C7549 P40034 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4] 2> 907674 T2820 C7549 P40034 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4] 2> 907675 T2820 C7549 P40034 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 907675 T2817 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 907678 T2820 C7549 P40034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 907680 T2725 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4] 2> 907681 T2725 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 907682 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 907685 T2779 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4] 2> 907689 T2725 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 907692 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 907715 T2760 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4] 2> 907719 T2760 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 909105 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 909109 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:40034",
[junit4] 2> "state":"recovering",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node4",
[junit4] 2> "node_name":"127.0.0.1:40034_",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":"shard2",
[junit4] 2> "core":"collection1"}
[junit4] 2> 909121 T2748 oasc.Overseer$ClusterStateUpdater.updateState WARN Could not find collection node for onenodecollection, skipping publish state
[junit4] 2> 909122 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:49722",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "node_name":"127.0.0.1:49722_",
[junit4] 2> "numShards":"1",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":"none",
[junit4] 2> "collection":"onenodecollection",
[junit4] 2> "shard":null,
[junit4] 2> "core":"onenodecollectioncore"}
[junit4] 2> 909123 T2748 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4] 2> 909124 T2748 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 909222 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 909223 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 909223 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 909224 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 909225 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 909225 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 909686 T2779 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4] 2> 909687 T2779 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=core_node4&wt=javabin&nodeName=127.0.0.1:40034_&core=collection1} status=0 QTime=2002
[junit4] 2> 909720 T2760 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for onenodecollectioncore
[junit4] 2> 909721 T2760 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-1374072977270/onenodecollectioncore
[junit4] 2> 909722 T2760 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4] 2> 909726 T2760 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4] 2> 909727 T2760 oasc.ZkController.getConfName Looking for collection configName
[junit4] 2> 909733 T2760 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4] 2> 909735 T2760 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4] 2> 909755 T2760 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4] 2> 909759 T2760 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-1374072977270/onenodecollectioncore/'
[junit4] 2> 909861 T2760 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 909899 T2760 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 909904 T2760 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 909911 T2760 oass.IndexSchema.readSchema [onenodecollectioncore] Schema name=test
[junit4] 2> 910369 T2760 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 910371 T2760 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 910373 T2760 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 910382 T2760 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 910387 T2760 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 910425 T2760 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 910434 T2760 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 910443 T2760 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 910447 T2760 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 910449 T2760 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 910450 T2760 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 910468 T2760 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 910470 T2760 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 910471 T2760 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 910472 T2760 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-1374072977270/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1374072971490/onenodecollection/
[junit4] 2> 910473 T2760 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@73167316
[junit4] 2> 910475 T2760 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1374072971490/onenodecollection
[junit4] 2> 910476 T2760 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-1374072971490/onenodecollection/index/
[junit4] 2> 910477 T2760 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-1374072971490/onenodecollection/index' doesn't exist. Creating new index...
[junit4] 2> 910478 T2760 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1374072971490/onenodecollection/index
[junit4] 2> 910481 T2760 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@4abc4abc lockFactory=org.apache.lucene.store.NativeFSLockFactory@6ed56ed5),segFN=segments_1,generation=1}
[junit4] 2> 910482 T2760 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 910493 T2760 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 910494 T2760 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 910495 T2760 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 910496 T2760 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 910498 T2760 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 910498 T2760 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 910500 T2760 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 910501 T2760 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 910502 T2760 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 910504 T2760 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 910508 T2760 oass.SolrIndexSearcher.<init> Opening Searcher@696a696a main
[junit4] 2> 910510 T2760 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 910512 T2760 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 910521 T2822 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@696a696a main{StandardDirectoryReader(segments_1:1)}
[junit4] 2> 910528 T2760 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4] 2> 910529 T2760 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:49722 collection:onenodecollection shard:shard1
[junit4] 2> 910531 T2760 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4] 2> 910543 T2760 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4] 2> 910564 T2760 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4] 2> 910572 T2760 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 910574 T2760 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> 910575 T2760 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49722/onenodecollectioncore/
[junit4] 2> 910576 T2760 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 910578 T2760 oasc.SyncStrategy.syncToMe http://127.0.0.1:49722/onenodecollectioncore/ has no replicas
[junit4] 2> 910579 T2760 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49722/onenodecollectioncore/ shard1
[junit4] 2> 910580 T2760 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4] 2> 910757 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 910852 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 910853 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 910853 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 910854 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 910852 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 910853 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 910963 T2760 oasc.ZkController.register We are http://127.0.0.1:49722/onenodecollectioncore/ and leader is http://127.0.0.1:49722/onenodecollectioncore/
[junit4] 2> 910965 T2760 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:49722
[junit4] 2> 910966 T2760 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 910967 T2760 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4] 2> 910972 T2760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 910975 T2760 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-1374072971490/onenodecollection&action=CREATE&version=2&numShards=1&name=onenodecollectioncore&wt=javabin&roles=none&collection=onenodecollection} status=0 QTime=3260
[junit4] 2> 910977 T2725 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):330
[junit4] 2> 910979 T2725 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> ASYNC NEW_CORE C7550 name=collection1 org.apache.solr.core.SolrCore@70627062 url=http://127.0.0.1:40034/collection1 node=127.0.0.1:40034_ C7550_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:40034, state=recovering, node_name=127.0.0.1:40034_, core=collection1}
[junit4] 2> 911689 T2820 C7550 P40034 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50954/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4] 2> 911689 T2820 C7550 P40034 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40034 START replicas=[http://127.0.0.1:50954/collection1/] nUpdates=100
[junit4] 2> 911690 T2820 C7550 P40034 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4] 2> 911691 T2820 C7550 P40034 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4] 2> 911691 T2820 C7550 P40034 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4] 2> 911692 T2820 C7550 P40034 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4] 2> ASYNC NEW_CORE C7551 name=collection1 org.apache.solr.core.SolrCore@70627062 url=http://127.0.0.1:40034/collection1 node=127.0.0.1:40034_ C7551_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:40034, state=recovering, node_name=127.0.0.1:40034_, core=collection1}
[junit4] 2> 911740 T2820 C7551 P40034 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4] 2> 911741 T2820 C7551 P40034 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50954/collection1/. core=collection1
[junit4] 2> 911741 T2820 C7551 P40034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> ASYNC NEW_CORE C7552 name=collection1 org.apache.solr.core.SolrCore@4b544b54 url=http://127.0.0.1:50954/collection1 node=127.0.0.1:50954_ C7552_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:50954, state=active, node_name=127.0.0.1:50954_, core=collection1, leader=true}
[junit4] 2> 911746 T2776 C7552 P50954 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4] 2> 911752 T2778 C7552 P50954 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 911755 T2778 C7552 P50954 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@22d022d0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@573a573a),segFN=segments_1,generation=1}
[junit4] 2> 911757 T2778 C7552 P50954 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 911758 T2778 C7552 P50954 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4] 2> 911760 T2778 C7552 P50954 oass.SolrIndexSearcher.<init> Opening Searcher@4c7e4c7e realtime
[junit4] 2> 911761 T2778 C7552 P50954 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 911763 T2778 C7552 P50954 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 11
[junit4] 2> 911764 T2820 C7551 P40034 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 911765 T2820 C7551 P40034 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4] 2> 911766 T2777 C7552 P50954 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 911768 T2777 C7552 P50954 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=2
[junit4] 2> 911769 T2820 C7551 P40034 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4] 2> 911770 T2820 C7551 P40034 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4] 2> 911770 T2820 C7551 P40034 oasc.ZkController.publish publishing core=collection1 state=active
[junit4] 2> 911771 T2820 C7551 P40034 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 911773 T2820 C7551 P40034 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4] 2> 911984 T2725 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 912444 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 912449 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:49722",
[junit4] 2> "state":"active",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "node_name":"127.0.0.1:49722_",
[junit4] 2> "numShards":"1",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":"none",
[junit4] 2> "collection":"onenodecollection",
[junit4] 2> "shard":"shard1",
[junit4] 2> "core":"onenodecollectioncore"}
[junit4] 2> 912467 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:40034",
[junit4] 2> "state":"active",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node4",
[junit4] 2> "node_name":"127.0.0.1:40034_",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":"shard2",
[junit4] 2> "core":"collection1"}
[junit4] 2> 912552 T2754 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 912552 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 912554 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 912554 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 912555 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 912554 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 912987 T2725 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 912990 T2725 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4] 2> 912990 T2725 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 913003 T2725 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 913005 T2825 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2fbb2fbb name:ZooKeeperConnection Watcher:127.0.0.1:59952 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 913006 T2725 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 913248 T2725 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 60973
[junit4] 2> 913249 T2725 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1786931842
[junit4] 2> 914108 T2748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 914113 T2748 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4] 2> "base_url":"http://127.0.0.1:60973",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "node_name":"127.0.0.1:60973_",
[junit4] 2> "roles":null,
[junit4] 2> "collection":"control_collection",
[junit4] 2> "shard":null,
[junit4] 2> "core":"collection1"}
[junit4] 2> 914114 T2748 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 914182 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 914183 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 914183 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 914182 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 914185 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 915252 T2725 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 915253 T2725 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 915255 T2725 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@74637463
[junit4] 2> 915261 T2725 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] 2> 915262 T2725 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 915263 T2725 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 915264 T2725 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 915264 T2725 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 915265 T2725 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 915266 T2725 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/control/data [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/control/data;done=false>>]
[junit4] 2> 915266 T2725 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/control/data
[junit4] 2> 915267 T2725 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/control/data/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/control/data/index;done=false>>]
[junit4] 2> 915268 T2725 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/control/data/index
[junit4] 2> 915269 T2748 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=90051246261796867-127.0.0.1:60973_-n_0000000000) am no longer a leader.
[junit4] 2> 915271 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4] 2> 915271 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4] 2> 915329 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4] 2> 915335 T2799 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 915336 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4] 2> 915340 T2767 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 915348 T2816 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 915348 T2783 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 915349 T2725 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4] 2> 915356 T2767 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 915367 T2767 oasc.Overseer.start Overseer (id=90051246261796870-127.0.0.1:49722_-n_0000000001) starting
[junit4] 2> 915389 T2827 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 915398 T2826 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 915402 T2725 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 49722
[junit4] 2> 915403 T2725 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1617518697
[junit4] 2> 915412 T2826 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 915417 T2826 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:60973",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "node_name":"127.0.0.1:60973_",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"control_collection",
[junit4] 2> "shard":"shard1",
[junit4] 2> "core":"collection1"}
[junit4] 2> 915436 T2826 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4] 2> "base_url":"http://127.0.0.1:49722",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "node_name":"127.0.0.1:49722_",
[junit4] 2> "roles":"none",
[junit4] 2> "collection":"onenodecollection",
[junit4] 2> "shard":null,
[junit4] 2> "core":"onenodecollectioncore"}
[junit4] 2> 915436 T2826 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 915504 T2826 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4] 2> "base_url":"http://127.0.0.1:49722",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "node_name":"127.0.0.1:49722_",
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":null,
[junit4] 2> "core":"collection1"}
[junit4] 2> 915505 T2826 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 915582 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 915583 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 915583 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 915582 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 916633 T2747 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 916634 T2747 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4] 2> 916635 T2747 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 917410 T2725 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 917411 T2725 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 917414 T2725 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4] 2> 917417 T2725 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@5f305f30
[junit4] 2> 917422 T2725 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] 2> 917423 T2725 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 917424 T2725 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 917425 T2725 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 917426 T2725 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 917427 T2725 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 917427 T2725 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty1/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty1/index;done=false>>]
[junit4] 2> 917428 T2725 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty1/index
[junit4] 2> 917429 T2725 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty1 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty1;done=false>>]
[junit4] 2> 917429 T2725 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty1
[junit4] 2> 917430 T2725 oasc.SolrCore.close [onenodecollectioncore] CLOSING SolrCore org.apache.solr.core.SolrCore@36d736d7
[junit4] 2> 917452 T2725 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] 2> 917453 T2725 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 917453 T2725 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 917454 T2725 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 917455 T2725 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4] 2> 917456 T2725 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 917456 T2725 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1374072971490/onenodecollection/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1374072971490/onenodecollection/index;done=false>>]
[junit4] 2> 917457 T2725 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1374072971490/onenodecollection/index
[junit4] 2> 917458 T2725 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1374072971490/onenodecollection [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1374072971490/onenodecollection;done=false>>]
[junit4] 2> 917458 T2725 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1374072971490/onenodecollection
[junit4] 2> 917460 T2826 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=90051246261796870-127.0.0.1:49722_-n_0000000001) am no longer a leader.
[junit4] 2> 917461 T2767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4] 2> 917461 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4] 2> 917472 T2799 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4] 2> 917472 T2783 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 917472 T2816 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 917482 T2799 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4] 2> 917482 T2799 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4] 2> 917483 T2799 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> 917483 T2799 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:60078/collection1/
[junit4] 2> 917484 T2799 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:60078 START replicas=[http://127.0.0.1:49722/collection1/] nUpdates=100
[junit4] 2> 917485 T2783 oasc.Overseer.start Overseer (id=90051246261796872-127.0.0.1:50954_-n_0000000002) starting
[junit4] 2> 917485 T2799 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:60078 DONE. We have no versions. sync failed.
[junit4] 2> 917486 T2799 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next candidate
[junit4] 2> 917486 T2799 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] 2> 917487 T2799 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:60078/collection1/ shard1
[junit4] 2> 917488 T2799 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 917490 T2725 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4] 2> 917503 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4] 2> 917503 T2830 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 917513 T2799 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 917514 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4] 2> 917514 T2783 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 917539 T2829 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 917542 T2725 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 50954
[junit4] 2> 917543 T2725 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=408688732
[junit4] 2> 917549 T2829 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 917553 T2829 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:49722",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "node_name":"127.0.0.1:49722_",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "core":"collection1"}
[junit4] 2> 917583 T2829 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:49722",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "node_name":"127.0.0.1:49722_",
[junit4] 2> "numShards":"1",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":"none",
[junit4] 2> "collection":"onenodecollection",
[junit4] 2> "shard":"shard1",
[junit4] 2> "core":"onenodecollectioncore"}
[junit4] 2> 917615 T2829 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4] 2> "base_url":"http://127.0.0.1:50954",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node2",
[junit4] 2> "node_name":"127.0.0.1:50954_",
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":null,
[junit4] 2> "core":"collection1"}
[junit4] 2> 917616 T2829 oasc.Overseer$ClusterStateUpdater.updateState shard=shard2 is already registered
[junit4] 2> 917626 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 917628 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 917629 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 918547 T2725 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 918548 T2725 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 918551 T2725 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@4b544b54
[junit4] 2> 918556 T2725 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] 2> 918557 T2725 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 918557 T2725 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 918558 T2725 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 918559 T2725 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 918560 T2725 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 918561 T2725 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty2 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty2;done=false>>]
[junit4] 2> 918561 T2725 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty2
[junit4] 2> 918562 T2725 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty2/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty2/index;done=false>>]
[junit4] 2> 918563 T2725 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty2/index
[junit4] 2> 918566 T2783 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4] 2> 918566 T2829 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=90051246261796872-127.0.0.1:50954_-n_0000000002) am no longer a leader.
[junit4] 2> 918570 T2799 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 918571 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 918572 T2816 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
[junit4] 2> 918579 T2725 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4] 2> 918581 T2816 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4] 2> 918582 T2816 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4] 2> 918582 T2816 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> 918582 T2799 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 918583 T2816 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:40034/collection1/
[junit4] 2> 918584 T2816 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40034 START replicas=[http://127.0.0.1:50954/collection1/] nUpdates=100
[junit4] 2> 918585 T2816 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40034 DONE. We have no versions. sync failed.
[junit4] 2> 918586 T2816 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next candidate
[junit4] 2> 918587 T2816 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] 2> 918587 T2816 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:40034/collection1/ shard2
[junit4] 2> 918588 T2816 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4] 2> 918593 T2799 oasc.Overseer.start Overseer (id=90051246261796874-127.0.0.1:60078_-n_0000000003) starting
[junit4] 2> 918651 T2725 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 60078
[junit4] 2> 918652 T2725 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=476322916
[junit4] 2> 918667 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4] 2> 918673 T2833 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 918678 T2816 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 918682 T2832 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 918692 T2832 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 918697 T2832 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:50954",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node2",
[junit4] 2> "node_name":"127.0.0.1:50954_",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":"shard2",
[junit4] 2> "core":"collection1"}
[junit4] 2> 918729 T2832 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4] 2> "base_url":"http://127.0.0.1:60078",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node3",
[junit4] 2> "node_name":"127.0.0.1:60078_",
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":null,
[junit4] 2> "core":"collection1"}
[junit4] 2> 918730 T2832 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 918763 T2767 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 918764 T2767 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 918822 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 918822 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 919661 T2725 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 919662 T2725 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 919665 T2725 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@6f426f42
[junit4] 2> 919673 T2725 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] 2> 919675 T2725 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 919676 T2725 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 919677 T2725 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 919678 T2725 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 919679 T2725 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 919680 T2725 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty3 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty3;done=false>>]
[junit4] 2> 919681 T2725 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty3
[junit4] 2> 919682 T2725 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty3/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty3/index;done=false>>]
[junit4] 2> 919683 T2725 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty3/index
[junit4] 2> 919685 T2832 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=90051246261796874-127.0.0.1:60078_-n_0000000003) am no longer a leader.
[junit4] 2> 919691 T2816 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 919700 T2816 oasc.Overseer.start Overseer (id=90051246261796876-127.0.0.1:40034_-n_0000000004) starting
[junit4] 2> 919709 T2725 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4] 2> 919717 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 919717 T2835 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 919725 T2816 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 919727 T2834 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 919769 T2834 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 919769 T2725 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 40034
[junit4] 2> 919770 T2725 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1041514004
[junit4] 2> 919773 T2834 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "shard_state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:60078",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node3",
[junit4] 2> "node_name":"127.0.0.1:60078_",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard_range":null,
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "core":"collection1"}
[junit4] 2> 919786 T2834 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4] 2> "base_url":"http://127.0.0.1:40034",
[junit4] 2> "state":"down",
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node4",
[junit4] 2> "node_name":"127.0.0.1:40034_",
[junit4] 2> "roles":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard":null,
[junit4] 2> "core":"collection1"}
[junit4] 2> 919786 T2834 oasc.Overseer$ClusterStateUpdater.updateState shard=shard2 is already registered
[junit4] 2> 919797 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 919871 T2783 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 919872 T2783 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 920773 T2725 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 920773 T2725 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 920776 T2725 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@70627062
[junit4] 2> 920786 T2725 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] 2> 920787 T2725 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 920787 T2725 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 920788 T2725 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 920789 T2725 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 920789 T2725 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 920790 T2725 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty4/index;done=false>>]
[junit4] 2> 920791 T2725 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty4/index
[junit4] 2> 920791 T2725 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty4;done=false>>]
[junit4] 2> 920792 T2725 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1374072971489/jetty4
[junit4] 2> 920793 T2834 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=90051246261796876-127.0.0.1:40034_-n_0000000004) am no longer a leader.
[junit4] 2> 920795 T2816 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 920817 T2725 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4] 2> 920876 T2725 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4] 2> 920877 T2725 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:59952 59952
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 1> / (2)
[junit4] 1> DATA:
[junit4] 1>
[junit4] 1> /solr (7)
[junit4] 1> /solr/configs (1)
[junit4] 1> /solr/configs/conf1 (9)
[junit4] 1> /solr/configs/conf1/old_synonyms.txt (0)
[junit4] 1> DATA: ...supressed...
[junit4] 1> /solr/configs/conf1/protwords.txt (0)
[junit4] 1> DATA: ...supressed...
[junit4] 1> /solr/configs/conf1/stopwords.txt (0)
[junit4] 1> DATA: ...supressed...
[junit4] 1> /solr/configs/conf1/synonyms.txt (0)
[junit4] 1> DATA: ...supressed...
[junit4] 1> /solr/configs/conf1/schema.xml (0)
[junit4] 1> DATA: ...supressed...
[junit4] 1> /solr/configs/conf1/currency.xml (0)
[junit4] 1> DATA: ...supressed...
[junit4] 1> /solr/configs/conf1/open-exchange-rates.json (0)
[junit4] 1> DATA:
[junit4] 1> {
[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] 1> "license": "http://www.apache.org/licenses/LICENSE-2.0",
[junit4] 1> "timestamp": 1332070464,
[junit4] 1>
[junit4] 1>
[junit4] 1> "IMPORTANT NOTE": "In order for tests to work, this data must be kept in sync with ./currency.xml",
[junit4] 1>
[junit4] 1>
[junit4] 1> "base": "USD",
[junit4] 1> "rates": {
[junit4] 1> "USD": 1,
[junit4] 1> "JPY": 81.29,
[junit4] 1> "EUR": 2.5,
[junit4] 1> "GBP": 0.5,
[junit4] 1> "MXN": 2.0
[junit4] 1> }
[junit4] 1> }
[junit4] 1>
[junit4] 1> /solr/configs/conf1/solrconfig.xml (0)
[junit4] 1> DATA: ...supressed...
[junit4] 1> /solr/configs/conf1/mapping-ISOLatin1Accent.txt (0)
[junit4] 1> DATA: ...supressed...
[junit4] 1> /solr/overseer (3)
[junit4] 1> DATA:
[junit4] 1>
[junit4] 1> /solr/overseer/queue (0)
[junit4] 1> /solr/overseer/collection-queue-work (0)
[junit4] 1> /solr/overseer/queue-work (0)
[junit4] 1> /solr/overseer_elect (2)
[junit4] 1> /solr/overseer_elect/leader (0)
[junit4] 1> DATA:
[junit4] 1> {"id":"90051246261796867-127.0.0.1:60973_-n_0000000000"}
[junit4] 1> /solr/overseer_elect/election (5)
[junit4] 1> /solr/overseer_elect/election/90051246261796872-127.0.0.1:50954_-n_0000000002 (0)
[junit4] 1> /solr/overseer_elect/election/90051246261796870-127.0.0.1:49722_-n_0000000001 (0)
[junit4] 1> /solr/overseer_elect/election/90051246261796867-127.0.0.1:60973_-n_0000000000 (0)
[junit4] 1> /solr/overseer_elect/election/90051246261796874-127.0.0.1:60078_-n_0000000003 (0)
[junit4] 1> /solr/overseer_elect/election/90051246261796876-127.0.0.1:40034_-n_0000000004 (0)
[junit4] 1> /solr/collections (3)
[junit4] 1> /solr/collections/control_collection (3)
[junit4] 1> DATA:
[junit4] 1> {"configName":"conf1"}
[junit4] 1> /solr/collections/control_collection/leader_elect (1)
[junit4] 1> /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election/90051246261796867-core_node1-n_0000000000 (0)
[junit4] 1> /solr/collections/control_collection/leaders (1)
[junit4] 1> /solr/collections/control_collection/leaders/shard1 (0)
[junit4] 1> DATA:
[junit4] 1> {
[junit4] 1> "base_url":"http://127.0.0.1:60973",
[junit4] 1> "node_name":"127.0.0.1:60973_",
[junit4] 1> "core":"collection1"}
[junit4] 1> /solr/collections/control_collection/shards (0)
[junit4] 1> /solr/collections/collection1 (3)
[junit4] 1> DATA:
[junit4] 1> {"configName":"conf1"}
[junit4] 1> /solr/collections/collection1/leader_elect (2)
[junit4] 1> /solr/collections/collection1/leader_elect/shard1 (1)
[junit4] 1> /solr/collections/collection1/leader_elect/shard1/election (2)
[junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/90051246261796874-core_node3-n_0000000001 (0)
[junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/90051246261796870-core_node1-n_0000000000 (0)
[junit4] 1> /solr/collections/collection1/leader_elect/shard2 (1)
[junit4] 1> /solr/collections/collection1/leader_elect/shard2/election (2)
[junit4] 1> /solr/collections/collection1/leader_elect/shard2/election/90051246261796876-core_node4-n_0000000001 (0)
[junit4] 1> /solr/collections/collection1/leader_elect/shard2/election/90051246261796872-core_node2-n_0000000000 (0)
[junit4] 1> /solr/collections/collection1/leaders (2)
[junit4] 1> /solr/collections/collection1/leaders/shard1 (0)
[junit4] 1> DATA:
[junit4] 1> {
[junit4] 1> "base_url":"http://127.0.0.1:49722",
[junit4] 1> "node_name":"127.0.0.1:49722_",
[junit4] 1> "core":"collection1"}
[junit4] 1> /solr/collections/collection1/leaders/shard2 (0)
[junit4] 1> DATA:
[junit4] 1> {
[junit4] 1> "base_url":"http://127.0.0.1:50954",
[junit4] 1> "node_name":"127.0.0.1:50954_",
[junit4] 1> "core":"collection1"}
[junit4] 1> /solr/collections/collection1/shards (0)
[junit4] 1> /solr/collections/onenodecollection (2)
[junit4] 1> DATA:
[junit4] 1> {
[junit4] 1> "router":"compositeId",
[junit4] 1> "configName":"conf1"}
[junit4] 1> /solr/collections/onenodecollection/leader_elect (1)
[junit4] 1> /solr/collections/onenodecollection/leader_elect/shard1 (1)
[junit4] 1> /solr/collections/onenodecollection/leader_elect/shard1/election (1)
[junit4] 1> /solr/collections/onenodecollection/leader_elect/shard1/election/90051246261796870-core_node1-n_0000000000 (0)
[junit4] 1> /solr/collections/onenodecollection/leaders (1)
[junit4] 1> /solr/collections/onenodecollection/leaders/shard1 (0)
[junit4] 1> DATA:
[junit4] 1> {
[junit4] 1> "base_url":"http://127.0.0.1:49722",
[junit4] 1> "node_name":"127.0.0.1:49722_",
[junit4] 1> "core":"onenodecollectioncore"}
[junit4] 1> /solr/aliases.json (0)
[junit4] 1> /solr/live_nodes (5)
[junit4] 1> /solr/live_nodes/127.0.0.1:60973_ (0)
[junit4] 1> /solr/live_nodes/127.0.0.1:49722_ (0)
[junit4] 1> /solr/live_nodes/127.0.0.1:60078_ (0)
[junit4] 1> /solr/live_nodes/127.0.0.1:40034_ (0)
[junit4] 1> /solr/live_nodes/127.0.0.1:50954_ (0)
[junit4] 1> /solr/clusterstate.json (0)
[junit4] 1> DATA:
[junit4] 1> {
[junit4] 1> "control_collection":{
[junit4] 1> "shards":{"shard1":{
[junit4] 1> "range":"80000000-7fffffff",
[junit4] 1> "state":"active",
[junit4] 1> "replicas":{"core_node1":{
[junit4] 1> "base_url":"http://127.0.0.1:60973",
[junit4] 1> "state":"active",
[junit4] 1> "node_name":"127.0.0.1:60973_",
[junit4] 1> "core":"collection1",
[junit4] 1> "leader":"true"}}}},
[junit4] 1> "router":"compositeId"},
[junit4] 1> "onenodecollection":{
[junit4] 1> "shards":{"shard1":{
[junit4] 1> "range":"80000000-7fffffff",
[junit4] 1> "state":"active",
[junit4] 1> "replicas":{"core_node1":{
[junit4] 1> "base_url":"http://127.0.0.1:49722",
[junit4] 1> "state":"active",
[junit4] 1> "node_name":"127.0.0.1:49722_",
[junit4] 1> "roles":"none",
[junit4] 1> "core":"onenodecollectioncore",
[junit4] 1> "leader":"true"}}}},
[junit4] 1> "router":"compositeId"},
[junit4] 1> "collection1":{
[junit4] 1> "shards":{
[junit4] 1> "shard1":{
[junit4] 1> "range":"80000000-ffffffff",
[junit4] 1> "state":"active",
[junit4] 1> "replicas":{
[junit4] 1> "core_node1":{
[junit4] 1> "base_url":"http://127.0.0.1:49722",
[junit4] 1> "state":"active",
[junit4] 1> "node_name":"127.0.0.1:49722_",
[junit4] 1> "core":"collection1",
[junit4] 1> "leader":"true"},
[junit4] 1> "core_node3":{
[junit4] 1> "base_url":"http://127.0.0.1:60078",
[junit4] 1> "state":"active",
[junit4] 1> "node_name":"127.0.0.1:60078_",
[junit4] 1> "core":"collection1"}}},
[junit4] 1> "shard2":{
[junit4] 1> "range":"0-7fffffff",
[junit4] 1> "state":"active",
[junit4] 1> "replicas":{
[junit4] 1> "core_node2":{
[junit4] 1> "base_url":"http://127.0.0.1:50954",
[junit4] 1> "state":"active",
[junit4] 1> "node_name":"127.0.0.1:50954_",
[junit4] 1> "core":"collection1",
[junit4] 1> "leader":"true"},
[junit4] 1> "core_node4":{
[junit4] 1> "base_url":"http://127.0.0.1:40034",
[junit4] 1> "state":"active",
[junit4] 1> "node_name":"127.0.0.1:40034_",
[junit4] 1> "core":"collection1"}}}},
[junit4] 1> "router":"compositeId"}}
[junit4] 1> /zookeeper (1)
[junit4] 1> DATA:
[junit4] 1>
[junit4] 1>
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=BasicDistributedZk2Test -Dtests.method=testDistribSearch -Dtests.seed=7B374360BB4D6C3B -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=en_BE_PREEURO -Dtests.timezone=Pacific/Norfolk -Dtests.file.encoding=UTF-8
[junit4] ERROR 38.0s J1 | BasicDistributedZk2Test.testDistribSearch <<<
[junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:50954/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
[junit4] > at __randomizedtesting.SeedInfo.seed([7B374360BB4D6C3B:FAD1CD78CC120C07]:0)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4] > at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
[junit4] > at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
[junit4] > at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
[junit4] > at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:196)
[junit4] > at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:88)
[junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4] > at java.lang.Thread.run(Thread.java:738)
[junit4] 2> 920897 T2725 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> 38052 T2724 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4] 2> 920988 T2799 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 920989 T2799 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 920989 T2799 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 922096 T2816 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 922097 T2816 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> NOTE: test params are: codec=Lucene41, sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=en_BE_PREEURO, timezone=Pacific/Norfolk
[junit4] 2> NOTE: Linux 3.2.0-49-generic x86/IBM Corporation 1.6.0 (32-bit)/cpus=8,threads=3,free=24377064,total=48819200
[junit4] 2> NOTE: All tests run in this JVM: [BadIndexSchemaTest, DocumentAnalysisRequestHandlerTest, TestPropInject, FileUtilsTest, DirectSolrSpellCheckerTest, TestDefaultSimilarityFactory, TestCloudManagedSchema, TestDistributedSearch, TestSerializedLuceneMatchVersion, TestRecovery, PathHierarchyTokenizerFactoryTest, TestDistributedGrouping, CachingDirectoryFactoryTest, TestCollationField, TestRecoveryHdfs, HighlighterTest, CoreContainerCoreInitFailuresTest, UniqFieldsUpdateProcessorFactoryTest, UpdateParamsTest, TestInfoStreamLogging, TestQuerySenderNoQuery, TestLazyCores, TestNumberUtils, TestCloudManagedSchemaAddField, TestStressLucene, ShardRoutingCustomTest, TimeZoneUtilsTest, ZkNodePropsTest, TestRandomFaceting, SpellCheckCollatorTest, DateMathParserTest, DefaultValueUpdateProcessorTest, LeaderElectionIntegrationTest, TestCSVResponseWriter, DocValuesMultiTest, JSONWriterTest, HighlighterConfigTest, TestPostingsSolrHighlighter, HardAutoCommitTest, CollectionsAPIDistributedZkTest, TestElisionMultitermQuery, TestFoldingMultitermQuery, TestWordDelimiterFilterFactory, CurrencyFieldOpenExchangeTest, ClusterStateTest, SolrRequestParserTest, RequestHandlersTest, TestZkChroot, HdfsRecoveryZkTest, TestUpdate, TestAtomicUpdateErrorCases, XmlUpdateRequestHandlerTest, ConvertedLegacyTest, SolrTestCaseJ4Test, DirectUpdateHandlerTest, OpenExchangeRatesOrgProviderTest, TestBinaryResponseWriter, TestStressReorder, SampleTest, StatsComponentTest, TestSolr4Spatial, ChaosMonkeySafeLeaderTest, MultiTermTest, TestSolrQueryParserResource, SolrCoreCheckLockOnStartupTest, SpellPossibilityIteratorTest, TestLuceneMatchVersion, DisMaxRequestHandlerTest, TestRTGBase, OpenCloseCoreStressTest, DebugComponentTest, TestCopyFieldCollectionResource, IndexReaderFactoryTest, BasicDistributedZk2Test]
[junit4] Completed on J1 in 39.35s, 1 test, 1 error <<< FAILURES!
[...truncated 524 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:395: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:388: 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:449: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1250: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:893: There were test failures: 319 suites, 1345 tests, 1 error, 35 ignored (7 assumptions)
Total time: 52 minutes 21 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/ibm-j9-jdk6 -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