You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/04/30 08:32:53 UTC
[JENKINS] Lucene-Solr-NightlyTests-trunk - Build # 250 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-trunk/250/
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:56934/collection1lastClient and got 5 from http://127.0.0.1:36809/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:56934/collection1lastClient and got 5 from http://127.0.0.1:36809/collection1
at __randomizedtesting.SeedInfo.seed([64A93AFD9173B7C3:E54FB4E5E62CD7FF]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
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:722)
Build Log:
[...truncated 9206 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 1> INFO - 2013-04-30 05:50:33.553; org.apache.solr.BaseDistributedSearchTestCase; Setting hostContext system property: /
[junit4:junit4] 1> INFO - 2013-04-30 05:50:33.559; org.apache.solr.SolrTestCaseJ4; ###Starting testDistribSearch
[junit4:junit4] 1> INFO - 2013-04-30 05:50:33.568; 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-30 05:50:33.584; org.apache.solr.cloud.ZkTestServer$ZKServerMain; Starting server
[junit4:junit4] 1> INFO - 2013-04-30 05:50:33.885; org.apache.solr.cloud.ZkTestServer; start zk server on port:26789
[junit4:junit4] 1> INFO - 2013-04-30 05:50:34.170; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> WARN - 2013-04-30 05:50:34.235; org.apache.zookeeper.server.NIOServerCnxn; Exception causing close of session 0x0 due to java.io.IOException: ZooKeeperServer not running
[junit4:junit4] 1> INFO - 2013-04-30 05:50:35.640; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1028b46a name:ZooKeeperConnection Watcher:127.0.0.1:26789 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:35.641; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:35.642; org.apache.solr.common.cloud.SolrZkClient; makePath: /solr
[junit4:junit4] 1> INFO - 2013-04-30 05:50:35.774; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:35.786; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@33b7a9c5 name:ZooKeeperConnection Watcher:127.0.0.1:26789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:35.787; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:35.787; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:35.794; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/shards
[junit4:junit4] 1> INFO - 2013-04-30 05:50:35.799; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection
[junit4:junit4] 1> INFO - 2013-04-30 05:50:35.803; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/shards
[junit4:junit4] 1> INFO - 2013-04-30 05:50:35.815; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:35.816; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:35.844; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:35.849; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.014; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.015; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.044; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.045; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.050; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.051; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.057; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/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-30 05:50:36.058; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.064; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.066; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.072; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.073; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.084; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.085; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.539; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.549; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:?????
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.550; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.551; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.551; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1367301036100
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.552; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1367301036100/solr.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.552; org.apache.solr.core.CoreContainer; New CoreContainer 1652541267
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.553; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1367301036100/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.554; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1367301036100/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.740; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.740; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.741; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.741; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.742; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.742; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.743; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.743; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.744; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.744; 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-30 05:50:36.869; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.870; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:26789/solr
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.896; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.898; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.901; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@3b723e name:ZooKeeperConnection Watcher:127.0.0.1:26789 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.902; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.921; 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-30 05:50:36.942; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.945; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@aa9eec9 name:ZooKeeperConnection Watcher:127.0.0.1:26789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.945; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.953; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.968; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/collection-queue-work
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.983; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.987; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58802_
[junit4:junit4] 1> INFO - 2013-04-30 05:50:36.995; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:58802_
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.000; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/election
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.031; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/leader
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.035; org.apache.solr.cloud.Overseer; Overseer (id=89607440568549379-127.0.0.1:58802_-n_0000000000) starting
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.051; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue-work
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.062; org.apache.solr.cloud.OverseerCollectionProcessor; Process current queue of collection creations
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.064; org.apache.solr.common.cloud.SolrZkClient; makePath: /clusterstate.json
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.067; org.apache.solr.common.cloud.SolrZkClient; makePath: /aliases.json
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.071; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.092; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Starting to work on the main queue
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.103; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1367301036100/collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.104; org.apache.solr.cloud.ZkController; Check for collection zkNode:control_collection
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.105; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.105; org.apache.solr.cloud.ZkController; Load collection config from:/collections/control_collection
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.108; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1367301036100/collection1/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.109; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1367301036100/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.110; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1367301036100/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.193; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.265; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.367; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.378; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-30 05:50:37.999; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.012; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.016; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.044; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.050; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.055; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 05:50:38.057; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 05:50:38.057; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.057; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 05:50:38.059; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 05:50:38.059; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.060; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.093; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1367301036100/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1367301033559/control/data/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.094; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@792de7f
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.094; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.096; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/control/data
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.097; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1367301033559/control/data/index/
[junit4:junit4] 1> WARN - 2013-04-30 05:50:38.097; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1367301033559/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.098; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/control/data/index
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.113; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@30a0630e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.114; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.117; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.117; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.118; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.118; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.119; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.119; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.120; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.120; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.121; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.134; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.142; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@6c821104 main
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.143; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.144; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.147; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@6c821104 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.149; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.149; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.598; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.600; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:58802_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:58802"}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.600; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection control_collection with numShards 1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.609; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:38.634; 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-30 05:50:39.154; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:39.154; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:58802 collection:control_collection shard:shard1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:39.164; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:39.183; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-04-30 05:50:39.215; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:39.231; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:39.231; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-04-30 05:50:39.236; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:58802/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:39.237; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-04-30 05:50:39.237; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:58802/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-04-30 05:50:39.237; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:58802/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:39.238; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.141; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.187; 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-30 05:50:40.225; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:58802/collection1/ and leader is http://127.0.0.1:58802/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.225; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58802
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.225; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.226; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.226; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.228; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.229; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.230; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.231; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.245; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.252; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.254; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@7a688e8c name:ZooKeeperConnection Watcher:127.0.0.1:26789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.254; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.256; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.262; org.apache.solr.cloud.ChaosMonkey; monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.478; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.481; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:?????
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.482; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.483; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.483; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1367301040262
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.484; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1367301040262/solr.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.484; org.apache.solr.core.CoreContainer; New CoreContainer 2109314504
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.485; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1367301040262/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.485; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1367301040262/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.603; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.604; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.604; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.605; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.605; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.606; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.606; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.607; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.607; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.608; 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-30 05:50:40.625; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.626; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:26789/solr
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.626; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.627; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.631; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@4f767231 name:ZooKeeperConnection Watcher:127.0.0.1:26789 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.631; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.646; 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-30 05:50:40.658; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.660; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@6ab69860 name:ZooKeeperConnection Watcher:127.0.0.1:26789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.661; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:40.673; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.679; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38044_
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.714; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:38044_
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.716; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.717; 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-30 05:50:41.718; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:58802__collection1",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:58802_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:58802"}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.719; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.719; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.736; 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-30 05:50:41.736; 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-30 05:50:41.741; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1367301040262/collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.741; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.742; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.742; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.743; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.743; 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-30 05:50:41.744; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1367301040262/collection1/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.746; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1367301040262/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.746; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1367301040262/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.798; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.856; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.958; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:41.968; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.577; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.587; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.590; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.619; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.623; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.626; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 05:50:42.627; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 05:50:42.640; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.641; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 05:50:42.642; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 05:50:42.642; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.643; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.643; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1367301040262/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty1/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.643; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@792de7f
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.644; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.645; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.645; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty1/index/
[junit4:junit4] 1> WARN - 2013-04-30 05:50:42.646; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.647; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty1/index
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.653; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@709cb796; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.653; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.656; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.656; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.657; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.657; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.658; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.658; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.659; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.659; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.659; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.670; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.681; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@7236385d main
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.681; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.682; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.686; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@7236385d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.688; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-30 05:50:42.688; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.243; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.244; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:38044_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:38044"}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.244; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection collection1 with numShards 1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.244; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.266; 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-30 05:50:43.266; 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-30 05:50:43.266; 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-30 05:50:43.703; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.703; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:38044 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.705; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.740; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.777; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.778; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.778; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:38044/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.779; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.780; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:38044/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.780; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:38044/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:43.780; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:44.785; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:44.813; 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-30 05:50:44.813; 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-30 05:50:44.813; 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-30 05:50:44.848; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:38044/collection1/ and leader is http://127.0.0.1:38044/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:44.848; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38044
[junit4:junit4] 1> INFO - 2013-04-30 05:50:44.848; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-04-30 05:50:44.849; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-30 05:50:44.849; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:50:44.852; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:44.857; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:44.857; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-30 05:50:44.858; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.226; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.230; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:?????
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.231; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.231; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.232; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1367301044874
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.232; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1367301044874/solr.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.233; org.apache.solr.core.CoreContainer; New CoreContainer 290847925
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.233; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1367301044874/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.234; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1367301044874/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.349; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.349; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.350; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.350; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.351; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.351; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.352; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.352; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.353; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.353; 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-30 05:50:45.371; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.372; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:26789/solr
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.373; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.374; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.378; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@6afd7a6c name:ZooKeeperConnection Watcher:127.0.0.1:26789 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.379; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.392; 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-30 05:50:45.407; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.409; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@24c360d5 name:ZooKeeperConnection Watcher:127.0.0.1:26789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.410; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:45.423; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.329; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.330; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:38044__collection1",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:38044_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:38044"}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.374; 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-30 05:50:46.374; 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-30 05:50:46.374; 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-30 05:50:46.374; 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-30 05:50:46.429; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:28405_
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.432; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:28405_
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.435; 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-30 05:50:46.435; 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-30 05:50:46.436; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.435; 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-30 05:50:46.436; 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-30 05:50:46.438; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.438; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.439; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.446; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1367301044874/collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.447; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.448; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.448; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.450; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1367301044874/collection1/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.451; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1367301044874/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.452; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1367301044874/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.512; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.594; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.696; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:46.706; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.398; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.410; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.414; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.460; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.468; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.475; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 05:50:47.477; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 05:50:47.478; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.478; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 05:50:47.480; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 05:50:47.480; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.481; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.481; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1367301044874/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty2/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.482; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@792de7f
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.482; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.484; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty2
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.485; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty2/index/
[junit4:junit4] 1> WARN - 2013-04-30 05:50:47.486; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.487; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty2/index
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.495; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@79f6112f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.496; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.500; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.501; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.502; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.503; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.503; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.504; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.504; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.505; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.506; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.524; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.536; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@5ad7f954 main
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.538; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.538; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.543; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@5ad7f954 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.545; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.545; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.882; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.883; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:28405_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:28405"}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.883; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.883; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:47.891; 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-30 05:50:47.891; 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-30 05:50:47.891; 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-30 05:50:47.891; 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-30 05:50:48.548; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.548; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:28405 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.557; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:28405/collection1/ and leader is http://127.0.0.1:38044/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.557; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:28405
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.557; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.557; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.562; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.563; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.563; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.564; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.564; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.565; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.566; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.566; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.566; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.590; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:28405__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.818; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.821; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:?????
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.822; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.823; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.823; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1367301048581
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.824; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1367301048581/solr.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.824; org.apache.solr.core.CoreContainer; New CoreContainer 564577610
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.825; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1367301048581/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.825; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1367301048581/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.939; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.940; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.941; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.941; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.942; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.942; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.943; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.943; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.944; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.944; 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-30 05:50:48.961; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.962; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:26789/solr
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.962; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.963; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.967; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@7ba65fa3 name:ZooKeeperConnection Watcher:127.0.0.1:26789 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:48.967; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:49.040; 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-30 05:50:49.052; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:49.060; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@65bb3aac name:ZooKeeperConnection Watcher:127.0.0.1:26789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:49.061; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:49.069; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:49.405; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:49.407; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:28405__collection1",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"recovering",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:28405_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:28405"}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:49.427; 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-30 05:50:49.427; 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-30 05:50:49.427; 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-30 05:50:49.427; 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-30 05:50:49.427; 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-30 05:50:49.591; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 127.0.0.1:28405__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:49.591; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:28405__collection1&state=recovering&nodeName=127.0.0.1:28405_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.075; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55191_
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.103; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:55191_
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.106; 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-30 05:50:50.107; 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-30 05:50:50.106; 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-30 05:50:50.113; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.113; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.113; 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-30 05:50:50.114; 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-30 05:50:50.115; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.115; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.117; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.123; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1367301048581/collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.123; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.124; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.124; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.126; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1367301048581/collection1/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.128; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1367301048581/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.129; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1367301048581/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.186; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.245; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.347; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:50.356; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.023; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.036; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.041; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.066; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.074; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.080; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 05:50:51.082; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 05:50:51.082; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.083; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 05:50:51.085; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 05:50:51.085; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.085; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.086; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1367301048581/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty3/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.086; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@792de7f
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.087; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.088; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty3
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.089; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty3/index/
[junit4:junit4] 1> WARN - 2013-04-30 05:50:51.090; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.091; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty3/index
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.099; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@211a539c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.100; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.103; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.103; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.104; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.105; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.105; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.106; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.106; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.107; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.107; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.120; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.128; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@72180703 main
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.129; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.130; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.134; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@72180703 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.136; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.136; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.594; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:38044/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.603; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.619; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:28405 START replicas=[http://127.0.0.1:38044/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-04-30 05:50:51.626; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.627; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.627; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.627; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.627; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.628; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:38044/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.628; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.663; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.673; 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-30 05:50:51.677; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@709cb796; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.677; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.681; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@709cb796; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@709cb796; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.681; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.682; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@232416dc realtime
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.682; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.683; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 22
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.684; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.684; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.711; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.775; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.776; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=56
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.778; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.778; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.778; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.782; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.783; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.785; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty2/index.20130430145051784
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.785; org.apache.solr.handler.SnapPuller; Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty2/index.20130430145051784 lockFactory=org.apache.lucene.store.NativeFSLockFactory@14e195c4; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.796; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=3
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.803; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.811; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.812; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.816; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@79f6112f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@79f6112f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.817; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.817; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.818; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@5a936d58 main
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.819; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@5a936d58 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.820; org.apache.solr.core.CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty2/index.20130430145051784 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty2/index.20130430145051784;done=true>>]
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.820; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty2/index.20130430145051784
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.820; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty2/index.20130430145051784
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.822; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.822; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.822; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.822; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:50:51.824; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:52.437; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:52.439; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:55191_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:55191"}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:52.439; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:52.439; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:52.444; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:28405__collection1",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:28405_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:28405"}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:52.463; 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-30 05:50:52.463; 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-30 05:50:52.463; 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-30 05:50:52.463; 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-30 05:50:52.463; 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-30 05:50:53.141; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.141; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:55191 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.172; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:55191/collection1/ and leader is http://127.0.0.1:38044/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.172; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55191
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.172; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.173; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.173; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.174; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.174; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.175; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.175; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.176; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.176; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.177; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.177; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.197; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:55191__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.413; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.417; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:?????
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.417; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.418; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.419; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1367301053195
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.419; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1367301053195/solr.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.420; org.apache.solr.core.CoreContainer; New CoreContainer 1033487281
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.420; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1367301053195/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.421; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1367301053195/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.534; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.535; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.535; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.536; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.536; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.537; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.537; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.538; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.538; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.539; 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-30 05:50:53.554; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.555; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:26789/solr
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.555; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.557; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.560; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@a2ab120 name:ZooKeeperConnection Watcher:127.0.0.1:26789 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.561; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.575; 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-30 05:50:53.588; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.590; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@78f37e47 name:ZooKeeperConnection Watcher:127.0.0.1:26789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.591; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.601; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.977; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:53.978; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:55191__collection1",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"recovering",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:55191_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:55191"}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.005; 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-30 05:50:54.005; 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-30 05:50:54.005; 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-30 05:50:54.005; 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-30 05:50:54.005; 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-30 05:50:54.005; 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-30 05:50:54.199; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 127.0.0.1:55191__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.199; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:55191__collection1&state=recovering&nodeName=127.0.0.1:55191_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.607; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40131_
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.635; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:40131_
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.639; 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-30 05:50:54.639; 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-30 05:50:54.640; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.640; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.640; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.639; 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-30 05:50:54.641; 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-30 05:50:54.640; 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-30 05:50:54.640; 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-30 05:50:54.642; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.642; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.644; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.651; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1367301053195/collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.651; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.652; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.652; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.654; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1367301053195/collection1/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.656; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1367301053195/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.656; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1367301053195/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.707; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.767; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.869; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:54.878; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.484; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.498; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.502; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.528; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.534; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.540; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 05:50:55.541; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 05:50:55.542; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.542; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 05:50:55.544; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 05:50:55.544; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.544; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.545; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1367301053195/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty4/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.545; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@792de7f
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.546; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.546; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty4
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.547; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty4/index/
[junit4:junit4] 1> WARN - 2013-04-30 05:50:55.548; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.548; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty4/index
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.554; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5acfda6b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.555; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.558; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.558; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.559; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.559; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.560; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.560; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.561; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.561; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.562; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.573; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.581; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@6f33ea4f main
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.582; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.582; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.587; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@6f33ea4f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.589; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-30 05:50:55.589; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.201; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:38044/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.201; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:55191 START replicas=[http://127.0.0.1:38044/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-04-30 05:50:56.202; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.203; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.203; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.204; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.204; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.204; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:38044/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.204; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.207; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.236; 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-30 05:50:56.269; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@709cb796; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@709cb796; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.270; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.272; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.273; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 38
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.274; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.275; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.279; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.280; org.apache.solr.handler.SnapPuller; Master's generation: 3
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.280; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.281; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.284; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.286; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.287; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty3/index.20130430145056286
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.288; org.apache.solr.handler.SnapPuller; Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty3/index.20130430145056286 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d42bcd4; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.292; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.294; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.297; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.297; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.302; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@211a539c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@211a539c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.302; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.303; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.304; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@60d3668d main
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.305; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@60d3668d main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.306; org.apache.solr.core.CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty3/index.20130430145056286 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty3/index.20130430145056286;done=true>>]
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.306; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty3/index.20130430145056286
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.306; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty3/index.20130430145056286
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.307; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.307; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.308; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.308; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:50:56.310; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.016; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.017; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:40131_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40131"}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.017; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.017; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.048; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:55191__collection1",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:55191_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:55191"}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.061; 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-30 05:50:57.061; 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-30 05:50:57.061; 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-30 05:50:57.061; 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-30 05:50:57.061; 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-30 05:50:57.061; 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-30 05:50:57.593; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.593; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:40131 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.603; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:40131/collection1/ and leader is http://127.0.0.1:38044/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.604; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40131
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.604; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.604; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.605; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.605; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.605; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.606; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.606; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.607; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.607; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.608; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.609; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.626; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:40131__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.906; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.909; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:?????
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.910; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.911; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.911; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1367301057622
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.911; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1367301057622/solr.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.912; org.apache.solr.core.CoreContainer; New CoreContainer 1976359670
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.912; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1367301057622/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:57.912; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1367301057622/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.005; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.005; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.006; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.006; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.006; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.007; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.007; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.007; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.008; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.008; 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-30 05:50:58.019; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.019; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:26789/solr
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.020; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.020; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.024; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@568ee2b9 name:ZooKeeperConnection Watcher:127.0.0.1:26789 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.024; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.035; 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-30 05:50:58.047; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.050; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@33227ea8 name:ZooKeeperConnection Watcher:127.0.0.1:26789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.050; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.056; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.576; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.577; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:40131__collection1",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"recovering",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:40131_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40131"}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.598; 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-30 05:50:58.598; 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-30 05:50:58.598; 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-30 05:50:58.598; 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-30 05:50:58.598; 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-30 05:50:58.598; 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-30 05:50:58.598; 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-30 05:50:58.627; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 127.0.0.1:40131__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:58.627; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:40131__collection1&state=recovering&nodeName=127.0.0.1:40131_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.061; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56934_
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.063; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:56934_
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.090; 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-30 05:50:59.090; 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-30 05:50:59.090; 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-30 05:50:59.090; 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-30 05:50:59.091; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (6)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.090; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (6)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.090; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (6)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.092; 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: 6)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.091; 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: 6)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.092; 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: 6)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.093; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (6)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.093; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (6)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.093; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (6)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.095; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (6)
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.101; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1367301057622/collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.101; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.102; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.102; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.104; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1367301057622/collection1/'
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.105; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty5-1367301057622/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.106; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty5-1367301057622/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.146; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.193; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.295; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.302; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.839; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.851; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.855; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.879; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.884; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.888; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 05:50:59.889; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 05:50:59.890; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.890; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 05:50:59.891; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 05:50:59.892; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.892; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.892; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1367301057622/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty5/
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.892; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@792de7f
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.893; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.893; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty5
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.894; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty5/index/
[junit4:junit4] 1> WARN - 2013-04-30 05:50:59.894; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.895; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty5/index
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.926; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty5/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d73f773; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.927; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.929; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.929; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.930; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.931; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.931; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.931; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.932; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.932; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.932; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.942; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.948; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@6807f00 main
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.949; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.949; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.952; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@6807f00 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.954; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-30 05:50:59.954; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.107; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.108; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:56934_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:56934"}
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.109; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.109; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.116; 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: 6)
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.117; 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: 6)
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.117; 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: 6)
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.117; 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: 6)
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.117; 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: 6)
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.117; 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: 6)
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.116; 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: 6)
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.629; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:38044/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.629; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:40131 START replicas=[http://127.0.0.1:38044/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-04-30 05:51:00.630; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.630; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.630; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.630; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.631; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.631; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:38044/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.631; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.633; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.644; 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-30 05:51:00.676; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@709cb796; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@709cb796; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@709cb796; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.677; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 4
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.678; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.678; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 35
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.680; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.680; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.684; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.685; org.apache.solr.handler.SnapPuller; Master's generation: 4
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.685; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.685; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.688; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.689; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.690; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty4/index.20130430145100690
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.691; org.apache.solr.handler.SnapPuller; Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty4/index.20130430145100690 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7300e5e6; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.695; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.697; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.699; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.699; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.702; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5acfda6b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5acfda6b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.703; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 4
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.703; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.704; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@ee27dd4 main
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.705; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@ee27dd4 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.705; org.apache.solr.core.CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty4/index.20130430145100690 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty4/index.20130430145100690;done=true>>]
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.705; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty4/index.20130430145100690
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.705; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1367301033559/jetty4/index.20130430145100690
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.706; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.706; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.706; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.707; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.708; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.957; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.957; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:56934 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.962; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:56934/collection1/ and leader is http://127.0.0.1:38044/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.963; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56934
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.963; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.963; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.964; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.964; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.965; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.965; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.965; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.966; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.967; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.967; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.967; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 05:51:00.981; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:56934__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.119; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.122; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:?????
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.122; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.123; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.123; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1367301060979
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.124; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1367301060979/solr.xml
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.124; org.apache.solr.core.CoreContainer; New CoreContainer 304975386
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.124; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1367301060979/'
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.125; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1367301060979/'
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.207; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.208; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.208; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.209; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.209; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.210; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.210; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.210; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.211; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.211; 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-30 05:51:01.221; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.222; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:26789/solr
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.223; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.224; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.227; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@6d19c1a name:ZooKeeperConnection Watcher:127.0.0.1:26789 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.228; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.241; 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-30 05:51:01.250; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.253; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@3f1a8791 name:ZooKeeperConnection Watcher:127.0.0.1:26789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.254; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.265; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.635; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.636; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:40131__collection1",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:40131_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40131"}
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.642; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:56934__collection1",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"recovering",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:56934_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:56934"}
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.655; 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: 6)
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.655; 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: 6)
[junit4:junit4] 1> INFO - 2013-04-30 05:51:01.655; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred -
[...truncated too long message...]
173086707712}, {id=233, _version_=1433719174473973760}, {id=163, _version_=1433719173342560256}, {id=22, _version_=1433719170767257600}, {id=98, _version_=1433719172248895488}, {id=292, _version_=1433719175563444224}, {id=291, _version_=1433719175545618432}, {id=78, _version_=1433719171890282496}, {id=183, _version_=1433719173694881792}, {id=6, _version_=1433719170449539072}, {id=209, _version_=1433719174091243520}, {id=175, _version_=1433719173540741120}, {id=107, _version_=1433719172439736320}, {id=197, _version_=1433719173908791296}, {id=81, _version_=1433719171941662720}, {id=260, _version_=1433719174952124416}, {id=79, _version_=1433719171906011136}, {id=118, _version_=1433719172647354368}, {id=112, _version_=1433719172534108160}, {id=96, _version_=1433719172215341056}, {id=103, _version_=1433719172341170176}, {id=117, _version_=1433719172631625728}, {id=43, _version_=1433719171220242432}, {id=148, _version_=1433719173133893632}, {id=121, _version_=1433719172696637440}, {id=114, _version_=1433719172575002624}, {id=32, _version_=1433719170970681344}, {id=10, _version_=1433719170529230848}, {id=272, _version_=1433719175190151168}, {id=134, _version_=1433719172916838400}, {id=41, _version_=1433719171177250816}, {id=174, _version_=1433719173522915328}, {id=150, _version_=1433719173162205184}, {id=212, _version_=1433719174142623744}, {id=190, _version_=1433719173803933696}, {id=275, _version_=1433719175246774272}, {id=18, _version_=1433719170685468672}, {id=113, _version_=1433719172554031104}, {id=136, _version_=1433719172950392832}, {id=232, _version_=1433719174456147968}, {id=135, _version_=1433719172932567040}, {id=162, _version_=1433719173326831616}, {id=115, _version_=1433719172594925568}, {id=59, _version_=1433719171549495296}, {id=282, _version_=1433719175392526336}, {id=257, _version_=1433719174900744192}, {id=192, _version_=1433719173835390976}, {id=259, _version_=1433719174934298624}, {id=261, _version_=1433719174969950208}, {id=293, _version_=1433719175582318592}, {id=271, _version_=1433719175140868096}, {id=204, _version_=1433719174016794624}, {id=186, _version_=1433719173743116288}, {id=47, _version_=1433719171306225664}, {id=57, _version_=1433719171511746560}, {id=128, _version_=1433719172823515136}, {id=187, _version_=1433719173758844928}, {id=14, _version_=1433719170604728320}, {id=289, _version_=1433719175512064000}, {id=154, _version_=1433719173217779712}, {id=23, _version_=1433719170787180544}, {id=21, _version_=1433719170747334656}, {id=53, _version_=1433719171420520448}, {id=237, _version_=1433719174552616960}, {id=40, _version_=1433719171151036416}, {id=27, _version_=1433719170867920896}, {id=123, _version_=1433719172734386176}, {id=206, _version_=1433719174046154752}, {id=250, _version_=1433719174774915072}, {id=110, _version_=1433719172496359424}, {id=220, _version_=1433719174269501440}, {id=139, _version_=1433719172999675904}, {id=17, _version_=1433719170665545728}, {id=194, _version_=1433719173863702528}, {id=253, _version_=1433719174830489600}, {id=155, _version_=1433719173231411200}, {id=295, _version_=1433719175624261632}, {id=101, _version_=1433719172304470016}, {id=169, _version_=1433719173442174976}, {id=167, _version_=1433719173405474816}, {id=248, _version_=1433719174740312064}, {id=238, _version_=1433719174570442752}, {id=71, _version_=1433719171772841984}, {id=196, _version_=1433719173893062656}, {id=251, _version_=1433719174792740864}, {id=88, _version_=1433719172062248960}, {id=55, _version_=1433719171460366336}, {id=226, _version_=1433719174355484672}, {id=245, _version_=1433719174689980416}, {id=228, _version_=1433719174386941952}, {id=179, _version_=1433719173607849984}, {id=24, _version_=1433719170807103488}, {id=106, _version_=1433719172419813376}, {id=165, _version_=1433719173376114688}, {id=217, _version_=1433719174223364096}, {id=200, _version_=1433719173953880064}, {id=214, _version_=1433719174174081024}, {id=48, _version_=1433719171326148608}, {id=56, _version_=1433719171487629312}, {id=219, _version_=1433719174253772800}, {id=137, _version_=1433719172968218624}, {id=230, _version_=1433719174420496384}, {id=177, _version_=1433719173574295552}, {id=105, _version_=1433719172399890432}, {id=89, _version_=1433719172090560512}, {id=286, _version_=1433719175460683776}, {id=140, _version_=1433719173013307392}, {id=87, _version_=1433719172044423168}, {id=234, _version_=1433719174500188160}, {id=73, _version_=1433719171806396416}, {id=215, _version_=1433719174189809664}, {id=267, _version_=1433719175069564928}, {id=172, _version_=1433719173489360896}, {id=7, _version_=1433719170469462016}, {id=235, _version_=1433719174519062528}, {id=44, _version_=1433719171244359680}, {id=75, _version_=1433719171838902272}, {id=242, _version_=1433719174638600192}, {id=138, _version_=1433719172983947264}, {id=133, _version_=1433719172903206912}, {id=26, _version_=1433719170847997952}, {id=83, _version_=1433719171979411456}, {id=132, _version_=1433719172886429696}, {id=35, _version_=1433719171027304448}, {id=129, _version_=1433719172839243776}, {id=11, _version_=1433719170549153792}, {id=264, _version_=1433719175019233280}, {id=304, _version_=1433719175785742336}]
[junit4:junit4] 2> client6
[junit4:junit4] 2> PROPS:127.0.0.1:32503__collection1:{"shard":"shard1","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:32503_","base_url":"http://127.0.0.1:32503"}
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:305
[junit4:junit4] 2>
[junit4:junit4] 2> NOTE: download the large Jenkins line-docs file by running 'ant get-jenkins-line-docs' in the lucene directory.
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=SyncSliceTest -Dtests.method=testDistribSearch -Dtests.seed=64A93AFD9173B7C3 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/hudson/lucene-data/enwiki.random.lines.txt -Dtests.locale=th_TH_TH_#u-nu-thai -Dtests.timezone=Asia/Tokyo -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 564s J0 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:56934/collection1lastClient and got 5 from http://127.0.0.1:36809/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([64A93AFD9173B7C3:E54FB4E5E62CD7FF]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
[junit4:junit4] > at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 1> INFO - 2013-04-30 05:59:57.920; org.apache.solr.SolrTestCaseJ4; ###deleteCore
[junit4:junit4] 2> 564372 T269 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {range_facet_l=Pulsing41(freqCutoff=1 minBlockSize=80 maxBlockSize=180), text=MockFixedIntBlock(blockSize=1759), _version_=Pulsing41(freqCutoff=1 minBlockSize=80 maxBlockSize=180), rnd_b=PostingsFormat(name=NestedPulsing), intDefault=Pulsing41(freqCutoff=1 minBlockSize=80 maxBlockSize=180), timestamp=Pulsing41(freqCutoff=1 minBlockSize=80 maxBlockSize=180), id=PostingsFormat(name=NestedPulsing), a_t=Pulsing41(freqCutoff=1 minBlockSize=80 maxBlockSize=180), range_facet_sl=MockFixedIntBlock(blockSize=1759), range_facet_si=PostingsFormat(name=Lucene41WithOrds), other_tl1=Pulsing41(freqCutoff=1 minBlockSize=80 maxBlockSize=180), multiDefault=PostingsFormat(name=Lucene41WithOrds), a_si=PostingsFormat(name=Lucene41WithOrds)}, docValues:{timestamp=DocValuesFormat(name=SimpleText)}, sim=DefaultSimilarity, locale=th_TH_TH_#u-nu-thai, timezone=Asia/Tokyo
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Oracle Corporation 1.7.0_17 (64-bit)/cpus=16,threads=2,free=124804576,total=238419968
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SearchHandlerTest, ShowFileRequestHandlerTest, BadComponentTest, PrimitiveFieldTypeTest, SolrIndexSplitterTest, TestGroupingSearch, TestJoin, FieldMutatingUpdateProcessorTest, CircularListTest, CSVRequestHandlerTest, TestReversedWildcardFilterFactory, TestRealTimeGet, OverseerCollectionProcessorTest, SoftAutoCommitTest, CoreAdminHandlerTest, TermVectorComponentTest, ScriptEngineTest, DocumentBuilderTest, DirectUpdateHandlerOptimizeTest, BasicFunctionalityTest, SyncSliceTest]
[junit4:junit4] Completed on J0 in 564.66s, 1 test, 1 failure <<< FAILURES!
[...truncated 675 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:385: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:358: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/common-build.xml:1240: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/common-build.xml:884: There were test failures: 293 suites, 1219 tests, 1 failure, 25 ignored (6 assumptions)
Total time: 102 minutes 27 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure