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/04/25 19:54:33 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/ibm-j9-jdk6) - Build # 5287
- Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/5287/
Java: 32bit/ibm-j9-jdk6
1 tests failed.
FAILED: org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearch
Error Message:
Server at http://127.0.0.1:36119/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:36119/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
at __randomizedtesting.SeedInfo.seed([ABD274DCB644A5C4:2A34FAC4C11BC5F8]: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:197)
at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:89)
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 8777 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.351; org.apache.solr.BaseDistributedSearchTestCase; Setting hostContext system property: /
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.354; org.apache.solr.SolrTestCaseJ4; ###Starting testDistribSearch
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.355; org.apache.solr.cloud.ZkTestServer; STARTING ZK TEST SERVER
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.356; org.apache.solr.cloud.ZkTestServer$ZKServerMain; Starting server
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.456; org.apache.solr.cloud.ZkTestServer; start zk server on port:42513
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.457; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.589; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1b481b48 name:ZooKeeperConnection Watcher:127.0.0.1:42513 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.590; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.590; org.apache.solr.common.cloud.SolrZkClient; makePath: /solr
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.599; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.601; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@724c724c name:ZooKeeperConnection Watcher:127.0.0.1:42513/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.601; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.603; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.611; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/shards
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.619; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.626; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/shards
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.633; org.apache.solr.cloud.AbstractZkTestCase; 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] 1> INFO - 2013-04-25 17:44:18.635; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.647; org.apache.solr.cloud.AbstractZkTestCase; 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] 1> INFO - 2013-04-25 17:44:18.649; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.658; org.apache.solr.cloud.AbstractZkTestCase; 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] 1> INFO - 2013-04-25 17:44:18.660; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.668; org.apache.solr.cloud.AbstractZkTestCase; 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] 1> INFO - 2013-04-25 17:44:18.670; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.678; org.apache.solr.cloud.AbstractZkTestCase; 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] 1> INFO - 2013-04-25 17:44:18.680; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.688; org.apache.solr.cloud.AbstractZkTestCase; 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] 1> INFO - 2013-04-25 17:44:18.690; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.699; org.apache.solr.cloud.AbstractZkTestCase; 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] 1> INFO - 2013-04-25 17:44:18.700; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.709; org.apache.solr.cloud.AbstractZkTestCase; 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] 1> INFO - 2013-04-25 17:44:18.711; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.719; org.apache.solr.cloud.AbstractZkTestCase; 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] 1> INFO - 2013-04-25 17:44:18.721; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.869; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.872; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:45521
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.872; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.873; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.874; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1366911858731
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.874; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1366911858731/solr.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.875; org.apache.solr.core.CoreContainer; New CoreContainer 143460493
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.876; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1366911858731/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.876; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1366911858731/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.930; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.930; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.931; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.932; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.932; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.933; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.934; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.934; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.935; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.936; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.941; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.942; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:42513/solr
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.943; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.944; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.946; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@3e653e65 name:ZooKeeperConnection Watcher:127.0.0.1:42513 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.947; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.952; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.957; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.961; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@13931393 name:ZooKeeperConnection Watcher:127.0.0.1:42513/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.962; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.966; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.977; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/collection-queue-work
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.987; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.994; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45521_
[junit4:junit4] 1> INFO - 2013-04-25 17:44:18.997; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:45521_
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.010; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/election
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.037; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/leader
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.044; org.apache.solr.cloud.Overseer; Overseer (id=89581935549546499-127.0.0.1:45521_-n_0000000000) starting
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.051; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue-work
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.057; org.apache.solr.cloud.OverseerCollectionProcessor; Process current queue of collection creations
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.060; org.apache.solr.common.cloud.SolrZkClient; makePath: /clusterstate.json
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.066; org.apache.solr.common.cloud.SolrZkClient; makePath: /aliases.json
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.071; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.077; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Starting to work on the main queue
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.079; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1366911858731/collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.079; org.apache.solr.cloud.ZkController; Check for collection zkNode:control_collection
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.081; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.081; org.apache.solr.cloud.ZkController; Load collection config from:/collections/control_collection
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.083; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1366911858731/collection1/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.086; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1366911858731/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.087; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1366911858731/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.122; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.162; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.165; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.170; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.553; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.558; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.561; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.589; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.594; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.598; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-25 17:44:19.601; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-25 17:44:19.602; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.603; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-25 17:44:19.606; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-25 17:44:19.607; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.608; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.609; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1366911858731/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/control/data/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.610; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f2b5f2b
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.612; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.613; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/control/data
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.614; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/control/data/index/
[junit4:junit4] 1> WARN - 2013-04-25 17:44:19.616; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.617; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/control/data/index
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.621; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ab60ab6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4bee4bee),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.623; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.627; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.629; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.630; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.632; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.633; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.634; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.636; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.637; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.639; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.642; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.644; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@41be41be main
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.645; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/control/data/tlog
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.646; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.646; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.651; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@41be41be main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.654; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-25 17:44:19.654; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.587; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.589; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:45521",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"1",
[junit4:junit4] 1> "node_name":"127.0.0.1:45521_",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.590; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection control_collection with numShards 1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.591; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.604; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.657; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.658; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:45521 collection:control_collection shard:shard1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.661; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.682; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.691; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.692; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.693; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:45521/collection1/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.694; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.695; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:45521/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.696; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:45521/collection1/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:20.697; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.156; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.180; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.225; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:45521/collection1/ and leader is http://127.0.0.1:45521/collection1/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.226; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:45521
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.227; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.228; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.229; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.234; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.237; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.239; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.241; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.247; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.248; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.250; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@45304530 name:ZooKeeperConnection Watcher:127.0.0.1:42513/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.251; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.254; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.260; org.apache.solr.cloud.ChaosMonkey; monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.403; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.406; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:39283
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.407; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.407; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.408; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1366911862261
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.409; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1366911862261/solr.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.409; org.apache.solr.core.CoreContainer; New CoreContainer 2009429957
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.410; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1366911862261/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.411; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1366911862261/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.451; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.452; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.452; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.453; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.454; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.454; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.455; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.456; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.456; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.457; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.462; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.464; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:42513/solr
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.464; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.465; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.467; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@3afe3afe name:ZooKeeperConnection Watcher:127.0.0.1:42513 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.469; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.473; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.478; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.480; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@56c056c0 name:ZooKeeperConnection Watcher:127.0.0.1:42513/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.481; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:22.490; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.508; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39283_
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.510; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:39283_
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.515; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.517; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.518; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.521; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.528; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1366911862261/collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.528; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.530; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.530; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.532; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1366911862261/collection1/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.534; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1366911862261/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.534; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1366911862261/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.565; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.623; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.626; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.634; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.697; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.698; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:45521",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"1",
[junit4:junit4] 1> "node_name":"127.0.0.1:45521_",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.704; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.704; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:23.704; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.015; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.021; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.024; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.043; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.048; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.052; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-25 17:44:24.054; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-25 17:44:24.055; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.055; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-25 17:44:24.057; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-25 17:44:24.058; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.058; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.059; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1366911862261/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty1/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.059; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f2b5f2b
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.060; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.061; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.061; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty1/index/
[junit4:junit4] 1> WARN - 2013-04-25 17:44:24.062; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.062; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty1/index
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.064; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@71ae71ae lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f6b3f6b),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.065; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.067; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.068; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.069; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.070; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.070; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.071; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.072; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.072; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.073; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.074; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.076; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@33813381 main
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.077; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty1/tlog
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.078; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.078; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.085; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@33813381 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.091; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-25 17:44:24.092; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:25.265; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:25.268; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39283",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"2",
[junit4:junit4] 1> "node_name":"127.0.0.1:39283_",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:25.269; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection collection1 with numShards 2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:25.270; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:25.284; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:25.284; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:25.284; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.096; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.098; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:39283 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.101; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.124; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.132; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.133; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.135; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:39283/collection1/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.136; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.137; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:39283/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.138; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:39283/collection1/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.139; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.799; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.822; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.822; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.822; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.862; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:39283/collection1/ and leader is http://127.0.0.1:39283/collection1/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.863; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39283
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.864; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.865; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.866; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.871; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.874; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.876; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-25 17:44:26.878; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.026; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.028; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:36119
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.029; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.030; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.031; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1366911866889
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.031; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1366911866889/solr.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.032; org.apache.solr.core.CoreContainer; New CoreContainer 534323161
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.033; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1366911866889/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.033; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1366911866889/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.074; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.075; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.076; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.076; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.077; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.078; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.078; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.079; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.080; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.080; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.086; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.087; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:42513/solr
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.088; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.089; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.102; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@692f692f name:ZooKeeperConnection Watcher:127.0.0.1:42513 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.104; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.107; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.115; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.117; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@16411641 name:ZooKeeperConnection Watcher:127.0.0.1:42513/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.118; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:27.128; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.139; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36119_
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.142; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:36119_
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.149; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.149; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.150; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.149; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.153; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.155; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.156; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.163; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1366911866889/collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.164; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.167; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.168; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.173; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1366911866889/collection1/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.175; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1366911866889/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.176; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1366911866889/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.229; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.295; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.299; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.303; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.339; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.340; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39283",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"2",
[junit4:junit4] 1> "node_name":"127.0.0.1:39283_",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.360; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.360; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.360; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.361; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.685; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.690; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.693; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.721; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.729; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.738; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-25 17:44:28.740; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-25 17:44:28.741; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.743; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-25 17:44:28.745; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-25 17:44:28.746; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.748; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.749; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1366911866889/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty2/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.750; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f2b5f2b
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.751; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.753; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.754; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty2/index/
[junit4:junit4] 1> WARN - 2013-04-25 17:44:28.755; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.757; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty2/index
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.760; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@59d259d2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@337d337d),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.762; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.767; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.768; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.770; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.772; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.774; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.775; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.776; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.778; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.779; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.782; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.785; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@2e5a2e5a main
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.785; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty2/tlog
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.786; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.787; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.803; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@2e5a2e5a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.807; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-25 17:44:28.807; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:29.869; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:29.870; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:36119",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"3",
[junit4:junit4] 1> "node_name":"127.0.0.1:36119_",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:29.870; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:29.871; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:29.877; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:29.878; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:29.877; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:29.878; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:30.810; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:30.810; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:36119 collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:30.812; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 1> INFO - 2013-04-25 17:44:30.822; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:30.827; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:30.827; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-04-25 17:44:30.828; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:36119/collection1/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:30.828; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-04-25 17:44:30.829; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:36119/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-04-25 17:44:30.829; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:36119/collection1/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:30.829; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.389; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.415; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.415; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.415; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.415; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.441; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:36119/collection1/ and leader is http://127.0.0.1:36119/collection1/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.442; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:36119
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.443; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.444; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.445; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.450; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.454; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.455; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.457; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.591; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.593; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:54862
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.594; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.595; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.595; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1366911871466
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.596; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1366911871466/solr.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.597; org.apache.solr.core.CoreContainer; New CoreContainer 93062540
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.597; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1366911871466/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.598; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1366911871466/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.663; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.664; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.664; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.665; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.666; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.666; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.667; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.668; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.668; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.669; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.674; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.676; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:42513/solr
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.676; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.677; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.679; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@6df56df5 name:ZooKeeperConnection Watcher:127.0.0.1:42513 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.680; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.683; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.689; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.691; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@5c7b5c7b name:ZooKeeperConnection Watcher:127.0.0.1:42513/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.691; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:31.703; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.713; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54862_
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.717; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:54862_
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.724; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.724; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.725; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.724; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.727; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.730; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.727; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.732; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.734; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.745; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1366911871466/collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.746; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.749; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.750; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.755; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1366911871466/collection1/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.757; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1366911871466/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.758; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1366911871466/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.823; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.856; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.859; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.863; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.933; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.934; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:36119",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"3",
[junit4:junit4] 1> "node_name":"127.0.0.1:36119_",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.941; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.941; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.942; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.941; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:32.941; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.231; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.236; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.239; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.268; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.273; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.277; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-25 17:44:33.280; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-25 17:44:33.280; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.281; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-25 17:44:33.283; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-25 17:44:33.284; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.284; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.285; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1366911871466/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty3/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.285; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f2b5f2b
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.286; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.287; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty3
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.287; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty3/index/
[junit4:junit4] 1> WARN - 2013-04-25 17:44:33.288; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.288; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty3/index
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.290; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@68ee68ee lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b0b7b0b),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.291; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.305; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.306; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.306; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.307; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.308; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.309; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.309; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.310; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.311; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.313; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.315; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1b7b1b7b main
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.316; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty3/tlog
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.317; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.317; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.324; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1b7b1b7b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.330; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-25 17:44:33.331; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:34.450; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:34.451; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54862",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"4",
[junit4:junit4] 1> "node_name":"127.0.0.1:54862_",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:34.452; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:34.452; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:34.459; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:34.459; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:34.459; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:34.459; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:34.459; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.336; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.337; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:54862 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.346; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:54862/collection1/ and leader is http://127.0.0.1:39283/collection1/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.346; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54862
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.347; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.347; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.348; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.348; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.348; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.349; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.350; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.351; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.351; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.352; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.354; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.360; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.503; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.505; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:49813
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.506; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.507; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.507; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1366911875359
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.508; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1366911875359/solr.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.509; org.apache.solr.core.CoreContainer; New CoreContainer 968505786
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.510; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1366911875359/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.510; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1366911875359/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.558; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.559; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.559; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.560; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.561; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.561; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.562; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.563; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.563; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.564; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.572; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.573; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:42513/solr
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.574; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.575; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.577; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@7430743 name:ZooKeeperConnection Watcher:127.0.0.1:42513 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.578; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.582; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.591; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.594; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@50995099 name:ZooKeeperConnection Watcher:127.0.0.1:42513/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.595; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.607; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.969; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.972; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54862",
[junit4:junit4] 1> "state":"recovering",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"4",
[junit4:junit4] 1> "node_name":"127.0.0.1:54862_",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.982; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.982; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.982; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.982; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.982; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:35.982; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.362; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.362; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=4&wt=javabin&nodeName=127.0.0.1:54862_&core=collection1} status=0 QTime=1002
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.617; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49813_
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.619; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:49813_
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.622; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.622; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.623; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.622; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.622; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.623; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.627; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.627; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.628; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.629; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.629; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.631; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.634; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1366911875359/collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.634; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.636; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.636; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.638; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1366911875359/collection1/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.639; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1366911875359/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.640; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1366911875359/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.670; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.704; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.707; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:36.711; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.089; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.094; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.097; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.128; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.137; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.144; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-25 17:44:37.148; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-25 17:44:37.149; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.150; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-25 17:44:37.154; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-25 17:44:37.155; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.156; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.157; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1366911875359/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.159; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f2b5f2b
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.160; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.162; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.163; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4/index/
[junit4:junit4] 1> WARN - 2013-04-25 17:44:37.164; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.165; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4/index
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.170; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4dc44dc4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6e796e79),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.172; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.178; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.179; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.181; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.182; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.183; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.184; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.185; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.185; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.186; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.187; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.189; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@5dd95dd9 main
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.190; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4/tlog
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.191; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.191; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.210; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@5dd95dd9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.213; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.214; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.532; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.535; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:49813",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"5",
[junit4:junit4] 1> "node_name":"127.0.0.1:49813_",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.536; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.537; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.550; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.551; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.550; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.551; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.550; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:37.551; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.216; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.217; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:49813 collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.228; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:49813/collection1/ and leader is http://127.0.0.1:36119/collection1/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.229; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49813
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.230; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.231; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.233; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.234; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.234; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.234; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.236; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.238; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.240; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.240; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.244; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.260; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.263; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.264; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.271; org.apache.solr.core.CoreContainer; Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1366911862261/onenodecollectioncore
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.272; org.apache.solr.cloud.ZkController; Check for collection zkNode:onenodecollection
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.274; org.apache.solr.cloud.ZkController; Creating collection in ZooKeeper:onenodecollection
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.275; org.apache.solr.cloud.ZkController; Looking for collection configName
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.277; org.apache.solr.cloud.ZkController; Only one config set found in zk - using it:conf1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.279; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/onenodecollection
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.282; org.apache.solr.cloud.ZkController; Load collection config from:/collections/onenodecollection
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.285; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1366911862261/onenodecollectioncore/'
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.324; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.364; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:39283/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.365; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:54862 START replicas=[http://127.0.0.1:39283/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-04-25 17:44:38.365; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.366; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.366; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.366; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.367; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.367; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:39283/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.368; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.371; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.379; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.382; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@71ae71ae lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f6b3f6b),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.383; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.385; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@71ae71ae lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f6b3f6b),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@71ae71ae lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f6b3f6b),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.386; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.388; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@7cd07cd realtime
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.388; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.389; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.391; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 12
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.391; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.392; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.394; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.395; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.396; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.397; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.398; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.398; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.399; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.400; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.402; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.404; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty3/index.20130425194438403
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.404; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@71ba71ba lockFactory=org.apache.lucene.store.NativeFSLockFactory@7deb7deb) fullCopy=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.415; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.417; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.418; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.418; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.420; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@68ee68ee lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b0b7b0b),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@68ee68ee lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b0b7b0b),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.421; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.421; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.422; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@37113711 main
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.423; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@37113711 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.424; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty3/index.20130425194438403 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty3/index.20130425194438403;done=true>>]
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.424; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty3/index.20130425194438403
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.425; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty3/index.20130425194438403
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.425; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.426; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.426; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.426; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.428; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.797; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.803; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.807; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.841; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.852; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.864; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-25 17:44:38.869; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-25 17:44:38.871; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.873; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-25 17:44:38.878; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-25 17:44:38.879; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.881; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.883; org.apache.solr.core.SolrCore; [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1366911862261/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1366911858355/onenodecollection/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.885; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f2b5f2b
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.887; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.890; org.apache.solr.core.CachingDirectoryFactory; return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1366911858355/onenodecollection
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.892; org.apache.solr.core.SolrCore; New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1366911858355/onenodecollection/index/
[junit4:junit4] 1> WARN - 2013-04-25 17:44:38.894; org.apache.solr.core.SolrCore; [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1366911858355/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.897; org.apache.solr.core.CachingDirectoryFactory; return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1366911858355/onenodecollection/index
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.902; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7fbc7fbc lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a164a16),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.903; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.907; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.907; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.908; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.909; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.911; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.911; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.912; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.913; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.914; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.916; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.919; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@4c744c74 main
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.919; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1366911858355/onenodecollection/tlog
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.921; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.921; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.932; org.apache.solr.core.SolrCore; [onenodecollectioncore] Registered new searcher Searcher@4c744c74 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:38.937; org.apache.solr.cloud.ZkController; publishing core=onenodecollectioncore state=down
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.090; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.094; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:49813",
[junit4:junit4] 1> "state":"recovering",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"5",
[junit4:junit4] 1> "node_name":"127.0.0.1:49813_",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.106; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54862",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"4",
[junit4:junit4] 1> "node_name":"127.0.0.1:54862_",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.117; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39283",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:39283_",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":"none",
[junit4:junit4] 1> "collection":"onenodecollection",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "core":"onenodecollectioncore"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.119; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection onenodecollection with numShards 1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.120; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.129; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.129; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.129; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.129; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.130; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.129; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.263; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.265; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=5&wt=javabin&nodeName=127.0.0.1:49813_&core=collection1} status=0 QTime=1005
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.941; org.apache.solr.core.CoreContainer; registering core: onenodecollectioncore
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.942; org.apache.solr.cloud.ZkController; Register replica - core:onenodecollectioncore address:http://127.0.0.1:39283 collection:onenodecollection shard:shard1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.944; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.959; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.965; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.966; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.966; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:39283/onenodecollectioncore/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.967; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.968; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:39283/onenodecollectioncore/ has no replicas
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.969; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:39283/onenodecollectioncore/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:39.970; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.649; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.689; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.690; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.689; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.689; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.690; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.689; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.745; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:39283/onenodecollectioncore/ and leader is http://127.0.0.1:39283/onenodecollectioncore/
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.746; org.apache.solr.cloud.ZkController; No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:39283
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.748; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.749; org.apache.solr.cloud.ZkController; publishing core=onenodecollectioncore state=active
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.755; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.758; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1366911858355/onenodecollection&action=CREATE&version=2&numShards=1&name=onenodecollectioncore&wt=javabin&roles=none&collection=onenodecollection} status=0 QTime=2487
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.760; org.apache.solr.cloud.AbstractDistribZkTestBase; Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4] 1> INFO - 2013-04-25 17:44:40.762; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.267; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:36119/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.268; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:49813 START replicas=[http://127.0.0.1:36119/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-04-25 17:44:41.269; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.270; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.271; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.272; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.273; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.273; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:36119/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.274; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.332; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.336; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.338; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@59d259d2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@337d337d),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.339; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.340; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@59d259d2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@337d337d),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@59d259d2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@337d337d),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.341; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.342; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@30a730a7 realtime
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.343; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.344; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 8
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.345; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.345; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.347; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.348; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.350; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.350; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.351; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.353; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.354; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.355; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4/index.20130425194441355
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.356; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@a240a24 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a124a12) fullCopy=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.359; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.360; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.362; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.363; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.365; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4dc44dc4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6e796e79),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4dc44dc4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6e796e79),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.366; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.367; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.368; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@6fb16fb1 main
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.370; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@6fb16fb1 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.372; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4/index.20130425194441355 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4/index.20130425194441355;done=true>>]
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.373; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4/index.20130425194441355
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.374; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4/index.20130425194441355
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.374; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.375; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.376; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.377; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.380; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-04-25 17:44:41.767; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.218; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.221; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39283",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:39283__onenodecollectioncore",
[junit4:junit4] 1> "node_name":"127.0.0.1:39283_",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":"none",
[junit4:junit4] 1> "collection":"onenodecollection",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"onenodecollectioncore"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.233; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:49813",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"5",
[junit4:junit4] 1> "node_name":"127.0.0.1:49813_",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.245; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.246; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.246; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.245; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.246; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.245; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.772; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.775; org.apache.solr.cloud.AbstractDistribZkTestBase; Recoveries finished - collection: onenodecollection
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.776; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.792; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.794; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@51665166 name:ZooKeeperConnection Watcher:127.0.0.1:42513 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.795; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[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":"89581935549546499-127.0.0.1:45521_-n_0000000000"}
[junit4:junit4] 1> /solr/overseer_elect/election (5)
[junit4:junit4] 1> /solr/overseer_elect/election/89581935549546508-127.0.0.1:49813_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89581935549546502-127.0.0.1:39283_-n_0000000001 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89581935549546499-127.0.0.1:45521_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89581935549546504-127.0.0.1:36119_-n_0000000002 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89581935549546506-127.0.0.1:54862_-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections (3)
[junit4:junit4] 1> /solr/collections/control_collection (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election/89581935549546499-1-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/control_collection/leaders (1)
[junit4:junit4] 1> /solr/collections/control_collection/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "base_url":"http://127.0.0.1:45521",
[junit4:junit4] 1> "node_name":"127.0.0.1:45521_",
[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/89581935549546506-4-n_0000000001 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89581935549546502-2-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard2 (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard2/election (2)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard2/election/89581935549546504-3-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard2/election/89581935549546508-5-n_0000000001 (0)
[junit4:junit4] 1> /solr/collections/collection1/leaders (2)
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39283",
[junit4:junit4] 1> "node_name":"127.0.0.1:39283_",
[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:36119",
[junit4:junit4] 1> "node_name":"127.0.0.1:36119_",
[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/89581935549546502-127.0.0.1:39283__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:39283",
[junit4:junit4] 1> "node_name":"127.0.0.1:39283_",
[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:45521_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:39283_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:36119_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:49813_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:54862_ (0)
[junit4:junit4] 1> /solr/clusterstate.json (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "control_collection":{
[junit4:junit4] 1> "shards":{"shard1":{
[junit4:junit4] 1> "range":"80000000-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{"1":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:45521",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:45521_",
[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:39283__onenodecollectioncore":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39283",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:39283_",
[junit4:junit4] 1> "roles":"none",
[junit4:junit4] 1> "collection":"onenodecollection",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"onenodecollectioncore",
[junit4:junit4] 1> "leader":"true"}}}},
[junit4:junit4] 1> "router":"compositeId"},
[junit4:junit4] 1> "collection1":{
[junit4:junit4] 1> "shards":{
[junit4:junit4] 1> "shard1":{
[junit4:junit4] 1> "range":"80000000-ffffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{
[junit4:junit4] 1> "2":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39283",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:39283_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"},
[junit4:junit4] 1> "4":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54862",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:54862_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1"}}},
[junit4:junit4] 1> "shard2":{
[junit4:junit4] 1> "range":"0-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{
[junit4:junit4] 1> "3":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:36119",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:36119_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"},
[junit4:junit4] 1> "5":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:49813",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:49813_",
[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] 1> INFO - 2013-04-25 17:44:42.916; org.apache.solr.cloud.ChaosMonkey; monkey: stop shard! 45521
[junit4:junit4] 1> INFO - 2013-04-25 17:44:42.918; org.apache.solr.core.CoreContainer; Shutting down CoreContainer instance=143460493
[junit4:junit4] 1> INFO - 2013-04-25 17:44:43.768; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:43.771; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=null message={
[junit4:junit4] 1> "base_url":"http://127.0.0.1:45521",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"1",
[junit4:junit4] 1> "node_name":"127.0.0.1:45521_",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:43.786; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:43.786; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:43.786; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:43.787; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:43.786; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.921; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.922; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.940; org.apache.solr.core.SolrCore; [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@59625962
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.947; org.apache.solr.update.DirectUpdateHandler2; 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] 1> INFO - 2013-04-25 17:44:44.950; org.apache.solr.update.SolrCoreState; Closing SolrCoreState
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.951; org.apache.solr.update.DefaultSolrCoreState; SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.952; org.apache.solr.update.DefaultSolrCoreState; closing IndexWriter with IndexWriterCloser
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.954; org.apache.solr.core.SolrCore; [collection1] Closing main searcher on request.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.955; org.apache.solr.core.CachingDirectoryFactory; Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.957; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/control/data [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/control/data;done=false>>]
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.958; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/control/data
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.959; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/control/data/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/control/data/index;done=false>>]
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.963; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/control/data/index
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.966; org.apache.solr.cloud.Overseer$ClusterStateUpdater; According to ZK I (id=89581935549546499-127.0.0.1:45521_-n_0000000000) am no longer a leader.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.967; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.969; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.970; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> WARN - 2013-04-25 17:44:44.970; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.972; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> WARN - 2013-04-25 17:44:44.973; org.apache.solr.common.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.969; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.994; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.996; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/leader
[junit4:junit4] 1> INFO - 2013-04-25 17:44:44.998; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:45.002; org.apache.solr.cloud.Overseer; Overseer (id=89581935549546502-127.0.0.1:39283_-n_0000000001) starting
[junit4:junit4] 1> INFO - 2013-04-25 17:44:45.004; org.eclipse.jetty.server.handler.ContextHandler; stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:45.014; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:45.014; org.apache.solr.cloud.OverseerCollectionProcessor; Process current queue of collection creations
[junit4:junit4] 1> INFO - 2013-04-25 17:44:45.015; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Starting to work on the main queue
[junit4:junit4] 1> INFO - 2013-04-25 17:44:45.019; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:45.021; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:45.023; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:45521",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"1",
[junit4:junit4] 1> "node_name":"127.0.0.1:45521_",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:45.056; org.apache.solr.cloud.ChaosMonkey; monkey: stop shard! 39283
[junit4:junit4] 1> INFO - 2013-04-25 17:44:45.057; org.apache.solr.core.CoreContainer; Shutting down CoreContainer instance=2009429957
[junit4:junit4] 1> INFO - 2013-04-25 17:44:45.129; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:45.130; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:45.129; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:45.129; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:46.641; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-25 17:44:46.644; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=null message={
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39283",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:39283__onenodecollectioncore",
[junit4:junit4] 1> "node_name":"127.0.0.1:39283_",
[junit4:junit4] 1> "roles":"none",
[junit4:junit4] 1> "collection":"onenodecollection",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"onenodecollectioncore"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:46.657; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=null message={
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39283",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"2",
[junit4:junit4] 1> "node_name":"127.0.0.1:39283_",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:46.699; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:46.699; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:46.699; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:46.699; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:48.133; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-25 17:44:48.134; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:48.138; org.apache.solr.cloud.ZkController; publishing core=onenodecollectioncore state=down
[junit4:junit4] 1> INFO - 2013-04-25 17:44:48.141; org.apache.solr.core.SolrCore; [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@4b494b49
[junit4:junit4] 1> INFO - 2013-04-25 17:44:48.150; org.apache.solr.update.DirectUpdateHandler2; 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] 1> INFO - 2013-04-25 17:44:48.151; org.apache.solr.update.SolrCoreState; Closing SolrCoreState
[junit4:junit4] 1> INFO - 2013-04-25 17:44:48.152; org.apache.solr.update.DefaultSolrCoreState; SolrCoreState ref count has
[...truncated too long message...]
ection1",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:50.551; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (1)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:50.552; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> WARN - 2013-04-25 17:44:50.605; org.apache.solr.common.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-04-25 17:44:50.606; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> WARN - 2013-04-25 17:44:50.607; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.521; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.523; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.530; org.apache.solr.core.SolrCore; [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@7a9f7a9f
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.544; org.apache.solr.update.DirectUpdateHandler2; 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] 1> INFO - 2013-04-25 17:44:51.545; org.apache.solr.update.SolrCoreState; Closing SolrCoreState
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.546; org.apache.solr.update.DefaultSolrCoreState; SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.546; org.apache.solr.update.DefaultSolrCoreState; closing IndexWriter with IndexWriterCloser
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.547; org.apache.solr.core.SolrCore; [collection1] Closing main searcher on request.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.548; org.apache.solr.core.CachingDirectoryFactory; Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.549; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4;done=false>>]
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.549; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.550; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4/index;done=false>>]
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.550; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1366911858355/jetty4/index
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.551; org.apache.solr.cloud.Overseer$ClusterStateUpdater; According to ZK I (id=89581935549546508-127.0.0.1:49813_-n_0000000004) am no longer a leader.
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.553; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> WARN - 2013-04-25 17:44:51.554; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-04-25 17:44:51.555; org.apache.solr.common.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.574; org.eclipse.jetty.server.handler.ContextHandler; stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.637; org.apache.solr.SolrTestCaseJ4; ###Ending testDistribSearch
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.639; org.apache.solr.cloud.ZkTestServer; connecting to 127.0.0.1:42513 42513
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1366911858355
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=BasicDistributedZk2Test -Dtests.method=testDistribSearch -Dtests.seed=ABD274DCB644A5C4 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ja -Dtests.timezone=Poland -Dtests.file.encoding=US-ASCII
[junit4:junit4] ERROR 33.3s J1 | BasicDistributedZk2Test.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:36119/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([ABD274DCB644A5C4:2A34FAC4C11BC5F8]: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:197)
[junit4:junit4] > at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:89)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:738)
[junit4:junit4] 1> INFO - 2013-04-25 17:44:51.672; org.apache.solr.SolrTestCaseJ4; ###deleteCore
[junit4:junit4] 2> 33332 T2139 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=ja, timezone=Poland
[junit4:junit4] 2> NOTE: Linux 3.2.0-40-generic x86/IBM Corporation 1.6.0 (32-bit)/cpus=8,threads=2,free=10063552,total=75888128
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestFieldTypeCollectionResource, TestFieldTypeResource, NoCacheHeaderTest, TestCollationField, PingRequestHandlerTest, HighlighterTest, SignatureUpdateProcessorFactoryTest, TestIndexingPerformance, SuggesterTSTTest, ZkSolrClientTest, TestRecovery, TestRTGBase, AliasIntegrationTest, OpenExchangeRatesOrgProviderTest, OpenCloseCoreStressTest, RequestHandlersTest, TestCodecSupport, MultiTermTest, BasicZkTest, XsltUpdateRequestHandlerTest, PathHierarchyTokenizerFactoryTest, TestStressReorder, DirectSolrSpellCheckerTest, TestZkChroot, NumericFieldsTest, TestSolrXml, TestIndexSearcher, StandardRequestHandlerTest, ShardRoutingCustomTest, DocumentAnalysisRequestHandlerTest, DateMathParserTest, TestMultiCoreConfBootstrap, SolrCmdDistributorTest, TestFiltering, TestQuerySenderNoQuery, TestSchemaVersionResource, TestUpdate, DistanceFunctionTest, HighlighterConfigTest, XmlUpdateRequestHandlerTest, HardAutoCommitTest, TestAnalyzedSuggestions, SolrIndexConfigTest, TestLMJelinekMercerSimilarityFactory, SolrRequestParserTest, TestSolr4Spatial, TestComponentsName, FieldAnalysisRequestHandlerTest, TestNumberUtils, TimeZoneUtilsTest, TestLuceneMatchVersion, TestReload, ChaosMonkeyShardSplitTest, DisMaxRequestHandlerTest, TestSchemaNameResource, TestMergePolicyConfig, CoreContainerCoreInitFailuresTest, SimplePostToolTest, SolrCoreCheckLockOnStartupTest, FileUtilsTest, TestLazyCores, DocValuesMultiTest, TestWordDelimiterFilterFactory, NotRequiredUniqueKeyTest, ShardSplitTest, TestFoldingMultitermQuery, UniqFieldsUpdateProcessorFactoryTest, FullSolrCloudDistribCmdsTest, URLClassifyProcessorTest, TestCSVResponseWriter, BasicDistributedZk2Test]
[junit4:junit4] Completed on J1 in 33.86s, 1 test, 1 error <<< FAILURES!
[...truncated 454 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:384: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:377: 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: 294 suites, 1221 tests, 1 error, 14 ignored (8 assumptions)
Total time: 45 minutes 58 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/ibm-j9-jdk6
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure