You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/15 10:29:39 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/ibm-j9-jdk7) - Build #
6145 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/6145/
Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
1 tests failed.
FAILED: org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearch
Error Message:
Server at http://127.0.0.1:47780/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:47780/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
at __randomizedtesting.SeedInfo.seed([98262B85C9F9B93A:19C0A59DBEA6D906]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:198)
at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:90)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:613)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:780)
Build Log:
[...truncated 9618 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4] 2> 550679 T1531 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 550683 T1531 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1371284203256
[junit4:junit4] 2> 550684 T1531 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 550685 T1532 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 550785 T1531 oasc.ZkTestServer.run start zk server on port:49255
[junit4:junit4] 2> 550790 T1531 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 550793 T1538 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@699cace2 name:ZooKeeperConnection Watcher:127.0.0.1:49255 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 550794 T1531 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 550795 T1531 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 550805 T1531 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 550807 T1540 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4bbd060f name:ZooKeeperConnection Watcher:127.0.0.1:49255/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 550808 T1531 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 550809 T1531 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 550814 T1531 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 550818 T1531 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 550822 T1531 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 550826 T1531 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 550827 T1531 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 550834 T1531 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 550835 T1531 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 550840 T1531 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 550841 T1531 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 550846 T1531 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 550847 T1531 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 550851 T1531 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 550852 T1531 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 550857 T1531 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 550858 T1531 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 550862 T1531 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 550863 T1531 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 550868 T1531 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 550869 T1531 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 550874 T1531 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 550875 T1531 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 550958 T1531 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 550964 T1531 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:60671
[junit4:junit4] 2> 550965 T1531 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 550965 T1531 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 550966 T1531 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1371284203452
[junit4:junit4] 2> 550967 T1531 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1371284203452/solr.xml
[junit4:junit4] 2> 550967 T1531 oasc.CoreContainer.<init> New CoreContainer -39563714
[junit4:junit4] 2> 550968 T1531 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1371284203452/'
[junit4:junit4] 2> 550968 T1531 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1371284203452/'
[junit4:junit4] 2> 551007 T1531 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 551008 T1531 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 551009 T1531 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 551009 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 551010 T1531 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 551011 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 551011 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 551012 T1531 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 551012 T1531 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 551013 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 551018 T1531 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 551019 T1531 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49255/solr
[junit4:junit4] 2> 551019 T1531 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 551022 T1531 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 551023 T1551 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e79c8180 name:ZooKeeperConnection Watcher:127.0.0.1:49255 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 551023 T1531 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 551024 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 551031 T1531 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 551032 T1553 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2ca5485d name:ZooKeeperConnection Watcher:127.0.0.1:49255/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 551032 T1531 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 551033 T1531 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 551036 T1531 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 551038 T1531 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 551040 T1531 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60671_
[junit4:junit4] 2> 551041 T1531 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60671_
[junit4:junit4] 2> 551043 T1531 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 551047 T1531 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 551050 T1531 oasc.Overseer.start Overseer (id=89868481544912899-127.0.0.1:60671_-n_0000000000) starting
[junit4:junit4] 2> 551054 T1531 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 551058 T1555 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 551059 T1531 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 551061 T1531 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 551063 T1531 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 551066 T1554 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 551069 T1556 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 551070 T1556 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 552571 T1554 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 552573 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60671",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:60671_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 552573 T1554 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 552574 T1554 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 552580 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 553072 T1556 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1371284203452/collection1
[junit4:junit4] 2> 553073 T1556 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 553074 T1556 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 553075 T1556 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 553077 T1556 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1371284203452/collection1/'
[junit4:junit4] 2> 553079 T1556 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1371284203452/collection1/lib/README' to classloader
[junit4:junit4] 2> 553080 T1556 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1371284203452/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 553118 T1556 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 553148 T1556 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 553149 T1556 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 553154 T1556 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 553473 T1556 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 553480 T1556 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 553482 T1556 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 553499 T1556 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 553504 T1556 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 553510 T1556 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 553512 T1556 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 553512 T1556 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 553513 T1556 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 553514 T1556 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 553515 T1556 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 553516 T1556 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 553516 T1556 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1371284203452/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/control/data/
[junit4:junit4] 2> 553517 T1556 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a3a2293
[junit4:junit4] 2> 553517 T1556 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 553518 T1556 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/control/data
[junit4:junit4] 2> 553519 T1556 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/control/data/index/
[junit4:junit4] 2> 553519 T1556 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 553520 T1556 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/control/data/index
[junit4:junit4] 2> 553522 T1556 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d74d0a6a lockFactory=org.apache.lucene.store.NativeFSLockFactory@ff8e730f),segFN=segments_1,generation=1}
[junit4:junit4] 2> 553523 T1556 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 553525 T1556 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 553525 T1556 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 553526 T1556 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 553527 T1556 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 553528 T1556 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 553528 T1556 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 553529 T1556 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 553529 T1556 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 553530 T1556 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 553532 T1556 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 553535 T1556 oass.SolrIndexSearcher.<init> Opening Searcher@9a288123 main
[junit4:junit4] 2> 553535 T1556 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/control/data/tlog
[junit4:junit4] 2> 553536 T1556 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 553537 T1556 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 553542 T1557 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9a288123 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 553543 T1556 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 553544 T1556 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:60671 collection:control_collection shard:shard1
[junit4:junit4] 2> 553545 T1556 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 553555 T1556 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 553558 T1556 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 553559 T1556 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 553560 T1556 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:60671/collection1/
[junit4:junit4] 2> 553560 T1556 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 553561 T1556 oasc.SyncStrategy.syncToMe http://127.0.0.1:60671/collection1/ has no replicas
[junit4:junit4] 2> 553562 T1556 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:60671/collection1/
[junit4:junit4] 2> 553563 T1556 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 554086 T1554 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 554097 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 554122 T1556 oasc.ZkController.register We are http://127.0.0.1:60671/collection1/ and leader is http://127.0.0.1:60671/collection1/
[junit4:junit4] 2> 554123 T1556 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60671
[junit4:junit4] 2> 554124 T1556 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 554124 T1556 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 554125 T1556 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 554128 T1556 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 554129 T1531 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 554130 T1531 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 554131 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 554138 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 554143 T1531 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 554144 T1560 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@aba4a40d name:ZooKeeperConnection Watcher:127.0.0.1:49255/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 554144 T1531 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 554146 T1531 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 554149 T1531 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 554222 T1531 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 554227 T1531 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:35705
[junit4:junit4] 2> 554228 T1531 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 554229 T1531 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 554229 T1531 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1371284206722
[junit4:junit4] 2> 554230 T1531 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1371284206722/solr.xml
[junit4:junit4] 2> 554231 T1531 oasc.CoreContainer.<init> New CoreContainer 1606219571
[junit4:junit4] 2> 554231 T1531 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1371284206722/'
[junit4:junit4] 2> 554232 T1531 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1371284206722/'
[junit4:junit4] 2> 554270 T1531 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 554271 T1531 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 554271 T1531 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 554272 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 554273 T1531 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 554273 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 554274 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 554274 T1531 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 554275 T1531 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 554275 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 554280 T1531 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 554281 T1531 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49255/solr
[junit4:junit4] 2> 554282 T1531 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 554284 T1531 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 554285 T1571 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7a83deeb name:ZooKeeperConnection Watcher:127.0.0.1:49255 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 554286 T1531 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 554287 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 554293 T1531 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 554294 T1573 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f0230b35 name:ZooKeeperConnection Watcher:127.0.0.1:49255/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 554295 T1531 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 554299 T1531 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 555302 T1531 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35705_
[junit4:junit4] 2> 555305 T1531 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:35705_
[junit4:junit4] 2> 555309 T1560 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 555309 T1573 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 555309 T1553 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 555311 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 555318 T1574 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 555319 T1574 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 555604 T1554 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 555605 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60671",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:60671_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 555610 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35705",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:35705_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 555610 T1554 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 555611 T1554 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 555620 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 555620 T1560 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 555620 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 556321 T1574 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1371284206722/collection1
[junit4:junit4] 2> 556322 T1574 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 556324 T1574 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 556324 T1574 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 556326 T1574 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1371284206722/collection1/'
[junit4:junit4] 2> 556327 T1574 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1371284206722/collection1/lib/README' to classloader
[junit4:junit4] 2> 556328 T1574 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1371284206722/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 556362 T1574 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 556391 T1574 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 556392 T1574 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 556397 T1574 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 556711 T1574 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 556716 T1574 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 556719 T1574 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 556729 T1574 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 556733 T1574 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 556738 T1574 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 556739 T1574 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 556740 T1574 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 556740 T1574 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 556741 T1574 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 556742 T1574 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 556742 T1574 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 556743 T1574 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1371284206722/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty1/
[junit4:junit4] 2> 556743 T1574 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a3a2293
[junit4:junit4] 2> 556744 T1574 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 556745 T1574 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty1
[junit4:junit4] 2> 556745 T1574 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty1/index/
[junit4:junit4] 2> 556746 T1574 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 556746 T1574 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty1/index
[junit4:junit4] 2> 556748 T1574 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@29110e3a lockFactory=org.apache.lucene.store.NativeFSLockFactory@d28d7767),segFN=segments_1,generation=1}
[junit4:junit4] 2> 556748 T1574 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 556750 T1574 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 556751 T1574 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 556751 T1574 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 556752 T1574 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 556752 T1574 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 556753 T1574 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 556753 T1574 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 556754 T1574 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 556754 T1574 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 556756 T1574 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 556758 T1574 oass.SolrIndexSearcher.<init> Opening Searcher@23306c0 main
[junit4:junit4] 2> 556758 T1574 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty1/tlog
[junit4:junit4] 2> 556759 T1574 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 556760 T1574 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 556764 T1575 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@23306c0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 556765 T1574 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 556765 T1574 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:35705 collection:collection1 shard:shard1
[junit4:junit4] 2> 556766 T1574 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 556771 T1574 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 556773 T1574 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 556773 T1574 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 556774 T1574 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:35705/collection1/
[junit4:junit4] 2> 556774 T1574 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 556774 T1574 oasc.SyncStrategy.syncToMe http://127.0.0.1:35705/collection1/ has no replicas
[junit4:junit4] 2> 556775 T1574 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:35705/collection1/
[junit4:junit4] 2> 556775 T1574 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 557127 T1554 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 557137 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 557137 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 557137 T1560 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 557181 T1574 oasc.ZkController.register We are http://127.0.0.1:35705/collection1/ and leader is http://127.0.0.1:35705/collection1/
[junit4:junit4] 2> 557181 T1574 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35705
[junit4:junit4] 2> 557182 T1574 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 557182 T1574 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 557183 T1574 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 557186 T1574 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 557188 T1531 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 557189 T1531 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 557190 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 557259 T1531 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 557264 T1531 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:47780
[junit4:junit4] 2> 557265 T1531 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 557265 T1531 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 557266 T1531 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1371284209766
[junit4:junit4] 2> 557266 T1531 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1371284209766/solr.xml
[junit4:junit4] 2> 557267 T1531 oasc.CoreContainer.<init> New CoreContainer -853146660
[junit4:junit4] 2> 557268 T1531 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1371284209766/'
[junit4:junit4] 2> 557268 T1531 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1371284209766/'
[junit4:junit4] 2> 557306 T1531 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 557306 T1531 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 557307 T1531 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 557307 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 557308 T1531 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 557309 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 557309 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 557310 T1531 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 557310 T1531 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 557311 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 557316 T1531 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 557317 T1531 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49255/solr
[junit4:junit4] 2> 557317 T1531 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 557320 T1531 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 557321 T1587 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a1c180f1 name:ZooKeeperConnection Watcher:127.0.0.1:49255 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 557322 T1531 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 557324 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 557330 T1531 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 557331 T1589 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9f399944 name:ZooKeeperConnection Watcher:127.0.0.1:49255/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 557331 T1531 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 557335 T1531 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 558339 T1531 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47780_
[junit4:junit4] 2> 558341 T1531 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47780_
[junit4:junit4] 2> 558345 T1560 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 558346 T1573 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 558346 T1553 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 558346 T1589 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 558347 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 558347 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 558349 T1560 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 558354 T1590 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 558355 T1590 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 558644 T1554 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 558646 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35705",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:35705_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 558651 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47780",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:47780_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 558652 T1554 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 558652 T1554 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 558657 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 558658 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 558657 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 558657 T1560 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 559357 T1590 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1371284209766/collection1
[junit4:junit4] 2> 559358 T1590 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 559359 T1590 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 559360 T1590 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 559362 T1590 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1371284209766/collection1/'
[junit4:junit4] 2> 559363 T1590 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1371284209766/collection1/lib/README' to classloader
[junit4:junit4] 2> 559364 T1590 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1371284209766/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 559391 T1590 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 559420 T1590 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 559421 T1590 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 559425 T1590 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 559740 T1590 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 559745 T1590 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 559748 T1590 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 559757 T1590 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 559761 T1590 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 559764 T1590 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 559765 T1590 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 559765 T1590 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 559766 T1590 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 559767 T1590 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 559767 T1590 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 559767 T1590 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 559768 T1590 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1371284209766/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty2/
[junit4:junit4] 2> 559768 T1590 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a3a2293
[junit4:junit4] 2> 559769 T1590 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 559769 T1590 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty2
[junit4:junit4] 2> 559770 T1590 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty2/index/
[junit4:junit4] 2> 559770 T1590 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 559770 T1590 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty2/index
[junit4:junit4] 2> 559772 T1590 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@17a54906 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4dbb07ad),segFN=segments_1,generation=1}
[junit4:junit4] 2> 559772 T1590 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 559773 T1590 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 559774 T1590 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 559774 T1590 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 559775 T1590 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 559775 T1590 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 559776 T1590 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 559776 T1590 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 559777 T1590 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 559777 T1590 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 559778 T1590 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 559780 T1590 oass.SolrIndexSearcher.<init> Opening Searcher@b012a0f1 main
[junit4:junit4] 2> 559780 T1590 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty2/tlog
[junit4:junit4] 2> 559781 T1590 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 559781 T1590 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 559785 T1591 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@b012a0f1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 559786 T1590 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 559787 T1590 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47780 collection:collection1 shard:shard2
[junit4:junit4] 2> 559787 T1590 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 559792 T1590 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 559794 T1590 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 559794 T1590 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 559795 T1590 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:47780/collection1/
[junit4:junit4] 2> 559795 T1590 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 559795 T1590 oasc.SyncStrategy.syncToMe http://127.0.0.1:47780/collection1/ has no replicas
[junit4:junit4] 2> 559796 T1590 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:47780/collection1/
[junit4:junit4] 2> 559796 T1590 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 560166 T1554 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 560176 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 560177 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 560177 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 560177 T1560 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 560201 T1590 oasc.ZkController.register We are http://127.0.0.1:47780/collection1/ and leader is http://127.0.0.1:47780/collection1/
[junit4:junit4] 2> 560201 T1590 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47780
[junit4:junit4] 2> 560202 T1590 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 560203 T1590 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 560203 T1590 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 560206 T1590 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 560207 T1531 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 560209 T1531 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 560210 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 560286 T1531 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 560291 T1531 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49779
[junit4:junit4] 2> 560292 T1531 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 560292 T1531 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 560293 T1531 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1371284212791
[junit4:junit4] 2> 560293 T1531 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1371284212791/solr.xml
[junit4:junit4] 2> 560294 T1531 oasc.CoreContainer.<init> New CoreContainer -1585120477
[junit4:junit4] 2> 560294 T1531 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1371284212791/'
[junit4:junit4] 2> 560295 T1531 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1371284212791/'
[junit4:junit4] 2> 560333 T1531 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 560333 T1531 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 560334 T1531 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 560334 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 560335 T1531 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 560336 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 560336 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 560337 T1531 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 560337 T1531 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 560338 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 560343 T1531 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 560344 T1531 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49255/solr
[junit4:junit4] 2> 560344 T1531 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 560347 T1531 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 560348 T1603 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b9c873e3 name:ZooKeeperConnection Watcher:127.0.0.1:49255 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 560349 T1531 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 560350 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 560357 T1531 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 560358 T1605 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ab39bf27 name:ZooKeeperConnection Watcher:127.0.0.1:49255/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 560358 T1531 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 560361 T1531 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 561365 T1531 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49779_
[junit4:junit4] 2> 561368 T1531 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49779_
[junit4:junit4] 2> 561373 T1560 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 561373 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 561373 T1553 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 561375 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 561373 T1573 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 561376 T1560 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 561374 T1605 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 561376 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 561378 T1589 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 561383 T1606 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 561384 T1606 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 561684 T1554 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 561685 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47780",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:47780_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 561688 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49779",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:49779_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 561688 T1554 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 561688 T1554 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 561691 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 561691 T1560 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 561691 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 561691 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 561691 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 562387 T1606 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1371284212791/collection1
[junit4:junit4] 2> 562388 T1606 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 562389 T1606 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 562390 T1606 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 562392 T1606 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1371284212791/collection1/'
[junit4:junit4] 2> 562394 T1606 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1371284212791/collection1/lib/README' to classloader
[junit4:junit4] 2> 562395 T1606 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1371284212791/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 562430 T1606 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 562461 T1606 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 562462 T1606 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 562466 T1606 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 562783 T1606 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 562788 T1606 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 562791 T1606 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 562808 T1606 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 562812 T1606 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 562816 T1606 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 562818 T1606 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 562818 T1606 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 562819 T1606 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 562820 T1606 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 562821 T1606 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 562821 T1606 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 562822 T1606 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1371284212791/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3/
[junit4:junit4] 2> 562822 T1606 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a3a2293
[junit4:junit4] 2> 562823 T1606 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 562825 T1606 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3
[junit4:junit4] 2> 562825 T1606 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3/index/
[junit4:junit4] 2> 562826 T1606 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 562827 T1606 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3/index
[junit4:junit4] 2> 562829 T1606 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d64445b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c829e0a3),segFN=segments_1,generation=1}
[junit4:junit4] 2> 562829 T1606 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 562831 T1606 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 562832 T1606 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 562832 T1606 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 562833 T1606 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 562834 T1606 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 562834 T1606 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 562834 T1606 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 562835 T1606 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 562835 T1606 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 562837 T1606 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 562839 T1606 oass.SolrIndexSearcher.<init> Opening Searcher@9e17829e main
[junit4:junit4] 2> 562839 T1606 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3/tlog
[junit4:junit4] 2> 562840 T1606 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 562841 T1606 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 562847 T1607 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9e17829e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 562850 T1606 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 562850 T1606 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49779 collection:collection1 shard:shard1
[junit4:junit4] 2> 562857 T1606 oasc.ZkController.register We are http://127.0.0.1:49779/collection1/ and leader is http://127.0.0.1:35705/collection1/
[junit4:junit4] 2> 562858 T1606 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49779
[junit4:junit4] 2> 562858 T1606 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 562859 T1606 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C758 name=collection1 org.apache.solr.core.SolrCore@6ca75f7 url=http://127.0.0.1:49779/collection1 node=127.0.0.1:49779_ C758_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:49779, state=down, node_name=127.0.0.1:49779_, collection=collection1, core=collection1}
[junit4:junit4] 2> 562860 T1608 C758 P49779 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 562860 T1606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 562860 T1608 C758 P49779 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 562861 T1608 C758 P49779 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 562861 T1608 C758 P49779 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 562861 T1531 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 562862 T1531 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 562863 T1608 C758 P49779 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 562863 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 562873 T1567 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 562945 T1531 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 562949 T1531 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:48435
[junit4:junit4] 2> 562950 T1531 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 562951 T1531 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 562951 T1531 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1371284215443
[junit4:junit4] 2> 562952 T1531 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1371284215443/solr.xml
[junit4:junit4] 2> 562952 T1531 oasc.CoreContainer.<init> New CoreContainer -498846104
[junit4:junit4] 2> 562953 T1531 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1371284215443/'
[junit4:junit4] 2> 562954 T1531 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1371284215443/'
[junit4:junit4] 2> 562992 T1531 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 562993 T1531 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 562993 T1531 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 562994 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 562994 T1531 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 562995 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 562995 T1531 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 562996 T1531 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 562997 T1531 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 562997 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 563002 T1531 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 563003 T1531 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49255/solr
[junit4:junit4] 2> 563003 T1531 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 563006 T1531 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 563007 T1620 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d497453b name:ZooKeeperConnection Watcher:127.0.0.1:49255 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 563008 T1531 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 563009 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 563018 T1531 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 563019 T1622 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@fde8832c name:ZooKeeperConnection Watcher:127.0.0.1:49255/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 563020 T1531 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 563023 T1531 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 563196 T1554 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 563198 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49779",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:49779_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 563205 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 563205 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 563205 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 563205 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 563205 T1560 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 563205 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 563875 T1567 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 563876 T1567 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=4&wt=javabin&nodeName=127.0.0.1:49779_&core=collection1} status=0 QTime=1003
[junit4:junit4] 2> 564025 T1531 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:48435_
[junit4:junit4] 2> 564028 T1531 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:48435_
[junit4:junit4] 2> 564032 T1560 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 564032 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 564033 T1573 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 564032 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 564033 T1553 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 564034 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 564033 T1622 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 564036 T1560 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 564036 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 564037 T1605 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 564038 T1589 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 564037 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 564043 T1623 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 564044 T1623 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 564713 T1554 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 564715 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48435",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:48435_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 564715 T1554 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 564716 T1554 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 564729 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 564729 T1560 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 564729 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 564729 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 564729 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 564729 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 565046 T1623 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1371284215443/collection1
[junit4:junit4] 2> 565046 T1623 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 565048 T1623 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 565049 T1623 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 565051 T1623 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1371284215443/collection1/'
[junit4:junit4] 2> 565052 T1623 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1371284215443/collection1/lib/README' to classloader
[junit4:junit4] 2> 565053 T1623 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1371284215443/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 565099 T1623 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 565128 T1623 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 565130 T1623 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 565134 T1623 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 565461 T1623 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 565466 T1623 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 565469 T1623 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 565478 T1623 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 565482 T1623 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 565486 T1623 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 565487 T1623 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 565487 T1623 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 565488 T1623 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 565489 T1623 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 565489 T1623 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 565490 T1623 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 565490 T1623 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1371284215443/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4/
[junit4:junit4] 2> 565491 T1623 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a3a2293
[junit4:junit4] 2> 565491 T1623 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 565492 T1623 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4
[junit4:junit4] 2> 565492 T1623 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4/index/
[junit4:junit4] 2> 565493 T1623 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 565494 T1623 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4/index
[junit4:junit4] 2> 565495 T1623 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@64929534 lockFactory=org.apache.lucene.store.NativeFSLockFactory@509dc8a6),segFN=segments_1,generation=1}
[junit4:junit4] 2> 565496 T1623 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 565498 T1623 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 565498 T1623 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 565499 T1623 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 565500 T1623 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 565500 T1623 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 565501 T1623 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 565501 T1623 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 565502 T1623 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 565502 T1623 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 565504 T1623 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 565507 T1623 oass.SolrIndexSearcher.<init> Opening Searcher@e5c9e898 main
[junit4:junit4] 2> 565507 T1623 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4/tlog
[junit4:junit4] 2> 565508 T1623 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 565508 T1623 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 565513 T1624 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e5c9e898 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 565514 T1623 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 565514 T1623 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:48435 collection:collection1 shard:shard2
[junit4:junit4] 2> 565518 T1623 oasc.ZkController.register We are http://127.0.0.1:48435/collection1/ and leader is http://127.0.0.1:47780/collection1/
[junit4:junit4] 2> 565519 T1623 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:48435
[junit4:junit4] 2> 565519 T1623 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 565519 T1623 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C759 name=collection1 org.apache.solr.core.SolrCore@a143eb9e url=http://127.0.0.1:48435/collection1 node=127.0.0.1:48435_ C759_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:48435, state=down, node_name=127.0.0.1:48435_, collection=collection1, core=collection1}
[junit4:junit4] 2> 565520 T1625 C759 P48435 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 565520 T1623 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 565520 T1625 C759 P48435 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 565521 T1625 C759 P48435 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 565522 T1625 C759 P48435 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 565522 T1531 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 565523 T1531 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 565523 T1625 C759 P48435 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 565524 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 565533 T1531 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 565534 T1585 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 565536 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 565550 T1568 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4] 2> ASYNC NEW_CORE C760 name=collection1 org.apache.solr.core.SolrCore@6ca75f7 url=http://127.0.0.1:49779/collection1 node=127.0.0.1:49779_ C760_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:49779, state=recovering, node_name=127.0.0.1:49779_, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4] 2> 565878 T1608 C760 P49779 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:35705/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 565879 T1608 C760 P49779 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49779 START replicas=[http://127.0.0.1:35705/collection1/] nUpdates=100
[junit4:junit4] 2> 565880 T1608 C760 P49779 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 565880 T1608 C760 P49779 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 565881 T1608 C760 P49779 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 565881 T1608 C760 P49779 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 565881 T1608 C760 P49779 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 565882 T1608 C760 P49779 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:35705/collection1/. core=collection1
[junit4:junit4] 2> 565882 T1608 C760 P49779 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C761 name=collection1 org.apache.solr.core.SolrCore@14be3a4f url=http://127.0.0.1:35705/collection1 node=127.0.0.1:35705_ C761_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:35705, state=active, node_name=127.0.0.1:35705_, collection=collection1, shard=shard1, core=collection1, leader=true}
[junit4:junit4] 2> 565889 T1566 C761 P35705 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 565891 T1567 C761 P35705 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 565892 T1567 C761 P35705 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@29110e3a lockFactory=org.apache.lucene.store.NativeFSLockFactory@d28d7767),segFN=segments_1,generation=1}
[junit4:junit4] 2> 565893 T1567 C761 P35705 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 565894 T1567 C761 P35705 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@29110e3a lockFactory=org.apache.lucene.store.NativeFSLockFactory@d28d7767),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@29110e3a lockFactory=org.apache.lucene.store.NativeFSLockFactory@d28d7767),segFN=segments_2,generation=2}
[junit4:junit4] 2> 565895 T1567 C761 P35705 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 565896 T1567 C761 P35705 oass.SolrIndexSearcher.<init> Opening Searcher@6cbab6b7 realtime
[junit4:junit4] 2> 565897 T1567 C761 P35705 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 565898 T1567 C761 P35705 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 7
[junit4:junit4] 2> 565899 T1608 C760 P49779 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 565899 T1608 C760 P49779 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 565901 T1569 C761 P35705 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 565901 T1569 C761 P35705 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 565902 T1608 C760 P49779 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 565902 T1608 C760 P49779 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 565902 T1608 C760 P49779 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 565904 T1567 C761 P35705 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 565904 T1608 C760 P49779 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 565905 T1608 C760 P49779 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3/index.20130615161658477
[junit4:junit4] 2> 565906 T1608 C760 P49779 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@39ea8747 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28fb9d9a) fullCopy=false
[junit4:junit4] 2> 565907 T1566 C761 P35705 oasc.SolrCore.execute [collection1] webapp= path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=0
[junit4:junit4] 2> 565908 T1608 C760 P49779 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 565909 T1608 C760 P49779 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 565909 T1608 C760 P49779 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 565910 T1608 C760 P49779 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d64445b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c829e0a3),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d64445b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c829e0a3),segFN=segments_2,generation=2}
[junit4:junit4] 2> 565910 T1608 C760 P49779 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 565911 T1608 C760 P49779 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 565911 T1608 C760 P49779 oass.SolrIndexSearcher.<init> Opening Searcher@5a82388c main
[junit4:junit4] 2> 565912 T1607 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5a82388c main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 565913 T1608 C760 P49779 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3/index.20130615161658477 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3/index.20130615161658477;done=true>>]
[junit4:junit4] 2> 565913 T1608 C760 P49779 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3/index.20130615161658477
[junit4:junit4] 2> 565914 T1608 C760 P49779 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3/index.20130615161658477
[junit4:junit4] 2> 565915 T1608 C760 P49779 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 565915 T1608 C760 P49779 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 565915 T1608 C760 P49779 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 565916 T1608 C760 P49779 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 565918 T1608 C760 P49779 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 566236 T1554 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 566237 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48435",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:48435_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 566243 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35705",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:35705_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 566243 T1554 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4] 2> 566244 T1554 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 566248 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49779",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:49779_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 566252 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 566252 T1560 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 566252 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 566252 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 566252 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 566252 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 566537 T1585 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 566537 T1585 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=5&wt=javabin&nodeName=127.0.0.1:48435_&core=collection1} status=0 QTime=1003
[junit4:junit4] 2> 566552 T1568 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1371284206722/onenodecollectioncore
[junit4:junit4] 2> 566553 T1568 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4] 2> 566555 T1568 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4] 2> 566556 T1568 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 566559 T1568 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 566560 T1568 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4] 2> 566564 T1568 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4] 2> 566566 T1568 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1371284206722/onenodecollectioncore/'
[junit4:junit4] 2> 566602 T1568 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 566632 T1568 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 566634 T1568 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 566638 T1568 oass.IndexSchema.readSchema [onenodecollectioncore] Schema name=test
[junit4:junit4] 2> 566956 T1568 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 566962 T1568 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 566965 T1568 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 566976 T1568 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 566980 T1568 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 566984 T1568 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 566985 T1568 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 566986 T1568 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 566987 T1568 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 566988 T1568 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 566988 T1568 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 566989 T1568 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 566990 T1568 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1371284206722/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1371284203256/onenodecollection/
[junit4:junit4] 2> 566990 T1568 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a3a2293
[junit4:junit4] 2> 566991 T1568 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 566992 T1568 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1371284203256/onenodecollection
[junit4:junit4] 2> 566993 T1568 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1371284203256/onenodecollection/index/
[junit4:junit4] 2> 566993 T1568 oasc.SolrCore.initIndex WARN [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1371284203256/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 566994 T1568 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1371284203256/onenodecollection/index
[junit4:junit4] 2> 566996 T1568 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@44e833a0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bee190a3),segFN=segments_1,generation=1}
[junit4:junit4] 2> 566997 T1568 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 566999 T1568 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 566999 T1568 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 567000 T1568 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 567001 T1568 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 567002 T1568 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 567002 T1568 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 567003 T1568 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 567004 T1568 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 567004 T1568 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 567006 T1568 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 567008 T1568 oass.SolrIndexSearcher.<init> Opening Searcher@170d23b3 main
[junit4:junit4] 2> 567009 T1568 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1371284203256/onenodecollection/tlog
[junit4:junit4] 2> 567010 T1568 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 567010 T1568 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 567014 T1629 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@170d23b3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 567016 T1568 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4] 2> 567017 T1568 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:35705 collection:onenodecollection shard:shard1
[junit4:junit4] 2> 567018 T1568 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4] 2> 567027 T1568 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 567031 T1568 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 567032 T1568 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 567033 T1568 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:35705/onenodecollectioncore/
[junit4:junit4] 2> 567034 T1568 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 567036 T1568 oasc.SyncStrategy.syncToMe http://127.0.0.1:35705/onenodecollectioncore/ has no replicas
[junit4:junit4] 2> 567037 T1568 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:35705/onenodecollectioncore/
[junit4:junit4] 2> 567038 T1568 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4] 2> 567759 T1554 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 567772 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 567773 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 567773 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 567773 T1560 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 567773 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 567773 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 567800 T1568 oasc.ZkController.register We are http://127.0.0.1:35705/onenodecollectioncore/ and leader is http://127.0.0.1:35705/onenodecollectioncore/
[junit4:junit4] 2> 567800 T1568 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:35705
[junit4:junit4] 2> 567801 T1568 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 567801 T1568 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4] 2> 567803 T1568 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 567804 T1568 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1371284203256/onenodecollection&action=CREATE&version=2&numShards=1&name=onenodecollectioncore&wt=javabin&roles=none&collection=onenodecollection} status=0 QTime=2255
[junit4:junit4] 2> 567805 T1531 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 567805 T1531 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C762 name=collection1 org.apache.solr.core.SolrCore@a143eb9e url=http://127.0.0.1:48435/collection1 node=127.0.0.1:48435_ C762_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:48435, state=recovering, node_name=127.0.0.1:48435_, collection=collection1, shard=shard2, core=collection1}
[junit4:junit4] 2> 568538 T1625 C762 P48435 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:47780/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 568539 T1625 C762 P48435 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:48435 START replicas=[http://127.0.0.1:47780/collection1/] nUpdates=100
[junit4:junit4] 2> 568539 T1625 C762 P48435 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 568539 T1625 C762 P48435 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 568540 T1625 C762 P48435 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 568540 T1625 C762 P48435 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 568540 T1625 C762 P48435 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 568540 T1625 C762 P48435 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:47780/collection1/. core=collection1
[junit4:junit4] 2> 568541 T1625 C762 P48435 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C763 name=collection1 org.apache.solr.core.SolrCore@28ebde29 url=http://127.0.0.1:47780/collection1 node=127.0.0.1:47780_ C763_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:47780, state=active, node_name=127.0.0.1:47780_, collection=collection1, shard=shard2, core=collection1, leader=true}
[junit4:junit4] 2> 568546 T1585 C763 P47780 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 568546 T1584 C763 P47780 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 568548 T1584 C763 P47780 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@17a54906 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4dbb07ad),segFN=segments_1,generation=1}
[junit4:junit4] 2> 568548 T1584 C763 P47780 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 568549 T1584 C763 P47780 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@17a54906 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4dbb07ad),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@17a54906 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4dbb07ad),segFN=segments_2,generation=2}
[junit4:junit4] 2> 568550 T1584 C763 P47780 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 568550 T1584 C763 P47780 oass.SolrIndexSearcher.<init> Opening Searcher@dedc3155 realtime
[junit4:junit4] 2> 568551 T1584 C763 P47780 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 568551 T1584 C763 P47780 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 5
[junit4:junit4] 2> 568552 T1625 C762 P48435 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 568552 T1625 C762 P48435 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 568553 T1582 C763 P47780 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 568554 T1582 C763 P47780 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 568554 T1625 C762 P48435 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 568555 T1625 C762 P48435 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 568555 T1625 C762 P48435 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 568556 T1585 C763 P47780 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 568557 T1625 C762 P48435 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 568558 T1625 C762 P48435 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4/index.20130615161701130
[junit4:junit4] 2> 568558 T1625 C762 P48435 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@3d8284c4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@df38e9b4) fullCopy=false
[junit4:junit4] 2> 568560 T1584 C763 P47780 oasc.SolrCore.execute [collection1] webapp= path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=0
[junit4:junit4] 2> 568561 T1625 C762 P48435 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 568561 T1625 C762 P48435 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 568562 T1625 C762 P48435 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 568563 T1625 C762 P48435 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@64929534 lockFactory=org.apache.lucene.store.NativeFSLockFactory@509dc8a6),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@64929534 lockFactory=org.apache.lucene.store.NativeFSLockFactory@509dc8a6),segFN=segments_2,generation=2}
[junit4:junit4] 2> 568563 T1625 C762 P48435 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 568563 T1625 C762 P48435 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 568564 T1625 C762 P48435 oass.SolrIndexSearcher.<init> Opening Searcher@55dd3bcf main
[junit4:junit4] 2> 568564 T1624 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@55dd3bcf main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 568565 T1625 C762 P48435 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4/index.20130615161701130 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4/index.20130615161701130;done=true>>]
[junit4:junit4] 2> 568565 T1625 C762 P48435 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4/index.20130615161701130
[junit4:junit4] 2> 568565 T1625 C762 P48435 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4/index.20130615161701130
[junit4:junit4] 2> 568566 T1625 C762 P48435 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 568566 T1625 C762 P48435 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 568566 T1625 C762 P48435 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 568566 T1625 C762 P48435 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 568579 T1625 C762 P48435 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 568807 T1531 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 569284 T1554 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 569286 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35705",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:35705__onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:35705_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 569291 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48435",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:48435_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 569297 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 569297 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 569297 T1560 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 569298 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 569297 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 569297 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 569811 T1531 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 569813 T1531 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4] 2> 569814 T1531 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 569837 T1531 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 569839 T1633 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b9fa6c1a name:ZooKeeperConnection Watcher:127.0.0.1:49255 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 569840 T1531 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 569922 T1531 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 60671
[junit4:junit4] 2> 569923 T1531 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-39563714
[junit4:junit4] 2> 570808 T1554 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 570810 T1554 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60671",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:60671_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 570815 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 570815 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 570815 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 570815 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 570815 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 571927 T1531 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 571928 T1531 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 571931 T1531 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@c95be5df
[junit4:junit4] 2> 571939 T1531 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 571940 T1531 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 571941 T1531 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 571942 T1531 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 571943 T1531 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 571944 T1531 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 571946 T1531 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/control/data/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/control/data/index;done=false>>]
[junit4:junit4] 2> 571947 T1531 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/control/data/index
[junit4:junit4] 2> 571948 T1531 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/control/data [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/control/data;done=false>>]
[junit4:junit4] 2> 571949 T1531 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/control/data
[junit4:junit4] 2> 571950 T1554 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89868481544912899-127.0.0.1:60671_-n_0000000000) am no longer a leader.
[junit4:junit4] 2> 571950 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 571950 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 571951 T1622 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 571951 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 571952 T1573 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 571952 T1589 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 571952 T1605 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 571954 T1573 oasc.Overseer.start Overseer (id=89868481544912902-127.0.0.1:35705_-n_0000000001) starting
[junit4:junit4] 2> 571958 T1635 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 571959 T1573 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 571959 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 571960 T1634 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 571962 T1634 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 571962 T1634 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60671",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:60671_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 571966 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 571966 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 571966 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 571966 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 571971 T1531 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 572023 T1531 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 35705
[junit4:junit4] 2> 572024 T1531 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1606219571
[junit4:junit4] 2> 573251 T1553 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 573251 T1553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 573252 T1553 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 573470 T1634 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 573472 T1634 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35705",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:35705__onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:35705_",
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 573477 T1634 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35705",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:35705_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 573483 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 573483 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 573483 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 573483 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 575028 T1531 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 575029 T1531 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 575032 T1531 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4] 2> 575034 T1531 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@14be3a4f
[junit4:junit4] 2> 575041 T1531 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 575042 T1531 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 575044 T1531 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 575045 T1531 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 575047 T1531 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 575048 T1531 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 575049 T1531 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty1 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty1;done=false>>]
[junit4:junit4] 2> 575051 T1531 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty1
[junit4:junit4] 2> 575052 T1531 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty1/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty1/index;done=false>>]
[junit4:junit4] 2> 575053 T1531 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty1/index
[junit4:junit4] 2> 575055 T1531 oasc.SolrCore.close [onenodecollectioncore] CLOSING SolrCore org.apache.solr.core.SolrCore@2e779b35
[junit4:junit4] 2> 575065 T1531 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 575066 T1531 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 575067 T1531 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 575068 T1531 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 575069 T1531 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4] 2> 575070 T1531 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 575070 T1531 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1371284203256/onenodecollection/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1371284203256/onenodecollection/index;done=false>>]
[junit4:junit4] 2> 575071 T1531 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1371284203256/onenodecollection/index
[junit4:junit4] 2> 575072 T1531 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1371284203256/onenodecollection [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1371284203256/onenodecollection;done=false>>]
[junit4:junit4] 2> 575072 T1531 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1371284203256/onenodecollection
[junit4:junit4] 2> 575073 T1634 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89868481544912902-127.0.0.1:35705_-n_0000000001) am no longer a leader.
[junit4:junit4] 2> 575074 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 575075 T1573 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 575075 T1622 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 575075 T1573 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 575075 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 575076 T1573 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 575076 T1589 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 575075 T1605 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 575078 T1589 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 575079 T1605 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4] 2> 575080 T1605 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4] 2> 575080 T1605 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 575080 T1589 oasc.Overseer.start Overseer (id=89868481544912904-127.0.0.1:47780_-n_0000000002) starting
[junit4:junit4] 2> 575081 T1605 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49779/collection1/
[junit4:junit4] 2> 575082 T1605 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49779 START replicas=[http://127.0.0.1:35705/collection1/] nUpdates=100
[junit4:junit4] 2> 575082 T1605 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49779 DONE. We have no versions. sync failed.
[junit4:junit4] 2> 575083 T1605 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4] 2> 575083 T1605 oasc.ShardLeaderElectionContext.runLeaderProcess We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4:junit4] 2> 575084 T1605 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49779/collection1/
[junit4:junit4] 2> 575084 T1605 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 575086 T1638 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 575086 T1637 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 575088 T1637 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 575088 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 575088 T1637 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35705",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:35705_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 575090 T1605 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 575092 T1637 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35705",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:35705__onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:35705_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 575095 T1531 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 575106 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 575106 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 575106 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 575148 T1531 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 47780
[junit4:junit4] 2> 575149 T1531 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-853146660
[junit4:junit4] 2> 576152 T1531 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 576152 T1531 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 576154 T1531 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@28ebde29
[junit4:junit4] 2> 576157 T1531 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 576158 T1531 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 576158 T1531 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 576159 T1531 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 576160 T1531 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 576160 T1531 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 576161 T1531 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty2 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty2;done=false>>]
[junit4:junit4] 2> 576161 T1531 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty2
[junit4:junit4] 2> 576162 T1531 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty2/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty2/index;done=false>>]
[junit4:junit4] 2> 576162 T1531 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty2/index
[junit4:junit4] 2> 576163 T1637 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89868481544912904-127.0.0.1:47780_-n_0000000002) am no longer a leader.
[junit4:junit4] 2> 576164 T1589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 576164 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 576164 T1589 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 576164 T1589 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 576165 T1622 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 576165 T1605 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 576166 T1605 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 576166 T1622 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4] 2> 576167 T1622 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4] 2> 576167 T1622 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 576168 T1622 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:48435/collection1/
[junit4:junit4] 2> 576168 T1622 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:48435 START replicas=[http://127.0.0.1:47780/collection1/] nUpdates=100
[junit4:junit4] 2> 576168 T1605 oasc.Overseer.start Overseer (id=89868481544912906-127.0.0.1:49779_-n_0000000003) starting
[junit4:junit4] 2> 576168 T1622 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:48435 DONE. We have no versions. sync failed.
[junit4:junit4] 2> 576169 T1622 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4] 2> 576169 T1622 oasc.ShardLeaderElectionContext.runLeaderProcess We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4:junit4] 2> 576170 T1622 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:48435/collection1/
[junit4:junit4] 2> 576170 T1622 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 576172 T1641 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 576172 T1640 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 576174 T1622 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 576174 T1640 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 576174 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 576174 T1531 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 576175 T1640 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47780",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:47780_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 576177 T1640 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47780",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:47780_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 576184 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 576184 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 576226 T1531 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 49779
[junit4:junit4] 2> 576228 T1531 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-1585120477
[junit4:junit4] 2> 577230 T1531 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 577232 T1531 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 577234 T1531 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@6ca75f7
[junit4:junit4] 2> 577240 T1531 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 577241 T1531 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 577242 T1531 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 577243 T1531 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 577245 T1531 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 577246 T1531 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 577247 T1531 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3;done=false>>]
[junit4:junit4] 2> 577248 T1531 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3
[junit4:junit4] 2> 577250 T1531 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3/index;done=false>>]
[junit4:junit4] 2> 577251 T1531 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty3/index
[junit4:junit4] 2> 577252 T1640 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89868481544912906-127.0.0.1:49779_-n_0000000003) am no longer a leader.
[junit4:junit4] 2> 577253 T1605 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 577254 T1605 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 577255 T1605 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 577255 T1622 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 577259 T1622 oasc.Overseer.start Overseer (id=89868481544912908-127.0.0.1:48435_-n_0000000004) starting
[junit4:junit4] 2> 577266 T1643 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 577267 T1622 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4:junit4] 2> 577267 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 577268 T1642 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 577271 T1642 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 577272 T1642 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49779",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:49779_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 577274 T1531 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 577277 T1642 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49779",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:49779_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 577281 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 577328 T1531 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 48435
[junit4:junit4] 2> 577329 T1531 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-498846104
[junit4:junit4] 2> 578332 T1531 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 578333 T1531 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 578336 T1531 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@a143eb9e
[junit4:junit4] 2> 578346 T1531 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 578348 T1531 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 578349 T1531 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 578350 T1531 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 578352 T1531 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 578353 T1531 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 578354 T1531 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4/index;done=false>>]
[junit4:junit4] 2> 578355 T1531 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4/index
[junit4:junit4] 2> 578356 T1531 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4;done=false>>]
[junit4:junit4] 2> 578357 T1531 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1371284203256/jetty4
[junit4:junit4] 2> 578359 T1642 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89868481544912908-127.0.0.1:48435_-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 578381 T1531 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 578440 T1531 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 578442 T1531 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:49255 49255
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 1> / (2)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1> /solr (7)
[junit4:junit4] 1> /solr/configs (1)
[junit4:junit4] 1> /solr/configs/conf1 (9)
[junit4:junit4] 1> /solr/configs/conf1/old_synonyms.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/protwords.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/stopwords.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/synonyms.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/schema.xml (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/currency.xml (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/open-exchange-rates.json (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "disclaimer": "This data is not real, it was synthetically created to match currency.xml. It is modeled after the data format available from openexchangerates.org. See https://openexchangerates.org/documentation for details",
[junit4:junit4] 1> "license": "http://www.apache.org/licenses/LICENSE-2.0",
[junit4:junit4] 1> "timestamp": 1332070464,
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 1> "IMPORTANT NOTE": "In order for tests to work, this data must be kept in sync with ./currency.xml",
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 1> "base": "USD",
[junit4:junit4] 1> "rates": {
[junit4:junit4] 1> "USD": 1,
[junit4:junit4] 1> "JPY": 81.29,
[junit4:junit4] 1> "EUR": 2.5,
[junit4:junit4] 1> "GBP": 0.5,
[junit4:junit4] 1> "MXN": 2.0
[junit4:junit4] 1> }
[junit4:junit4] 1> }
[junit4:junit4] 1>
[junit4:junit4] 1> /solr/configs/conf1/solrconfig.xml (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/mapping-ISOLatin1Accent.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/overseer (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1> /solr/overseer/queue (0)
[junit4:junit4] 1> /solr/overseer/collection-queue-work (0)
[junit4:junit4] 1> /solr/overseer/queue-work (0)
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89868481544912899-127.0.0.1:60671_-n_0000000000"}
[junit4:junit4] 1> /solr/overseer_elect/election (5)
[junit4:junit4] 1> /solr/overseer_elect/election/89868481544912906-127.0.0.1:49779_-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89868481544912902-127.0.0.1:35705_-n_0000000001 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89868481544912899-127.0.0.1:60671_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89868481544912908-127.0.0.1:48435_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89868481544912904-127.0.0.1:47780_-n_0000000002 (0)
[junit4:junit4] 1> /solr/collections (3)
[junit4:junit4] 1> /solr/collections/control_collection (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election/89868481544912899-1-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/control_collection/leaders (1)
[junit4:junit4] 1> /solr/collections/control_collection/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "base_url":"http://127.0.0.1:60671",
[junit4:junit4] 1> "node_name":"127.0.0.1:60671_",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> /solr/collections/control_collection/shards (0)
[junit4:junit4] 1> /solr/collections/collection1 (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/collection1/leader_elect (2)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election (2)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89868481544912906-4-n_0000000001 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89868481544912902-2-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard2 (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard2/election (2)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard2/election/89868481544912904-3-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard2/election/89868481544912908-5-n_0000000001 (0)
[junit4:junit4] 1> /solr/collections/collection1/leaders (2)
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "base_url":"http://127.0.0.1:35705",
[junit4:junit4] 1> "node_name":"127.0.0.1:35705_",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard2 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "base_url":"http://127.0.0.1:47780",
[junit4:junit4] 1> "node_name":"127.0.0.1:47780_",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> /solr/collections/collection1/shards (0)
[junit4:junit4] 1> /solr/collections/onenodecollection (2)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "router":"compositeId",
[junit4:junit4] 1> "configName":"conf1"}
[junit4:junit4] 1> /solr/collections/onenodecollection/leader_elect (1)
[junit4:junit4] 1> /solr/collections/onenodecollection/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/onenodecollection/leader_elect/shard1/election (1)
[junit4:junit4] 1> /solr/collections/onenodecollection/leader_elect/shard1/election/89868481544912902-127.0.0.1:35705__onenodecollectioncore-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/onenodecollection/leaders (1)
[junit4:junit4] 1> /solr/collections/onenodecollection/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "base_url":"http://127.0.0.1:35705",
[junit4:junit4] 1> "node_name":"127.0.0.1:35705_",
[junit4:junit4] 1> "core":"onenodecollectioncore"}
[junit4:junit4] 1> /solr/aliases.json (0)
[junit4:junit4] 1> /solr/live_nodes (5)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:49779_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:47780_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:48435_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:35705_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:60671_ (0)
[junit4:junit4] 1> /solr/clusterstate.json (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "control_collection":{
[junit4:junit4] 1> "shards":{"shard1":{
[junit4:junit4] 1> "range":"80000000-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{"1":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:60671",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:60671_",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"}}}},
[junit4:junit4] 1> "router":"compositeId"},
[junit4:junit4] 1> "onenodecollection":{
[junit4:junit4] 1> "shards":{"shard1":{
[junit4:junit4] 1> "range":"80000000-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{"127.0.0.1:35705__onenodecollectioncore":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:35705",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:35705_",
[junit4:junit4] 1> "roles":"none",
[junit4:junit4] 1> "collection":"onenodecollection",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"onenodecollectioncore",
[junit4:junit4] 1> "leader":"true"}}}},
[junit4:junit4] 1> "router":"compositeId"},
[junit4:junit4] 1> "collection1":{
[junit4:junit4] 1> "shards":{
[junit4:junit4] 1> "shard1":{
[junit4:junit4] 1> "range":"80000000-ffffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{
[junit4:junit4] 1> "2":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:35705",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:35705_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"},
[junit4:junit4] 1> "4":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:49779",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:49779_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1"}}},
[junit4:junit4] 1> "shard2":{
[junit4:junit4] 1> "range":"0-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{
[junit4:junit4] 1> "3":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:47780",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:47780_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"},
[junit4:junit4] 1> "5":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:48435",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:48435_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "core":"collection1"}}}},
[junit4:junit4] 1> "router":"compositeId"}}
[junit4:junit4] 1> /zookeeper (1)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=BasicDistributedZk2Test -Dtests.method=testDistribSearch -Dtests.seed=98262B85C9F9B93A -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=uk_UA -Dtests.timezone=Asia/Chungking -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR 27.8s J1 | BasicDistributedZk2Test.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:47780/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([98262B85C9F9B93A:19C0A59DBEA6D906]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
[junit4:junit4] > at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
[junit4:junit4] > at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
[junit4:junit4] > at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:198)
[junit4:junit4] > at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:90)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:780)
[junit4:junit4] 2> 578487 T1531 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 27811 T1530 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> 579660 T1622 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 579660 T1622 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 579661 T1622 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Asserting, sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {}, locale=uk_UA, timezone=Asia/Chungking
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic x86/IBM Corporation 1.7.0 (32-bit)/cpus=8,threads=3,free=52621440,total=185860096
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestStressReorder, TestSolrXml, SpellPossibilityIteratorTest, ClusterStateTest, IndexSchemaRuntimeFieldTest, TestHashPartitioner, TestNumberUtils, StatsComponentTest, TestMultiCoreConfBootstrap, TestPartialUpdateDeduplication, URLClassifyProcessorTest, CopyFieldTest, DefaultValueUpdateProcessorTest, SpellCheckComponentTest, FileUtilsTest, TestCollationField, TestFieldTypeResource, TestSuggestSpellingConverter, MultiTermTest, BasicZkTest, TestCSVLoader, ZkSolrClientTest, TestComponentsName, TestSolrQueryParserResource, TestSchemaSimilarityResource, CurrencyFieldOpenExchangeTest, TestManagedSchema, IndexReaderFactoryTest, TestSolrXMLSerializer, TestReload, PingRequestHandlerTest, SolrPluginUtilsTest, SuggesterTSTTest, JSONWriterTest, SimplePostToolTest, TestAtomicUpdateErrorCases, TestShardHandlerFactory, SortByFunctionTest, TestRandomFaceting, EchoParamsTest, HighlighterTest, TestQuerySenderNoQuery, DOMUtilTest, DocValuesMultiTest, ConvertedLegacyTest, TestFiltering, TestLMJelinekMercerSimilarityFactory, TestQueryTypes, TestMergePolicyConfig, TestSystemIdResolver, TestBinaryField, RequestHandlersTest, TestFastOutputStream, TestUtils, TestAnalyzedSuggestions, HardAutoCommitTest, TestDistributedSearch, DirectUpdateHandlerTest, ChaosMonkeySafeLeaderTest, DocumentAnalysisRequestHandlerTest, SampleTest, BadIndexSchemaTest, FieldAnalysisRequestHandlerTest, StandardRequestHandlerTest, TestDefaultSimilarityFactory, TestPostingsSolrHighlighter, TestFieldTypeCollectionResource, TestSchemaVersionResource, TestRangeQuery, FullSolrCloudDistribCmdsTest, BasicDistributedZk2Test]
[junit4:junit4] Completed on J1 in 29.10s, 1 test, 1 error <<< FAILURES!
[...truncated 476 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:385: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:378: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1240: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:884: There were test failures: 296 suites, 1243 tests, 1 error, 14 ignored (8 assumptions)
Total time: 43 minutes 18 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure