You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/05/28 14:30:06 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/ibm-j9-jdk6) - Build # 5806
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/5806/
Java: 32bit/ibm-j9-jdk6 -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:38798/w_/p/onenodecollectioncore returned non ok status:404, message:Can not find: /w_/p/onenodecollectioncore/update
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:38798/w_/p/onenodecollectioncore returned non ok status:404, message:Can not find: /w_/p/onenodecollectioncore/update
at __randomizedtesting.SeedInfo.seed([B22A3C3AA856663D:33CCB222DF090601]: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:60)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
at java.lang.reflect.Method.invoke(Method.java:611)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:738)
Build Log:
[...truncated 9108 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4] 2> 943964 T2293 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /w_/p
[junit4:junit4] 2> 943968 T2293 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369743581194
[junit4:junit4] 2> 943970 T2293 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 943971 T2294 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 944071 T2293 oasc.ZkTestServer.run start zk server on port:43088
[junit4:junit4] 2> 944072 T2293 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 944216 T2300 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@63d663d6 name:ZooKeeperConnection Watcher:127.0.0.1:43088 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 944217 T2293 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 944218 T2293 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 944225 T2293 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 944229 T2302 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5bec5bec name:ZooKeeperConnection Watcher:127.0.0.1:43088/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 944229 T2293 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 944230 T2293 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 944240 T2293 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 944246 T2293 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 944249 T2293 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 944254 T2293 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 944255 T2293 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 944261 T2293 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 944262 T2293 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 944267 T2293 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 944268 T2293 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 944272 T2293 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 944274 T2293 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 944278 T2293 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 944279 T2293 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 944283 T2293 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 944284 T2293 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 944289 T2293 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 944290 T2293 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 944295 T2293 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 944297 T2293 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 944304 T2293 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 944305 T2293 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 944534 T2293 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 944537 T2293 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58243
[junit4:junit4] 2> 944538 T2293 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 944538 T2293 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 944539 T2293 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369743581537
[junit4:junit4] 2> 944540 T2293 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369743581537/solr.xml
[junit4:junit4] 2> 944541 T2293 oasc.CoreContainer.<init> New CoreContainer 1039482357
[junit4:junit4] 2> 944541 T2293 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369743581537/'
[junit4:junit4] 2> 944542 T2293 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369743581537/'
[junit4:junit4] 2> 944591 T2293 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 944592 T2293 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 944593 T2293 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 944593 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 944594 T2293 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 944595 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 944595 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 944596 T2293 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 944597 T2293 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 944598 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 944604 T2293 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 944605 T2293 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43088/solr
[junit4:junit4] 2> 944606 T2293 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 944607 T2293 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 944610 T2313 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@429f429f name:ZooKeeperConnection Watcher:127.0.0.1:43088 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 944610 T2293 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 944614 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 944625 T2293 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 944626 T2315 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@27652765 name:ZooKeeperConnection Watcher:127.0.0.1:43088/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 944627 T2293 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 944630 T2293 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 944636 T2293 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 944641 T2293 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 944646 T2293 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58243_w_%2Fp
[junit4:junit4] 2> 944648 T2293 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58243_w_%2Fp
[junit4:junit4] 2> 944656 T2293 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 944665 T2293 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 944669 T2293 oasc.Overseer.start Overseer (id=89767515337523203-127.0.0.1:58243_w_%2Fp-n_0000000000) starting
[junit4:junit4] 2> 944674 T2293 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 944681 T2317 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 944681 T2293 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 944686 T2293 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 944689 T2293 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 944694 T2316 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 944696 T2318 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369743581537/collection1
[junit4:junit4] 2> 944697 T2318 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 944698 T2318 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 944698 T2318 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 944701 T2318 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369743581537/collection1/'
[junit4:junit4] 2> 944702 T2318 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369743581537/collection1/lib/README' to classloader
[junit4:junit4] 2> 944703 T2318 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369743581537/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 944741 T2318 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 944789 T2318 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 944791 T2318 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 944797 T2318 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 945193 T2318 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 945201 T2318 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 945205 T2318 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 945283 T2318 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 945290 T2318 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 945297 T2318 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 945301 T2318 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 945302 T2318 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 945303 T2318 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 945318 T2318 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 945319 T2318 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 945319 T2318 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 945320 T2318 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369743581537/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/control/data/
[junit4:junit4] 2> 945320 T2318 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@413d413d
[junit4:junit4] 2> 945321 T2318 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 945322 T2318 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/control/data
[junit4:junit4] 2> 945322 T2318 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/control/data/index/
[junit4:junit4] 2> 945323 T2318 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 945324 T2318 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/control/data/index
[junit4:junit4] 2> 945327 T2318 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3db43db4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@656e656e),segFN=segments_1,generation=1}
[junit4:junit4] 2> 945327 T2318 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 945330 T2318 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 945331 T2318 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 945332 T2318 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 945333 T2318 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 945334 T2318 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 945334 T2318 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 945335 T2318 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 945336 T2318 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 945337 T2318 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 945339 T2318 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 945342 T2318 oass.SolrIndexSearcher.<init> Opening Searcher@3d183d18 main
[junit4:junit4] 2> 945343 T2318 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/control/data/tlog
[junit4:junit4] 2> 945344 T2318 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 945345 T2318 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 945359 T2318 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 945359 T2319 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3d183d18 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 945360 T2318 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 946202 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 946203 T2316 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:58243/w_/p",
[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:58243_w_%2Fp",
[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> 946204 T2316 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 946205 T2316 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 946212 T2315 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> 946364 T2318 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 946364 T2318 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58243/w_/p collection:control_collection shard:shard1
[junit4:junit4] 2> 946366 T2318 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 946380 T2318 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 946388 T2318 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 946390 T2318 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 946390 T2318 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58243/w_/p/collection1/
[junit4:junit4] 2> 946391 T2318 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 946392 T2318 oasc.SyncStrategy.syncToMe http://127.0.0.1:58243/w_/p/collection1/ has no replicas
[junit4:junit4] 2> 946392 T2318 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58243/w_/p/collection1/
[junit4:junit4] 2> 946393 T2318 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 947721 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 947746 T2315 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> 947763 T2318 oasc.ZkController.register We are http://127.0.0.1:58243/w_/p/collection1/ and leader is http://127.0.0.1:58243/w_/p/collection1/
[junit4:junit4] 2> 947764 T2318 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58243/w_/p
[junit4:junit4] 2> 947764 T2318 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 947765 T2318 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 947765 T2318 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 947768 T2318 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 947770 T2293 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 947771 T2293 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 947772 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 947777 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 947779 T2293 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 947780 T2322 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@28a128a1 name:ZooKeeperConnection Watcher:127.0.0.1:43088/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 947781 T2293 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 947783 T2293 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 947787 T2293 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 947933 T2293 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 947935 T2293 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:39886
[junit4:junit4] 2> 947936 T2293 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 947937 T2293 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 947938 T2293 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369743585012
[junit4:junit4] 2> 947940 T2293 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369743585012/solr.xml
[junit4:junit4] 2> 947941 T2293 oasc.CoreContainer.<init> New CoreContainer 237637162
[junit4:junit4] 2> 947942 T2293 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369743585012/'
[junit4:junit4] 2> 947943 T2293 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369743585012/'
[junit4:junit4] 2> 948038 T2293 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 948039 T2293 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 948041 T2293 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 948042 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 948043 T2293 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 948044 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 948045 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 948047 T2293 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 948048 T2293 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 948049 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 948057 T2293 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 948059 T2293 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43088/solr
[junit4:junit4] 2> 948060 T2293 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 948061 T2293 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 948063 T2333 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@70bb70bb name:ZooKeeperConnection Watcher:127.0.0.1:43088 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 948065 T2293 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 948068 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 948075 T2293 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 948077 T2335 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@72f872f8 name:ZooKeeperConnection Watcher:127.0.0.1:43088/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 948077 T2293 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 948084 T2293 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 949090 T2293 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39886_w_%2Fp
[junit4:junit4] 2> 949092 T2293 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39886_w_%2Fp
[junit4:junit4] 2> 949099 T2315 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 949099 T2322 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 949099 T2315 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> 949102 T2335 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 949109 T2336 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369743585012/collection1
[junit4:junit4] 2> 949110 T2336 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 949111 T2336 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 949112 T2336 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 949115 T2336 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369743585012/collection1/'
[junit4:junit4] 2> 949117 T2336 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369743585012/collection1/lib/README' to classloader
[junit4:junit4] 2> 949118 T2336 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369743585012/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 949157 T2336 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 949192 T2336 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 949194 T2336 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 949199 T2336 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 949255 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 949257 T2316 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:58243/w_/p",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58243_w_%2Fp_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:58243_w_%2Fp",
[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> 949263 T2322 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> 949263 T2335 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> 949263 T2315 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> 949579 T2336 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 949584 T2336 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 949587 T2336 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 949607 T2336 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 949612 T2336 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 949619 T2336 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 949629 T2336 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 949630 T2336 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 949631 T2336 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 949633 T2336 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 949634 T2336 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 949635 T2336 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 949635 T2336 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369743585012/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty1/
[junit4:junit4] 2> 949636 T2336 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@413d413d
[junit4:junit4] 2> 949637 T2336 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 949638 T2336 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty1
[junit4:junit4] 2> 949638 T2336 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty1/index/
[junit4:junit4] 2> 949639 T2336 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 949640 T2336 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty1/index
[junit4:junit4] 2> 949642 T2336 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@428e428e lockFactory=org.apache.lucene.store.NativeFSLockFactory@67db67db),segFN=segments_1,generation=1}
[junit4:junit4] 2> 949642 T2336 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 949646 T2336 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 949646 T2336 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 949647 T2336 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 949648 T2336 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 949649 T2336 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 949650 T2336 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 949651 T2336 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 949652 T2336 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 949652 T2336 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 949654 T2336 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 949656 T2336 oass.SolrIndexSearcher.<init> Opening Searcher@6cce6cce main
[junit4:junit4] 2> 949657 T2336 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty1/tlog
[junit4:junit4] 2> 949658 T2336 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 949659 T2336 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 949665 T2337 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6cce6cce main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 949669 T2336 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 949669 T2336 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 950776 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 950778 T2316 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:39886/w_/p",
[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:39886_w_%2Fp",
[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> 950778 T2316 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 950779 T2316 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 950786 T2322 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> 950787 T2335 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> 950787 T2315 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> 951671 T2336 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 951671 T2336 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39886/w_/p collection:collection1 shard:shard1
[junit4:junit4] 2> 951673 T2336 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 951684 T2336 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 951688 T2336 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 951688 T2336 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 951689 T2336 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:39886/w_/p/collection1/
[junit4:junit4] 2> 951689 T2336 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 951690 T2336 oasc.SyncStrategy.syncToMe http://127.0.0.1:39886/w_/p/collection1/ has no replicas
[junit4:junit4] 2> 951690 T2336 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:39886/w_/p/collection1/
[junit4:junit4] 2> 951691 T2336 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 952323 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 952337 T2322 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> 952337 T2335 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> 952338 T2315 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> 952352 T2336 oasc.ZkController.register We are http://127.0.0.1:39886/w_/p/collection1/ and leader is http://127.0.0.1:39886/w_/p/collection1/
[junit4:junit4] 2> 952353 T2336 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39886/w_/p
[junit4:junit4] 2> 952353 T2336 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 952354 T2336 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 952355 T2336 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 952357 T2336 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 952359 T2293 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 952360 T2293 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 952362 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 952527 T2293 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 952528 T2293 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:38798
[junit4:junit4] 2> 952529 T2293 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 952530 T2293 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 952531 T2293 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369743589595
[junit4:junit4] 2> 952532 T2293 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369743589595/solr.xml
[junit4:junit4] 2> 952532 T2293 oasc.CoreContainer.<init> New CoreContainer 490282297
[junit4:junit4] 2> 952533 T2293 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369743589595/'
[junit4:junit4] 2> 952534 T2293 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369743589595/'
[junit4:junit4] 2> 952584 T2293 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 952585 T2293 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 952585 T2293 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 952586 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 952587 T2293 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 952588 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 952588 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 952589 T2293 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 952590 T2293 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 952591 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 952597 T2293 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 952599 T2293 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43088/solr
[junit4:junit4] 2> 952600 T2293 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 952601 T2293 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 952603 T2349 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@61586158 name:ZooKeeperConnection Watcher:127.0.0.1:43088 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 952603 T2293 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 952606 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 952613 T2293 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 952615 T2351 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@423a423a name:ZooKeeperConnection Watcher:127.0.0.1:43088/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 952615 T2293 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 952622 T2293 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 953655 T2293 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38798_w_%2Fp
[junit4:junit4] 2> 953657 T2293 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38798_w_%2Fp
[junit4:junit4] 2> 953660 T2322 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> 953662 T2315 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 953662 T2335 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> 953662 T2351 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 953663 T2315 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> 953665 T2322 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 953669 T2335 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 953670 T2352 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369743589595/collection1
[junit4:junit4] 2> 953671 T2352 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 953672 T2352 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 953672 T2352 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 953675 T2352 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369743589595/collection1/'
[junit4:junit4] 2> 953676 T2352 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369743589595/collection1/lib/README' to classloader
[junit4:junit4] 2> 953677 T2352 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369743589595/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 953708 T2352 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 953742 T2352 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 953745 T2352 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 953750 T2352 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 953848 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 953850 T2316 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:39886/w_/p",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39886_w_%2Fp_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:39886_w_%2Fp",
[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> 953857 T2322 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> 953857 T2315 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> 953857 T2351 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> 953857 T2335 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> 954113 T2352 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 954119 T2352 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 954122 T2352 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 954141 T2352 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 954146 T2352 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 954151 T2352 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 954153 T2352 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 954154 T2352 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 954154 T2352 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 954157 T2352 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 954157 T2352 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 954158 T2352 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 954158 T2352 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369743589595/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty2/
[junit4:junit4] 2> 954159 T2352 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@413d413d
[junit4:junit4] 2> 954160 T2352 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 954160 T2352 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty2
[junit4:junit4] 2> 954161 T2352 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty2/index/
[junit4:junit4] 2> 954161 T2352 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 954162 T2352 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty2/index
[junit4:junit4] 2> 954164 T2352 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a0a2a0a lockFactory=org.apache.lucene.store.NativeFSLockFactory@5b995b99),segFN=segments_1,generation=1}
[junit4:junit4] 2> 954165 T2352 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 954168 T2352 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 954168 T2352 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 954169 T2352 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 954170 T2352 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 954171 T2352 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 954171 T2352 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 954172 T2352 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 954173 T2352 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 954174 T2352 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 954175 T2352 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 954177 T2352 oass.SolrIndexSearcher.<init> Opening Searcher@6a576a57 main
[junit4:junit4] 2> 954178 T2352 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty2/tlog
[junit4:junit4] 2> 954179 T2352 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 954179 T2352 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 954186 T2353 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6a576a57 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 954219 T2352 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 954220 T2352 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 955368 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 955369 T2316 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:38798/w_/p",
[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:38798_w_%2Fp",
[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> 955370 T2316 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 955370 T2316 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 955376 T2322 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> 955376 T2315 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> 955376 T2351 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> 955376 T2335 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> 956222 T2352 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 956223 T2352 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38798/w_/p collection:collection1 shard:shard2
[junit4:junit4] 2> 956225 T2352 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 956235 T2352 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 956239 T2352 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 956240 T2352 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 956241 T2352 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:38798/w_/p/collection1/
[junit4:junit4] 2> 956241 T2352 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 956242 T2352 oasc.SyncStrategy.syncToMe http://127.0.0.1:38798/w_/p/collection1/ has no replicas
[junit4:junit4] 2> 956243 T2352 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:38798/w_/p/collection1/
[junit4:junit4] 2> 956244 T2352 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 956885 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 956898 T2322 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> 956898 T2315 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> 956898 T2351 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> 956898 T2335 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> 956904 T2352 oasc.ZkController.register We are http://127.0.0.1:38798/w_/p/collection1/ and leader is http://127.0.0.1:38798/w_/p/collection1/
[junit4:junit4] 2> 956905 T2352 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38798/w_/p
[junit4:junit4] 2> 956905 T2352 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 956906 T2352 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 956907 T2352 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 956910 T2352 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 956912 T2293 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 956913 T2293 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 956914 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 957063 T2293 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 957065 T2293 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50137
[junit4:junit4] 2> 957066 T2293 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 957066 T2293 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 957067 T2293 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369743594144
[junit4:junit4] 2> 957068 T2293 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369743594144/solr.xml
[junit4:junit4] 2> 957069 T2293 oasc.CoreContainer.<init> New CoreContainer 784740038
[junit4:junit4] 2> 957069 T2293 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369743594144/'
[junit4:junit4] 2> 957070 T2293 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369743594144/'
[junit4:junit4] 2> 957126 T2293 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 957127 T2293 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 957128 T2293 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 957128 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 957129 T2293 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 957130 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 957131 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 957131 T2293 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 957132 T2293 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 957133 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 957139 T2293 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 957140 T2293 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43088/solr
[junit4:junit4] 2> 957141 T2293 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 957143 T2293 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 957144 T2365 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4c8c4c8c name:ZooKeeperConnection Watcher:127.0.0.1:43088 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 957145 T2293 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 957147 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 957154 T2293 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 957156 T2367 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@20252025 name:ZooKeeperConnection Watcher:127.0.0.1:43088/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 957156 T2293 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 957165 T2293 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 958173 T2293 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50137_w_%2Fp
[junit4:junit4] 2> 958175 T2293 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50137_w_%2Fp
[junit4:junit4] 2> 958180 T2322 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> 958181 T2351 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> 958182 T2335 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> 958182 T2315 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 958183 T2315 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> 958184 T2367 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 958186 T2335 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 958187 T2322 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 958186 T2351 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 958192 T2368 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369743594144/collection1
[junit4:junit4] 2> 958193 T2368 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 958194 T2368 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 958195 T2368 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 958198 T2368 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369743594144/collection1/'
[junit4:junit4] 2> 958199 T2368 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369743594144/collection1/lib/README' to classloader
[junit4:junit4] 2> 958200 T2368 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369743594144/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 958232 T2368 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 958267 T2368 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 958270 T2368 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 958275 T2368 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 958409 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 958411 T2316 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:38798/w_/p",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:38798_w_%2Fp_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:38798_w_%2Fp",
[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> 958417 T2322 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> 958418 T2315 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> 958418 T2351 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> 958417 T2335 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> 958417 T2367 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> 958667 T2368 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 958672 T2368 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 958675 T2368 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 958702 T2368 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 958707 T2368 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 958713 T2368 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 958716 T2368 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 958716 T2368 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 958717 T2368 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 958720 T2368 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 958720 T2368 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 958721 T2368 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 958721 T2368 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369743594144/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty3/
[junit4:junit4] 2> 958722 T2368 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@413d413d
[junit4:junit4] 2> 958723 T2368 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 958724 T2368 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty3
[junit4:junit4] 2> 958724 T2368 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty3/index/
[junit4:junit4] 2> 958725 T2368 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 958725 T2368 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty3/index
[junit4:junit4] 2> 958727 T2368 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1c701c70 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54cc54cc),segFN=segments_1,generation=1}
[junit4:junit4] 2> 958728 T2368 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 958731 T2368 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 958731 T2368 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 958732 T2368 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 958733 T2368 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 958734 T2368 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 958734 T2368 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 958735 T2368 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 958736 T2368 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 958737 T2368 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 958738 T2368 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 958740 T2368 oass.SolrIndexSearcher.<init> Opening Searcher@611e611e main
[junit4:junit4] 2> 958741 T2368 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty3/tlog
[junit4:junit4] 2> 958742 T2368 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 958742 T2368 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 958750 T2369 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@611e611e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 958756 T2368 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 958756 T2368 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 959927 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 959929 T2316 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:50137/w_/p",
[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:50137_w_%2Fp",
[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> 959929 T2316 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 959930 T2316 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 959936 T2322 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> 959936 T2335 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> 959938 T2351 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> 959938 T2315 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> 959938 T2367 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> 960758 T2368 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 960759 T2368 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50137/w_/p collection:collection1 shard:shard1
[junit4:junit4] 2> 960764 T2368 oasc.ZkController.register We are http://127.0.0.1:50137/w_/p/collection1/ and leader is http://127.0.0.1:39886/w_/p/collection1/
[junit4:junit4] 2> 960765 T2368 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50137/w_/p
[junit4:junit4] 2> 960765 T2368 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 960766 T2368 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C4580 name=collection1 org.apache.solr.core.SolrCore@3cac3cac url=http://127.0.0.1:50137/w_/p/collection1 node=127.0.0.1:50137_w_%2Fp C4580_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:50137/w_/p, state=down, node_name=127.0.0.1:50137_w_%2Fp, collection=collection1, core=collection1}
[junit4:junit4] 2> 960767 T2370 C4580 P50137 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 960768 T2370 C4580 P50137 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 960768 T2368 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 960768 T2370 C4580 P50137 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 960770 T2370 C4580 P50137 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 960771 T2293 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 960772 T2293 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 960772 T2370 C4580 P50137 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 960773 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 960780 T2325 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:50137_w_%2Fp_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 960968 T2293 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 960969 T2293 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51663
[junit4:junit4] 2> 960970 T2293 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 960971 T2293 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 960972 T2293 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369743598004
[junit4:junit4] 2> 960973 T2293 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369743598004/solr.xml
[junit4:junit4] 2> 960974 T2293 oasc.CoreContainer.<init> New CoreContainer 286396690
[junit4:junit4] 2> 960975 T2293 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369743598004/'
[junit4:junit4] 2> 960975 T2293 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369743598004/'
[junit4:junit4] 2> 961033 T2293 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 961034 T2293 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 961035 T2293 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 961036 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 961037 T2293 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 961038 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 961039 T2293 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 961039 T2293 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 961040 T2293 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 961041 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 961049 T2293 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 961052 T2293 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43088/solr
[junit4:junit4] 2> 961053 T2293 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 961054 T2293 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 961056 T2382 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7560756 name:ZooKeeperConnection Watcher:127.0.0.1:43088 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 961057 T2293 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 961075 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 961082 T2293 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 961084 T2384 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@57a157a1 name:ZooKeeperConnection Watcher:127.0.0.1:43088/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 961085 T2293 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 961091 T2293 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 961449 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 961450 T2316 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:50137/w_/p",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50137_w_%2Fp_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:50137_w_%2Fp",
[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> 961456 T2322 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> 961456 T2351 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> 961456 T2315 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> 961456 T2335 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> 961456 T2367 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> 961456 T2384 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> 961781 T2325 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:50137_w_%2Fp_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 961782 T2325 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=127.0.0.1:50137_w_%252Fp_collection1&wt=javabin&nodeName=127.0.0.1:50137_w_%252Fp&core=collection1} status=0 QTime=1002
[junit4:junit4] 2> 962097 T2293 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51663_w_%2Fp
[junit4:junit4] 2> 962099 T2293 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51663_w_%2Fp
[junit4:junit4] 2> 962102 T2322 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> 962103 T2335 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> 962103 T2384 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> 962104 T2367 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 962102 T2351 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> 962105 T2367 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> 962103 T2315 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 962107 T2315 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> 962107 T2322 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 962111 T2335 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 962111 T2351 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 962112 T2384 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 962116 T2385 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369743598004/collection1
[junit4:junit4] 2> 962117 T2385 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 962118 T2385 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 962119 T2385 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 962121 T2385 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369743598004/collection1/'
[junit4:junit4] 2> 962122 T2385 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369743598004/collection1/lib/README' to classloader
[junit4:junit4] 2> 962123 T2385 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369743598004/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 962154 T2385 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 962189 T2385 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 962191 T2385 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 962196 T2385 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 962601 T2385 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 962606 T2385 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 962609 T2385 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 962628 T2385 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 962633 T2385 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 962638 T2385 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 962640 T2385 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 962640 T2385 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 962641 T2385 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 962644 T2385 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 962644 T2385 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 962645 T2385 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 962645 T2385 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369743598004/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4/
[junit4:junit4] 2> 962646 T2385 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@413d413d
[junit4:junit4] 2> 962647 T2385 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 962647 T2385 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4
[junit4:junit4] 2> 962648 T2385 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4/index/
[junit4:junit4] 2> 962648 T2385 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 962649 T2385 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4/index
[junit4:junit4] 2> 962651 T2385 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e446e44 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7db67db6),segFN=segments_1,generation=1}
[junit4:junit4] 2> 962652 T2385 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 962655 T2385 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 962655 T2385 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 962656 T2385 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 962657 T2385 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 962658 T2385 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 962658 T2385 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 962659 T2385 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 962660 T2385 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 962661 T2385 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 962662 T2385 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 962664 T2385 oass.SolrIndexSearcher.<init> Opening Searcher@41dc41dc main
[junit4:junit4] 2> 962665 T2385 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4/tlog
[junit4:junit4] 2> 962666 T2385 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 962666 T2385 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 962673 T2386 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@41dc41dc main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 962676 T2385 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 962677 T2385 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 962977 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 962979 T2316 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:51663/w_/p",
[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:51663_w_%2Fp",
[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> 962979 T2316 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 962980 T2316 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 962986 T2384 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> 962986 T2322 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> 962987 T2367 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> 962987 T2335 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> 962987 T2351 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> 962987 T2315 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> 963679 T2385 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 963680 T2385 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51663/w_/p collection:collection1 shard:shard2
[junit4:junit4] 2> 963686 T2385 oasc.ZkController.register We are http://127.0.0.1:51663/w_/p/collection1/ and leader is http://127.0.0.1:38798/w_/p/collection1/
[junit4:junit4] 2> 963686 T2385 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51663/w_/p
[junit4:junit4] 2> 963687 T2385 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 963687 T2385 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C4581 name=collection1 org.apache.solr.core.SolrCore@66466646 url=http://127.0.0.1:51663/w_/p/collection1 node=127.0.0.1:51663_w_%2Fp C4581_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:51663/w_/p, state=down, node_name=127.0.0.1:51663_w_%2Fp, collection=collection1, core=collection1}
[junit4:junit4] 2> 963688 T2387 C4581 P51663 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 963689 T2387 C4581 P51663 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 963689 T2385 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 963689 T2387 C4581 P51663 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 963690 T2387 C4581 P51663 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 963691 T2293 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 963693 T2293 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 963693 T2387 C4581 P51663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 963694 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 963700 T2293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 963701 T2346 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:51663_w_%2Fp_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 963702 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 963748 T2325 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369743585012/onenodecollectioncore
[junit4:junit4] 2> 963749 T2325 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4] 2> 963751 T2325 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4] 2> 963752 T2325 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 963755 T2325 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 963756 T2325 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4] 2> 963761 T2325 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4] 2> 963764 T2325 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369743585012/onenodecollectioncore/'
[junit4:junit4] 2> ASYNC NEW_CORE C4582 name=collection1 org.apache.solr.core.SolrCore@3cac3cac url=http://127.0.0.1:50137/w_/p/collection1 node=127.0.0.1:50137_w_%2Fp C4582_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:50137/w_/p, state=recovering, node_name=127.0.0.1:50137_w_%2Fp, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4] 2> 963783 T2370 C4582 P50137 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:39886/w_/p/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 963784 T2370 C4582 P50137 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50137/w_/p START replicas=[http://127.0.0.1:39886/w_/p/collection1/] nUpdates=100
[junit4:junit4] 2> 963785 T2370 C4582 P50137 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 963785 T2370 C4582 P50137 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 963786 T2370 C4582 P50137 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 963787 T2370 C4582 P50137 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 963787 T2370 C4582 P50137 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 963788 T2370 C4582 P50137 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:39886/w_/p/collection1/. core=collection1
[junit4:junit4] 2> 963788 T2370 C4582 P50137 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C4583 name=collection1 org.apache.solr.core.SolrCore@513f513f url=http://127.0.0.1:39886/w_/p/collection1 node=127.0.0.1:39886_w_%2Fp C4583_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:39886/w_/p, state=active, node_name=127.0.0.1:39886_w_%2Fp, collection=collection1, shard=shard1, core=collection1, leader=true}
[junit4:junit4] 2> 963791 T2330 C4583 P39886 oasc.SolrCore.execute [collection1] webapp=/w_/p path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 963798 T2331 C4583 P39886 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 963801 T2331 C4583 P39886 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@428e428e lockFactory=org.apache.lucene.store.NativeFSLockFactory@67db67db),segFN=segments_1,generation=1}
[junit4:junit4] 2> 963802 T2331 C4583 P39886 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 963803 T2325 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 963804 T2331 C4583 P39886 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@428e428e lockFactory=org.apache.lucene.store.NativeFSLockFactory@67db67db),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@428e428e lockFactory=org.apache.lucene.store.NativeFSLockFactory@67db67db),segFN=segments_2,generation=2}
[junit4:junit4] 2> 963806 T2331 C4583 P39886 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 963807 T2331 C4583 P39886 oass.SolrIndexSearcher.<init> Opening Searcher@1380138 realtime
[junit4:junit4] 2> 963809 T2331 C4583 P39886 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 963810 T2331 C4583 P39886 oasup.LogUpdateProcessor.finish [collection1] webapp=/w_/p path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 12
[junit4:junit4] 2> 963811 T2370 C4582 P50137 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 963812 T2370 C4582 P50137 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 963814 T2330 C4583 P39886 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 963815 T2330 C4583 P39886 oasc.SolrCore.execute [collection1] webapp=/w_/p path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=2
[junit4:junit4] 2> 963816 T2370 C4582 P50137 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 963816 T2370 C4582 P50137 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 963817 T2370 C4582 P50137 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 963819 T2331 C4583 P39886 oasc.SolrCore.execute [collection1] webapp=/w_/p path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 963820 T2370 C4582 P50137 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 963821 T2370 C4582 P50137 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty3/index.20130528072001046
[junit4:junit4] 2> 963822 T2370 C4582 P50137 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@10981098 lockFactory=org.apache.lucene.store.NativeFSLockFactory@d5a0d5a) fullCopy=false
[junit4:junit4] 2> 963824 T2329 C4583 P39886 oasc.SolrCore.execute [collection1] webapp=/w_/p path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=0
[junit4:junit4] 2> 963825 T2370 C4582 P50137 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 963826 T2370 C4582 P50137 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 963827 T2370 C4582 P50137 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 963828 T2370 C4582 P50137 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1c701c70 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54cc54cc),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1c701c70 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54cc54cc),segFN=segments_2,generation=2}
[junit4:junit4] 2> 963829 T2370 C4582 P50137 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 963830 T2370 C4582 P50137 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 963831 T2370 C4582 P50137 oass.SolrIndexSearcher.<init> Opening Searcher@33553355 main
[junit4:junit4] 2> 963832 T2369 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@33553355 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 963833 T2370 C4582 P50137 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty3/index.20130528072001046 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty3/index.20130528072001046;done=true>>]
[junit4:junit4] 2> 963834 T2370 C4582 P50137 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty3/index.20130528072001046
[junit4:junit4] 2> 963834 T2370 C4582 P50137 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty3/index.20130528072001046
[junit4:junit4] 2> 963835 T2370 C4582 P50137 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 963836 T2370 C4582 P50137 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 963836 T2370 C4582 P50137 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 963837 T2370 C4582 P50137 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 963839 T2370 C4582 P50137 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 963843 T2325 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 963845 T2325 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 963851 T2325 oass.IndexSchema.readSchema [onenodecollectioncore] Schema name=test
[junit4:junit4] 2> 964254 T2325 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 964259 T2325 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 964263 T2325 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 964294 T2325 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 964299 T2325 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 964304 T2325 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 964306 T2325 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 964307 T2325 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 964308 T2325 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 964310 T2325 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 964311 T2325 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 964312 T2325 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 964313 T2325 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369743585012/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369743581194/onenodecollection/
[junit4:junit4] 2> 964314 T2325 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@413d413d
[junit4:junit4] 2> 964315 T2325 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 964316 T2325 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369743581194/onenodecollection
[junit4:junit4] 2> 964317 T2325 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369743581194/onenodecollection/index/
[junit4:junit4] 2> 964318 T2325 oasc.SolrCore.initIndex WARN [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369743581194/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 964319 T2325 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369743581194/onenodecollection/index
[junit4:junit4] 2> 964321 T2325 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58265826 lockFactory=org.apache.lucene.store.NativeFSLockFactory@764b764b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 964322 T2325 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 964326 T2325 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 964327 T2325 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 964328 T2325 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 964329 T2325 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 964330 T2325 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 964331 T2325 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 964332 T2325 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 964333 T2325 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 964334 T2325 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 964336 T2325 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 964338 T2325 oass.SolrIndexSearcher.<init> Opening Searcher@2d0a2d0a main
[junit4:junit4] 2> 964339 T2325 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369743581194/onenodecollection/tlog
[junit4:junit4] 2> 964341 T2325 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 964341 T2325 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 964348 T2391 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@2d0a2d0a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 964353 T2325 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4] 2> 964497 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 964498 T2316 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:51663/w_/p",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:51663_w_%2Fp_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:51663_w_%2Fp",
[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> 964505 T2316 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:50137/w_/p",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50137_w_%2Fp_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:50137_w_%2Fp",
[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> 964511 T2316 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:39886/w_/p",
[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:39886_w_%2Fp",
[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> 964511 T2316 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4] 2> 964512 T2316 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 964518 T2322 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> 964518 T2351 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> 964518 T2384 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> 964519 T2315 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> 964519 T2367 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> 964520 T2335 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> 964702 T2346 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:51663_w_%2Fp_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 964703 T2346 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=127.0.0.1:51663_w_%252Fp_collection1&wt=javabin&nodeName=127.0.0.1:51663_w_%252Fp&core=collection1} status=0 QTime=1002
[junit4:junit4] 2> 965355 T2325 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4] 2> 965356 T2325 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:39886/w_/p collection:onenodecollection shard:shard1
[junit4:junit4] 2> 965358 T2325 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4] 2> 965369 T2325 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 965373 T2325 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 965374 T2325 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 965375 T2325 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:39886/w_/p/onenodecollectioncore/
[junit4:junit4] 2> 965376 T2325 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 965377 T2325 oasc.SyncStrategy.syncToMe http://127.0.0.1:39886/w_/p/onenodecollectioncore/ has no replicas
[junit4:junit4] 2> 965378 T2325 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:39886/w_/p/onenodecollectioncore/
[junit4:junit4] 2> 965378 T2325 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4] 2> 966034 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 966051 T2322 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> 966051 T2335 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> 966052 T2367 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> 966051 T2351 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> 966052 T2384 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> 966051 T2315 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> 966097 T2325 oasc.ZkController.register We are http://127.0.0.1:39886/w_/p/onenodecollectioncore/ and leader is http://127.0.0.1:39886/w_/p/onenodecollectioncore/
[junit4:junit4] 2> 966098 T2325 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:39886/w_/p
[junit4:junit4] 2> 966099 T2325 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 966100 T2325 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4] 2> 966102 T2325 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 966104 T2325 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369743581194/onenodecollection&action=CREATE&version=2&numShards=1&name=onenodecollectioncore&wt=javabin&roles=none&collection=onenodecollection} status=0 QTime=2356
[junit4:junit4] 2> 966105 T2293 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 966107 T2293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C4584 name=collection1 org.apache.solr.core.SolrCore@66466646 url=http://127.0.0.1:51663/w_/p/collection1 node=127.0.0.1:51663_w_%2Fp C4584_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:51663/w_/p, state=recovering, node_name=127.0.0.1:51663_w_%2Fp, collection=collection1, shard=shard2, core=collection1}
[junit4:junit4] 2> 966704 T2387 C4584 P51663 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:38798/w_/p/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 966705 T2387 C4584 P51663 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:51663/w_/p START replicas=[http://127.0.0.1:38798/w_/p/collection1/] nUpdates=100
[junit4:junit4] 2> 966705 T2387 C4584 P51663 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 966706 T2387 C4584 P51663 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 966706 T2387 C4584 P51663 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 966707 T2387 C4584 P51663 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 966707 T2387 C4584 P51663 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 966707 T2387 C4584 P51663 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:38798/w_/p/collection1/. core=collection1
[junit4:junit4] 2> 966708 T2387 C4584 P51663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C4585 name=collection1 org.apache.solr.core.SolrCore@3fa63fa6 url=http://127.0.0.1:38798/w_/p/collection1 node=127.0.0.1:38798_w_%2Fp C4585_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:38798/w_/p, state=active, node_name=127.0.0.1:38798_w_%2Fp, collection=collection1, shard=shard2, core=collection1, leader=true}
[junit4:junit4] 2> 966711 T2346 C4585 P38798 oasc.SolrCore.execute [collection1] webapp=/w_/p path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 966714 T2344 C4585 P38798 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 966717 T2344 C4585 P38798 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a0a2a0a lockFactory=org.apache.lucene.store.NativeFSLockFactory@5b995b99),segFN=segments_1,generation=1}
[junit4:junit4] 2> 966718 T2344 C4585 P38798 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 966719 T2344 C4585 P38798 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a0a2a0a lockFactory=org.apache.lucene.store.NativeFSLockFactory@5b995b99),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a0a2a0a lockFactory=org.apache.lucene.store.NativeFSLockFactory@5b995b99),segFN=segments_2,generation=2}
[junit4:junit4] 2> 966719 T2344 C4585 P38798 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 966720 T2344 C4585 P38798 oass.SolrIndexSearcher.<init> Opening Searcher@51095109 realtime
[junit4:junit4] 2> 966721 T2344 C4585 P38798 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 966722 T2344 C4585 P38798 oasup.LogUpdateProcessor.finish [collection1] webapp=/w_/p path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 8
[junit4:junit4] 2> 966723 T2387 C4584 P51663 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 966724 T2387 C4584 P51663 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 966725 T2346 C4585 P38798 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 966726 T2346 C4585 P38798 oasc.SolrCore.execute [collection1] webapp=/w_/p path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 966727 T2387 C4584 P51663 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 966728 T2387 C4584 P51663 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 966729 T2387 C4584 P51663 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 966731 T2347 C4585 P38798 oasc.SolrCore.execute [collection1] webapp=/w_/p path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 966732 T2387 C4584 P51663 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 966733 T2387 C4584 P51663 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4/index.20130528072003957
[junit4:junit4] 2> 966733 T2387 C4584 P51663 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@460a460a lockFactory=org.apache.lucene.store.NativeFSLockFactory@68086808) fullCopy=false
[junit4:junit4] 2> 966735 T2344 C4585 P38798 oasc.SolrCore.execute [collection1] webapp=/w_/p path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=0
[junit4:junit4] 2> 966737 T2387 C4584 P51663 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 966738 T2387 C4584 P51663 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 966738 T2387 C4584 P51663 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 966740 T2387 C4584 P51663 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e446e44 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7db67db6),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e446e44 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7db67db6),segFN=segments_2,generation=2}
[junit4:junit4] 2> 966741 T2387 C4584 P51663 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 966741 T2387 C4584 P51663 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 966742 T2387 C4584 P51663 oass.SolrIndexSearcher.<init> Opening Searcher@29e029e main
[junit4:junit4] 2> 966743 T2386 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@29e029e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 966744 T2387 C4584 P51663 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4/index.20130528072003957 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4/index.20130528072003957;done=true>>]
[junit4:junit4] 2> 966745 T2387 C4584 P51663 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4/index.20130528072003957
[junit4:junit4] 2> 966745 T2387 C4584 P51663 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4/index.20130528072003957
[junit4:junit4] 2> 966746 T2387 C4584 P51663 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 966747 T2387 C4584 P51663 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 966747 T2387 C4584 P51663 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 966748 T2387 C4584 P51663 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 966749 T2387 C4584 P51663 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 967110 T2293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 967565 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 967567 T2316 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:39886/w_/p",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39886_w_%2Fp_onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:39886_w_%2Fp",
[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> 967572 T2316 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:51663/w_/p",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:51663_w_%2Fp_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:51663_w_%2Fp",
[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> 967580 T2322 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> 967580 T2315 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> 967580 T2351 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> 967580 T2335 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> 967580 T2384 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> 967580 T2367 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> 968112 T2293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 968114 T2293 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4] 2> 968115 T2293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 968127 T2293 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 968128 T2395 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9410941 name:ZooKeeperConnection Watcher:127.0.0.1:43088 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 968129 T2293 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 1> / (2)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1> /solr (7)
[junit4:junit4] 1> /solr/configs (1)
[junit4:junit4] 1> /solr/configs/conf1 (9)
[junit4:junit4] 1> /solr/configs/conf1/old_synonyms.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/protwords.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/stopwords.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/synonyms.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/schema.xml (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/currency.xml (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/open-exchange-rates.json (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "disclaimer": "This data is not real, it was synthetically created to match currency.xml. It is modeled after the data format available from openexchangerates.org. See https://openexchangerates.org/documentation for details",
[junit4:junit4] 1> "license": "http://www.apache.org/licenses/LICENSE-2.0",
[junit4:junit4] 1> "timestamp": 1332070464,
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 1> "IMPORTANT NOTE": "In order for tests to work, this data must be kept in sync with ./currency.xml",
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 1> "base": "USD",
[junit4:junit4] 1> "rates": {
[junit4:junit4] 1> "USD": 1,
[junit4:junit4] 1> "JPY": 81.29,
[junit4:junit4] 1> "EUR": 2.5,
[junit4:junit4] 1> "GBP": 0.5,
[junit4:junit4] 1> "MXN": 2.0
[junit4:junit4] 1> }
[junit4:junit4] 1> }
[junit4:junit4] 1>
[junit4:junit4] 1> /solr/configs/conf1/solrconfig.xml (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/mapping-ISOLatin1Accent.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/overseer (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1> /solr/overseer/queue (0)
[junit4:junit4] 1> /solr/overseer/collection-queue-work (0)
[junit4:junit4] 1> /solr/overseer/queue-work (0)
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89767515337523203-127.0.0.1:58243_w_%2Fp-n_0000000000"}
[junit4:junit4] 1> /solr/overseer_elect/election (5)
[junit4:junit4] 1> /solr/overseer_elect/election/89767515337523203-127.0.0.1:58243_w_%2Fp-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89767515337523208-127.0.0.1:38798_w_%2Fp-n_0000000002 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89767515337523212-127.0.0.1:51663_w_%2Fp-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89767515337523210-127.0.0.1:50137_w_%2Fp-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89767515337523206-127.0.0.1:39886_w_%2Fp-n_0000000001 (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/89767515337523203-127.0.0.1:58243_w_%2Fp_collection1-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/control_collection/leaders (1)
[junit4:junit4] 1> /solr/collections/control_collection/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "base_url":"http://127.0.0.1:58243/w_/p",
[junit4:junit4] 1> "node_name":"127.0.0.1:58243_w_%2Fp",
[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/89767515337523206-127.0.0.1:39886_w_%2Fp_collection1-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89767515337523210-127.0.0.1:50137_w_%2Fp_collection1-n_0000000001 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard2 (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard2/election (2)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard2/election/89767515337523212-127.0.0.1:51663_w_%2Fp_collection1-n_0000000001 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard2/election/89767515337523208-127.0.0.1:38798_w_%2Fp_collection1-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/collection1/leaders (2)
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39886/w_/p",
[junit4:junit4] 1> "node_name":"127.0.0.1:39886_w_%2Fp",
[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:38798/w_/p",
[junit4:junit4] 1> "node_name":"127.0.0.1:38798_w_%2Fp",
[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/89767515337523206-127.0.0.1:39886_w_%2Fp_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:39886/w_/p",
[junit4:junit4] 1> "node_name":"127.0.0.1:39886_w_%2Fp",
[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:50137_w_%2Fp (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:38798_w_%2Fp (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:39886_w_%2Fp (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:51663_w_%2Fp (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:58243_w_%2Fp (0)
[junit4:junit4] 1> /solr/clusterstate.json (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "control_collection":{
[junit4:junit4] 1> "shards":{"shard1":{
[junit4:junit4] 1> "range":"80000000-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{"127.0.0.1:58243_w_%2Fp_collection1":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:58243/w_/p",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:58243_w_%2Fp",
[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:39886_w_%2Fp_onenodecollectioncore":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39886/w_/p",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:39886_w_%2Fp",
[junit4:junit4] 1> "roles":"none",
[junit4:junit4] 1> "collection":"onenodecollection",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"onenodecollectioncore",
[junit4:junit4] 1> "leader":"true"}}}},
[junit4:junit4] 1> "router":"compositeId"},
[junit4:junit4] 1> "collection1":{
[junit4:junit4] 1> "shards":{
[junit4:junit4] 1> "shard1":{
[junit4:junit4] 1> "range":"80000000-ffffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{
[junit4:junit4] 1> "127.0.0.1:39886_w_%2Fp_collection1":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39886/w_/p",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:39886_w_%2Fp",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"},
[junit4:junit4] 1> "127.0.0.1:50137_w_%2Fp_collection1":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:50137/w_/p",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:50137_w_%2Fp",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1"}}},
[junit4:junit4] 1> "shard2":{
[junit4:junit4] 1> "range":"0-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{
[junit4:junit4] 1> "127.0.0.1:38798_w_%2Fp_collection1":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:38798/w_/p",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:38798_w_%2Fp",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"},
[junit4:junit4] 1> "127.0.0.1:51663_w_%2Fp_collection1":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:51663/w_/p",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:51663_w_%2Fp",
[junit4:junit4] 2> 968233 T2293 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 58243
[junit4:junit4] 2> 968233 T2293 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1039482357
[junit4:junit4] 2> 969094 T2316 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 969095 T2316 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58243/w_/p",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58243_w_%2Fp_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:58243_w_%2Fp",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 969102 T2351 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> 969102 T2367 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> 969102 T2335 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> 969102 T2384 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> 969102 T2315 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> 970236 T2293 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 970237 T2293 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 970239 T2293 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@53f253f2
[junit4:junit4] 2> 970243 T2293 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> 970244 T2293 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 970244 T2293 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 970245 T2293 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 970246 T2293 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 970246 T2293 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 970247 T2293 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/control/data [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/control/data;done=false>>]
[junit4:junit4] 2> 970248 T2293 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/control/data
[junit4:junit4] 2> 970248 T2293 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/control/data/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/control/data/index;done=false>>]
[junit4:junit4] 2> 970249 T2293 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/control/data/index
[junit4:junit4] 2> 970250 T2316 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89767515337523203-127.0.0.1:58243_w_%2Fp-n_0000000000) am no longer a leader.
[junit4:junit4] 2> 970251 T2384 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> 970251 T2351 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> 970253 T2315 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 970253 T2315 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> 970254 T2315 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 970254 T2335 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 970255 T2384 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 970255 T2351 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 970254 T2367 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 970257 T2367 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> 970260 T2335 oasc.Overseer.start Overseer (id=89767515337523206-127.0.0.1:39886_w_%2Fp-n_0000000001) starting
[junit4:junit4] 2> 970269 T2335 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> 970269 T2397 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 970273 T2293 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/w_/p,null}
[junit4:junit4] 2> 970274 T2335 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 970276 T2396 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 970281 T2396 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 970283 T2396 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:58243/w_/p",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58243_w_%2Fp_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:58243_w_%2Fp",
[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> 970291 T2351 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> 970291 T2367 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> 970291 T2384 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> 970291 T2335 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> 970325 T2293 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 39886
[junit4:junit4] 2> 970326 T2293 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=237637162
[junit4:junit4] 2> 971801 T2396 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 971803 T2396 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39886/w_/p",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39886_w_%2Fp_onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:39886_w_%2Fp",
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 971811 T2396 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39886/w_/p",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39886_w_%2Fp_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:39886_w_%2Fp",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 971830 T2335 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> 971830 T2367 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> 971830 T2384 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> 971830 T2351 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> 973330 T2293 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 973331 T2293 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 973332 T2293 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4] 2> 973334 T2293 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@513f513f
[junit4:junit4] 2> 973338 T2293 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> 973339 T2293 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 973340 T2293 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 973341 T2293 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 973343 T2293 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 973344 T2293 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 973344 T2396 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 973344 T2293 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty1 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty1;done=false>>]
[junit4:junit4] 2> 973346 T2293 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty1
[junit4:junit4] 2> 973346 T2396 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:39886/w_/p",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39886_w_%2Fp_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:39886_w_%2Fp",
[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> 973346 T2293 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty1/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty1/index;done=false>>]
[junit4:junit4] 2> 973348 T2293 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty1/index
[junit4:junit4] 2> 973348 T2293 oasc.SolrCore.close [onenodecollectioncore] CLOSING SolrCore org.apache.solr.core.SolrCore@2bcb2bcb
[junit4:junit4] 2> 973354 T2396 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:39886/w_/p",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39886_w_%2Fp_onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:39886_w_%2Fp",
[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> 973356 T2293 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> 973357 T2293 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 973358 T2293 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 973358 T2293 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 973359 T2293 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4] 2> 973360 T2293 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 973361 T2293 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369743581194/onenodecollection/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369743581194/onenodecollection/index;done=false>>]
[junit4:junit4] 2> 973362 T2384 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> 973362 T2351 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> 973362 T2367 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> 973362 T2293 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369743581194/onenodecollection/index
[junit4:junit4] 2> 973362 T2335 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> 973365 T2293 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369743581194/onenodecollection [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369743581194/onenodecollection;done=false>>]
[junit4:junit4] 2> 973366 T2293 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369743581194/onenodecollection
[junit4:junit4] 2> 973369 T2384 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> 973370 T2295 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eeb1460100006, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:738)
[junit4:junit4] 2>
[junit4:junit4] 2> 973373 T2351 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 973375 T2367 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 973375 T2384 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 973379 T2367 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4] 2> 973379 T2351 oasc.Overseer.start Overseer (id=89767515337523208-127.0.0.1:38798_w_%2Fp-n_0000000002) starting
[junit4:junit4] 2> 973380 T2367 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4] 2> 973381 T2367 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 973382 T2367 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50137/w_/p/collection1/
[junit4:junit4] 2> 973382 T2367 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50137/w_/p START replicas=[http://127.0.0.1:39886/w_/p/collection1/] nUpdates=100
[junit4:junit4] 2> 973383 T2367 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50137/w_/p DONE. We have no versions. sync failed.
[junit4:junit4] 2> 973384 T2367 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4] 2> 973385 T2367 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> 973385 T2367 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50137/w_/p/collection1/
[junit4:junit4] 2> 973386 T2367 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 973392 T2351 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> 973392 T2293 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/w_/p,null}
[junit4:junit4] 2> 973392 T2400 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 973397 T2351 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 973398 T2367 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 973398 T2367 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> 973401 T2399 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 973402 T2399 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue.
[junit4:junit4] 2> 973404 T2399 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:39886/w_/p",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39886_w_%2Fp_onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:39886_w_%2Fp",
[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> 973405 T2351 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> 973406 T2384 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> 973407 T2367 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> 973411 T2399 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 973417 T2399 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 973445 T2293 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 38798
[junit4:junit4] 2> 973445 T2293 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=490282297
[junit4:junit4] 2> 973448 T2351 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> 973448 T2384 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> 973448 T2367 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> 974447 T2293 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 974448 T2293 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 974450 T2293 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@3fa63fa6
[junit4:junit4] 2> 974454 T2293 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> 974455 T2293 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 974456 T2293 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 974456 T2293 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 974458 T2293 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 974458 T2293 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 974459 T2293 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty2 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty2;done=false>>]
[junit4:junit4] 2> 974460 T2293 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty2
[junit4:junit4] 2> 974460 T2293 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty2/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty2/index;done=false>>]
[junit4:junit4] 2> 974461 T2293 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty2/index
[junit4:junit4] 2> 974463 T2399 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89767515337523208-127.0.0.1:38798_w_%2Fp-n_0000000002) am no longer a leader.
[junit4:junit4] 2> 974463 T2384 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> 974466 T2384 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 974467 T2351 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> 974468 T2351 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 974469 T2351 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 974469 T2367 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 974470 T2384 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 974473 T2384 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4] 2> 974474 T2384 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4] 2> 974475 T2367 oasc.Overseer.start Overseer (id=89767515337523210-127.0.0.1:50137_w_%2Fp-n_0000000003) starting
[junit4:junit4] 2> 974475 T2384 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 974476 T2384 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51663/w_/p/collection1/
[junit4:junit4] 2> 974477 T2384 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 974477 T2384 oasc.SyncStrategy.syncToMe http://127.0.0.1:51663/w_/p/collection1/ has no replicas
[junit4:junit4] 2> 974478 T2384 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51663/w_/p/collection1/
[junit4:junit4] 2> 974478 T2384 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 974484 T2402 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 974486 T2367 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 974486 T2367 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> 974488 T2401 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 974489 T2293 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/w_/p,null}
[junit4:junit4] 2> 974495 T2401 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 974496 T2401 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38798/w_/p",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:38798_w_%2Fp_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:38798_w_%2Fp",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 974504 T2401 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:38798/w_/p",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:38798_w_%2Fp_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:38798_w_%2Fp",
[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> 974525 T2384 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> 974526 T2367 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> 974541 T2293 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 50137
[junit4:junit4] 2> 974542 T2293 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=784740038
[junit4:junit4] 2> 974668 T2335 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 974669 T2335 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> 974669 T2335 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 974670 T2335 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 975544 T2293 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 975545 T2293 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 975547 T2293 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@3cac3cac
[junit4:junit4] 2> 975551 T2293 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> 975552 T2293 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 975553 T2293 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 975553 T2293 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 975555 T2293 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 975555 T2293 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 d
[...truncated too long message...]
2> "core_node_name":"127.0.0.1:50137_w_%2Fp_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:50137_w_%2Fp",
[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> 975614 T2384 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> 975643 T2293 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 51663
[junit4:junit4] 2> 975643 T2293 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=286396690
[junit4:junit4] 2> 976645 T2293 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 976646 T2293 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 976650 T2293 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@66466646
[junit4:junit4] 2> 976658 T2293 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> 976658 T2293 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 976659 T2293 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 976660 T2293 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 976661 T2293 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 976662 T2293 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 976662 T2293 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4/index;done=false>>]
[junit4:junit4] 2> 976663 T2293 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4/index
[junit4:junit4] 2> 976664 T2293 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4;done=false>>]
[junit4:junit4] 2> 976664 T2293 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369743581194/jetty4
[junit4:junit4] 2> 976665 T2403 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89767515337523212-127.0.0.1:51663_w_%2Fp-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 976666 T2384 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> 976687 T2293 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/w_/p,null}
[junit4:junit4] 2> 976746 T2293 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 976747 T2293 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:43088 43088
[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=B22A3C3AA856663D -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=zh_TW -Dtests.timezone=America/Monterrey -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR 32.8s J0 | BasicDistributedZk2Test.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:38798/w_/p/onenodecollectioncore returned non ok status:404, message:Can not find: /w_/p/onenodecollectioncore/update
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([B22A3C3AA856663D:33CCB222DF090601]: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:738)
[junit4:junit4] 2> 976782 T2293 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 32835 T2292 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> 976860 T2367 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 976861 T2367 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> 976861 T2367 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 977967 T2384 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 977967 T2384 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=zh_TW, timezone=America/Monterrey
[junit4:junit4] 2> NOTE: Linux 3.2.0-44-generic x86/IBM Corporation 1.6.0 (32-bit)/cpus=8,threads=2,free=22052488,total=79830528
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestExtendedDismaxParser, DirectUpdateHandlerOptimizeTest, DocValuesTest, UpdateRequestProcessorFactoryTest, TestPropInjectDefaults, TestPHPSerializedResponseWriter, QueryElevationComponentTest, TestSolrQueryParserResource, TestRealTimeGet, TestSolrQueryParserDefaultOperatorResource, TestManagedSchemaFieldResource, ZkCLITest, TestSurroundQueryParser, RegexBoostProcessorTest, TestStressRecovery, SynonymTokenizerTest, BadCopyFieldTest, TestDefaultSearchFieldResource, DateFieldTest, ShowFileRequestHandlerTest, QueryParsingTest, TestXIncludeConfig, ResourceLoaderTest, TestRemoteStreaming, PluginInfoTest, SpellingQueryConverterTest, TestWriterPerf, PreAnalyzedUpdateProcessorTest, TestGroupingSearch, SearchHandlerTest, BadComponentTest, TestConfig, TestDocSet, TestDocumentBuilder, TestFuzzyAnalyzedSuggestions, TestSolrQueryParser, PolyFieldTest, TestFieldResource, TestBadConfig, TestDynamicFieldCollectionResource, TestRandomDVFaceting, CacheHeaderTest, PeerSyncTest, SolrIndexSplitterTest, DistributedSpellCheckComponentTest, SOLR749Test, TestClassNameShortening, TestQueryUtils, TestFaceting, SchemaVersionSpecificBehaviorTest, AutoCommitTest, MoreLikeThisHandlerTest, TestSort, TestReversedWildcardFilterFactory, TestJoin, SliceStateUpdateTest, TestUniqueKeyFieldResource, TestSolrDeletionPolicy1, UnloadDistributedZkTest, TermVectorComponentTest, LeaderElectionTest, MinimalSchemaTest, TestDynamicFieldResource, OverseerTest, SpatialFilterTest, TestSerializedLuceneMatchVersion, SolrInfoMBeanTest, PreAnalyzedFieldTest, TestPseudoReturnFields, DistributedQueryElevationComponentTest, AnalysisAfterCoreReloadTest, BasicDistributedZkTest, BasicDistributedZk2Test]
[junit4:junit4] Completed on J0 in 34.12s, 1 test, 1 error <<< FAILURES!
[...truncated 464 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:386: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:379: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1243: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:887: There were test failures: 296 suites, 1234 tests, 1 error, 14 ignored (8 assumptions)
Total time: 49 minutes 24 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/ibm-j9-jdk6 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure