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/26 14:16:53 UTC
[JENKINS] Lucene-Solr-Tests-4.x-java7 - Build # 1195 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-java7/1195/
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:63335/hk_tv/collection1lastClient and got 5 from http://127.0.0.1:63347/hk_tv/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:63335/hk_tv/collection1lastClient and got 5 from http://127.0.0.1:63347/hk_tv/collection1
at __randomizedtesting.SeedInfo.seed([73A43C6F70D44E13:F242B277078B2E2F]: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 9155 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 1> INFO - 2013-04-26 11:42:17.628; org.apache.solr.BaseDistributedSearchTestCase; Setting hostContext system property: /hk_tv/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:17.633; org.apache.solr.SolrTestCaseJ4; ###Starting testDistribSearch
[junit4:junit4] 1> INFO - 2013-04-26 11:42:17.640; 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-26 11:42:17.645; org.apache.solr.cloud.ZkTestServer$ZKServerMain; Starting server
[junit4:junit4] 1> INFO - 2013-04-26 11:42:17.846; org.apache.solr.cloud.ZkTestServer; start zk server on port:63308
[junit4:junit4] 1> INFO - 2013-04-26 11:42:18.016; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> WARN - 2013-04-26 11:42:18.052; 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-26 11:42:19.584; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@798e81ce name:ZooKeeperConnection Watcher:127.0.0.1:63308 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.585; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.589; org.apache.solr.common.cloud.SolrZkClient; makePath: /solr
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.676; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.679; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1b7c3088 name:ZooKeeperConnection Watcher:127.0.0.1:63308/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.679; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.685; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.692; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/shards
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.697; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.701; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/shards
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.707; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.709; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.724; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.725; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.835; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.836; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.842; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.843; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.853; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.854; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.860; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/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-26 11:42:19.860; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.866; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.867; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.872; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.873; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.879; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-26 11:42:19.880; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.124; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.129; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:63314
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.130; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.131; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.131; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1366976539887
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.132; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1366976539887/solr.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.133; org.apache.solr.core.CoreContainer; New CoreContainer 1597828610
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.134; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1366976539887/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.134; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1366976539887/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.263; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.264; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.265; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.265; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.266; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.267; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.267; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.268; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.268; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.269; 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-26 11:42:20.290; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.291; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:63308/solr
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.315; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.316; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.320; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@55b823c5 name:ZooKeeperConnection Watcher:127.0.0.1:63308 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.321; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.342; 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-26 11:42:20.361; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.364; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@279fb543 name:ZooKeeperConnection Watcher:127.0.0.1:63308/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.365; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.377; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.394; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/collection-queue-work
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.413; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.417; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63314_hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.425; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:63314_hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.431; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/election
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.462; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/leader
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.466; org.apache.solr.cloud.Overseer; Overseer (id=89586174392532995-127.0.0.1:63314_hk_tv-n_0000000000) starting
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.496; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue-work
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.514; org.apache.solr.cloud.OverseerCollectionProcessor; Process current queue of collection creations
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.515; org.apache.solr.common.cloud.SolrZkClient; makePath: /clusterstate.json
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.521; org.apache.solr.common.cloud.SolrZkClient; makePath: /aliases.json
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.524; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.552; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Starting to work on the main queue
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.569; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1366976539887/collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.569; org.apache.solr.cloud.ZkController; Check for collection zkNode:control_collection
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.571; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.571; org.apache.solr.cloud.ZkController; Load collection config from:/collections/control_collection
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.574; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1366976539887/collection1/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.576; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1366976539887/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.577; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1366976539887/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.663; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.733; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.836; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:20.873; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.613; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.629; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.633; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.663; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.669; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.675; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-26 11:42:21.677; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-26 11:42:21.677; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.678; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-26 11:42:21.679; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-26 11:42:21.680; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.680; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.721; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1366976539887/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1366976537634/control/data/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.721; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7b1f9c80
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.722; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.723; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/control/data
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.724; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1366976537634/control/data/index/
[junit4:junit4] 1> WARN - 2013-04-26 11:42:21.725; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1366976537634/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.726; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/control/data/index
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.732; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1eb3d168; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.733; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.736; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.737; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.737; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.738; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.739; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.739; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.739; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.740; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.741; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.753; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.761; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@251b6c2d main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.762; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.762; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.766; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@251b6c2d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.769; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-26 11:42:21.769; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.063; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.064; 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:63314_hk_tv",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:63314/hk_tv"}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.065; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection control_collection with numShards 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.094; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.118; 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-26 11:42:22.774; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.774; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:63314/hk_tv collection:control_collection shard:shard1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.789; 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-26 11:42:22.807; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.835; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.870; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.871; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.876; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:63314/hk_tv/collection1/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.876; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.877; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:63314/hk_tv/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.877; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:63314/hk_tv/collection1/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:22.878; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.626; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.678; 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-26 11:42:23.710; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:63314/hk_tv/collection1/ and leader is http://127.0.0.1:63314/hk_tv/collection1/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.710; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63314/hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.710; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.711; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.711; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.714; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.715; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.716; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.795; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.818; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.824; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.852; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@55686109 name:ZooKeeperConnection Watcher:127.0.0.1:63308/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.852; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.855; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:23.861; org.apache.solr.cloud.ChaosMonkey; monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.089; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.093; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:63320
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.094; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.094; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.095; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1366976543861
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.095; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1366976543861/solr.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.096; org.apache.solr.core.CoreContainer; New CoreContainer 1086159486
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.097; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1366976543861/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.097; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1366976543861/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.220; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.221; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.222; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.222; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.223; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.223; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.224; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.225; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.225; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.226; 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-26 11:42:24.242; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.243; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:63308/solr
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.244; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.245; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.248; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@6f42602e name:ZooKeeperConnection Watcher:127.0.0.1:63308 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.249; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.261; 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-26 11:42:24.274; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.277; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@67d7ad74 name:ZooKeeperConnection Watcher:127.0.0.1:63308/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.277; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:24.290; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.194; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.195; 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:63314_hk_tv_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:63314_hk_tv",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:63314/hk_tv"}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.214; 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-26 11:42:25.214; 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-26 11:42:25.214; 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-26 11:42:25.295; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63320_hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.297; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:63320_hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.301; 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-26 11:42:25.301; 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-26 11:42:25.301; 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-26 11:42:25.304; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.305; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.305; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.316; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1366976543861/collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.317; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.318; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.318; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.320; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1366976543861/collection1/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.322; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1366976543861/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.323; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1366976543861/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.380; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.445; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.547; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:25.569; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.257; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.274; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.279; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.312; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.318; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.325; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-26 11:42:26.327; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-26 11:42:26.328; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.328; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-26 11:42:26.330; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-26 11:42:26.331; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.331; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.331; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1366976543861/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.332; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7b1f9c80
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.333; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.334; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.334; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index/
[junit4:junit4] 1> WARN - 2013-04-26 11:42:26.335; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.336; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.343; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.343; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.347; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.348; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.349; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.350; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.351; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.351; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.352; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.353; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.353; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.367; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.375; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@41cd1045 main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.376; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.377; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.382; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@41cd1045 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.385; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.385; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.723; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.724; 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:63320_hk_tv",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:63320/hk_tv"}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.725; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection collection1 with numShards 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.725; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:26.732; 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-26 11:42:26.732; 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-26 11:42:26.732; 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-26 11:42:27.389; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:27.389; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:63320/hk_tv collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:27.391; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-04-26 11:42:27.475; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:27.511; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:27.511; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-04-26 11:42:27.511; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:63320/hk_tv/collection1/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:27.512; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-04-26 11:42:27.512; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:63320/hk_tv/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-04-26 11:42:27.513; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:63320/hk_tv/collection1/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:27.513; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.249; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.288; 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-26 11:42:28.288; 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-26 11:42:28.288; 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-26 11:42:28.330; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:63320/hk_tv/collection1/ and leader is http://127.0.0.1:63320/hk_tv/collection1/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.330; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63320/hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.330; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.331; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.331; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.335; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.336; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.337; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.338; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.578; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.581; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:63328
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.582; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.583; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.583; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1366976548356
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.584; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1366976548356/solr.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.584; org.apache.solr.core.CoreContainer; New CoreContainer 1170056928
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.585; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1366976548356/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.586; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1366976548356/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.709; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.710; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.710; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.711; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.711; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.712; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.712; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.713; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.714; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.714; 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-26 11:42:28.733; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.734; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:63308/solr
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.734; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.735; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.739; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@637d8eba name:ZooKeeperConnection Watcher:127.0.0.1:63308 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.740; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.750; 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-26 11:42:28.765; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.767; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@5fd9a782 name:ZooKeeperConnection Watcher:127.0.0.1:63308/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.768; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:28.780; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.787; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63328_hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.790; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:63328_hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.794; 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-26 11:42:29.794; 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-26 11:42:29.794; 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-26 11:42:29.795; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.797; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.798; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.808; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.810; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.811; 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:63320_hk_tv_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:63320_hk_tv",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:63320/hk_tv"}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.815; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1366976548356/collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.816; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.817; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.817; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.819; 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-26 11:42:29.819; 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-26 11:42:29.819; 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-26 11:42:29.819; 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-26 11:42:29.820; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1366976548356/collection1/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.822; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1366976548356/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.824; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1366976548356/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.898; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-26 11:42:29.964; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.066; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.094; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.814; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.831; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.834; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.860; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.865; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.870; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-26 11:42:30.872; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-26 11:42:30.872; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.872; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-26 11:42:30.874; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-26 11:42:30.874; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.875; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.875; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1366976548356/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.875; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7b1f9c80
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.876; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.876; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.877; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/index/
[junit4:junit4] 1> WARN - 2013-04-26 11:42:30.878; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.878; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/index
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.884; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4080906a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.884; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.887; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.887; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.887; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.888; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.889; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.889; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.889; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.890; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.890; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.899; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.904; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@6091cc51 main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.905; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.905; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.910; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@6091cc51 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.912; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-26 11:42:30.912; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.328; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.329; 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:63328_hk_tv",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:63328/hk_tv"}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.329; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.329; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.335; 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-26 11:42:31.335; 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-26 11:42:31.336; 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-26 11:42:31.335; 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-26 11:42:31.915; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.915; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:63328/hk_tv collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.924; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:63328/hk_tv/collection1/ and leader is http://127.0.0.1:63320/hk_tv/collection1/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.925; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63328/hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.925; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.926; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.933; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.933; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.934; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.934; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.935; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.935; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.936; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.937; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:31.937; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.251; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.254; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:63335
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.255; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.256; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.256; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1366976551962
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.257; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1366976551962/solr.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.258; org.apache.solr.core.CoreContainer; New CoreContainer 1733194345
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.259; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1366976551962/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.260; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1366976551962/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.418; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.419; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.420; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.420; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.421; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.421; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.422; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.423; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.423; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.424; 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-26 11:42:32.444; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.445; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:63308/solr
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.446; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.447; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.494; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@375f519 name:ZooKeeperConnection Watcher:127.0.0.1:63308 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.495; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.523; 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-26 11:42:32.539; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.570; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1844def2 name:ZooKeeperConnection Watcher:127.0.0.1:63308/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.570; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.596; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.854; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.855; 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:63328_hk_tv_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:63328_hk_tv",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:63328/hk_tv"}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:32.880; 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-26 11:42:32.880; 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-26 11:42:32.880; 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-26 11:42:32.880; 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-26 11:42:32.880; 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-26 11:42:33.100; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:63328_hk_tv_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.102; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 127.0.0.1:63328_hk_tv_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 0 seconds.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.103; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:63328_hk_tv_collection1&state=recovering&nodeName=127.0.0.1:63328_hk_tv&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=9
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.602; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63335_hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.630; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:63335_hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.634; 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-26 11:42:33.634; 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-26 11:42:33.635; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.634; 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-26 11:42:33.634; 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-26 11:42:33.638; 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-26 11:42:33.660; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.660; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.660; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.660; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.673; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1366976551962/collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.674; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.676; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.676; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.679; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1366976551962/collection1/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.681; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1366976551962/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.682; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1366976551962/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.775; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.851; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.953; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:33.969; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.683; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.700; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.704; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.735; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.742; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.749; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-26 11:42:34.751; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-26 11:42:34.752; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.753; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-26 11:42:34.755; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-26 11:42:34.755; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.756; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.757; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1366976551962/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.758; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7b1f9c80
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.759; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.760; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.762; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/index/
[junit4:junit4] 1> WARN - 2013-04-26 11:42:34.763; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.764; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/index
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.771; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a080ee; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.772; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.776; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.777; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.778; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.779; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.780; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.780; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.781; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.781; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.782; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.795; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.804; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@7931d72b main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.805; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.805; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.811; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@7931d72b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.813; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-26 11:42:34.814; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.189; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:63320/hk_tv/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.199; 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-26 11:42:35.222; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:63328/hk_tv START replicas=[http://127.0.0.1:63320/hk_tv/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-04-26 11:42:35.232; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.233; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.233; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.234; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.234; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.234; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:63320/hk_tv/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.235; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.285; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=6
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.301; 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-26 11:42:35.306; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.307; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.311; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.312; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.313; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@5aaddd9f realtime
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.314; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.315; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 36
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.375; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.375; 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-26 11:42:35.402; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.461; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.462; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=58
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.464; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.464; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.464; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.469; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.470; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.472; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/index.20130426114235471
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.473; org.apache.solr.handler.SnapPuller; Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/index.20130426114235471 lockFactory=org.apache.lucene.store.NativeFSLockFactory@619f4d36; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.486; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=4
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.500; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.503; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.504; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.509; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4080906a; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4080906a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.511; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.511; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.513; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@7c0debb2 main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.514; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@7c0debb2 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.515; org.apache.solr.core.CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/index.20130426114235471 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/index.20130426114235471;done=true>>]
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.517; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/index.20130426114235471
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.517; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/index.20130426114235471
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.519; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.519; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.520; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.520; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.523; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.892; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.893; 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:63335_hk_tv",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:63335/hk_tv"}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.894; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.894; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.900; 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:63328_hk_tv_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:63328_hk_tv",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:63328/hk_tv"}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:35.918; 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-26 11:42:35.918; 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-26 11:42:35.918; 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-26 11:42:35.918; 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-26 11:42:35.918; 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-26 11:42:36.818; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.818; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:63335/hk_tv collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.824; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:63335/hk_tv/collection1/ and leader is http://127.0.0.1:63320/hk_tv/collection1/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.824; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63335/hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.825; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.825; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.826; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.827; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.827; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.827; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.828; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.829; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.830; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.830; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.830; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:36.851; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:63335_hk_tv_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.072; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.076; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:63347
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.076; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.077; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.078; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1366976556848
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.078; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1366976556848/solr.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.079; org.apache.solr.core.CoreContainer; New CoreContainer 955821611
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.080; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1366976556848/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.080; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1366976556848/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.227; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.229; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.229; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.230; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.231; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.232; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.233; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.234; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.235; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.236; 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-26 11:42:37.257; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.258; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:63308/solr
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.259; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.261; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.336; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@30cba8c4 name:ZooKeeperConnection Watcher:127.0.0.1:63308 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.337; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.356; 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-26 11:42:37.369; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.372; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@118a85f7 name:ZooKeeperConnection Watcher:127.0.0.1:63308/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.372; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.416; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.433; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.434; 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:63335_hk_tv_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:63335_hk_tv",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:63335/hk_tv"}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.547; 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-26 11:42:37.547; 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-26 11:42:37.547; 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-26 11:42:37.547; 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-26 11:42:37.547; 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-26 11:42:37.547; 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-26 11:42:37.853; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 127.0.0.1:63335_hk_tv_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:37.853; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:63335_hk_tv_collection1&state=recovering&nodeName=127.0.0.1:63335_hk_tv&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.422; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63347_hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.451; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:63347_hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.455; 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-26 11:42:38.455; 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-26 11:42:38.456; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.456; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.455; 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-26 11:42:38.455; 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-26 11:42:38.457; 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-26 11:42:38.456; 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-26 11:42:38.458; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.459; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.476; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.477; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.483; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1366976556848/collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.483; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.484; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.484; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.487; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1366976556848/collection1/'
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.488; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1366976556848/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.489; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1366976556848/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.545; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.610; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.712; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:38.726; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.368; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.378; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.381; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.400; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.405; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.409; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-26 11:42:39.410; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-26 11:42:39.410; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.410; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-26 11:42:39.412; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-26 11:42:39.412; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.412; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.413; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1366976556848/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.413; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7b1f9c80
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.413; org.apache.solr.core.SolrCore; solr.NRTCachingDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.414; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.415; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/index/
[junit4:junit4] 1> WARN - 2013-04-26 11:42:39.415; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.416; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/index
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.455; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@36297348; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.455; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.463; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.463; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.464; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.465; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.465; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.465; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.466; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.466; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.467; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.475; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.481; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@5fb43265 main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.482; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.482; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.486; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@5fb43265 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.489; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.490; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.855; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:63320/hk_tv/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.855; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:63335/hk_tv START replicas=[http://127.0.0.1:63320/hk_tv/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-04-26 11:42:39.856; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.856; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.856; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.857; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.857; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.857; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:63320/hk_tv/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.857; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.859; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.870; 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-26 11:42:39.875; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.876; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.877; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.877; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.879; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.879; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.883; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.884; org.apache.solr.handler.SnapPuller; Master's generation: 3
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.884; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.885; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.888; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.889; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.890; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/index.20130426114239890
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.891; org.apache.solr.handler.SnapPuller; Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/index.20130426114239890 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a4ecaab; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.895; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv 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-26 11:42:39.897; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.900; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.900; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.905; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a080ee; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a080ee; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.906; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.906; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.907; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@43437a99 main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.908; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@43437a99 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.909; org.apache.solr.core.CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/index.20130426114239890 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/index.20130426114239890;done=true>>]
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.909; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/index.20130426114239890
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.910; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/index.20130426114239890
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.911; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.911; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.912; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.912; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-26 11:42:39.914; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:40.609; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:40.610; 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:63347_hk_tv",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:63347/hk_tv"}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:40.611; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:40.611; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:40.617; 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:63335_hk_tv_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:63335_hk_tv",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:63335/hk_tv"}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:40.635; 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-26 11:42:40.635; 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-26 11:42:40.635; 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-26 11:42:40.635; 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-26 11:42:40.635; 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-26 11:42:40.635; 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-26 11:42:41.494; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.494; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:63347/hk_tv collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.502; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:63347/hk_tv/collection1/ and leader is http://127.0.0.1:63320/hk_tv/collection1/
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.503; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63347/hk_tv
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.503; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.503; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.504; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.505; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.505; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.505; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.506; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.507; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.508; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.508; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.508; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.532; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.535; org.apache.solr.cloud.AbstractFullDistribZkTestBase; Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.535; org.apache.solr.cloud.AbstractDistribZkTestBase; Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.536; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:63347_hk_tv_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-04-26 11:42:41.537; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:42.151; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:42.152; 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:63347_hk_tv_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:63347_hk_tv",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:63347/hk_tv"}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:42.160; 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-26 11:42:42.160; 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-26 11:42:42.160; 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-26 11:42:42.160; 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-26 11:42:42.160; 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-26 11:42:42.160; 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-26 11:42:42.537; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 127.0.0.1:63347_hk_tv_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:42.537; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:63347_hk_tv_collection1&state=recovering&nodeName=127.0.0.1:63347_hk_tv&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 1> INFO - 2013-04-26 11:42:42.540; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:43.543; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.540; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:63320/hk_tv/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.540; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:63347/hk_tv START replicas=[http://127.0.0.1:63320/hk_tv/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-04-26 11:42:44.541; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.541; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.541; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.542; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.542; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.542; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:63320/hk_tv/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.543; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.545; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.547; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.557; 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-26 11:42:44.574; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.575; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 4
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.576; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.577; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 20
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.578; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.578; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.582; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.583; org.apache.solr.handler.SnapPuller; Master's generation: 4
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.584; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.584; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.588; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.589; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.590; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/index.20130426114244589
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.591; org.apache.solr.handler.SnapPuller; Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/index.20130426114244589 lockFactory=org.apache.lucene.store.NativeFSLockFactory@32311ede; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.603; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv 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-26 11:42:44.605; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.608; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.608; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.613; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@36297348; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@36297348; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.613; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 4
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.614; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.615; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@6943aab0 main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.616; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@6943aab0 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.617; org.apache.solr.core.CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/index.20130426114244589 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/index.20130426114244589;done=true>>]
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.618; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/index.20130426114244589
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.618; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/index.20130426114244589
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.619; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.620; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.620; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.620; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-26 11:42:44.628; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.185; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.186; 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:63347_hk_tv_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:63347_hk_tv",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:63347/hk_tv"}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.213; 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-26 11:42:45.213; 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-26 11:42:45.213; 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-26 11:42:45.213; 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-26 11:42:45.213; 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-26 11:42:45.213; 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-26 11:42:45.550; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.551; org.apache.solr.cloud.AbstractDistribZkTestBase; Recoveries finished - collection: collection1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.564; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.569; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1eb3d168; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.570; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.578; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1eb3d168; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1eb3d168; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.579; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.580; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@c6a4c05 main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.581; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.582; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@c6a4c05 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.583; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 19
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.607; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.612; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.613; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 5
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.614; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@76f7acc9 main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.615; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.616; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@76f7acc9 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.631; org.apache.solr.update.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:63328/hk_tv/collection1/, StdNode: http://127.0.0.1:63335/hk_tv/collection1/, StdNode: http://127.0.0.1:63347/hk_tv/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.656; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.656; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.656; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.670; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@36297348; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@36297348; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.671; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 5
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.672; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4080906a; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4080906a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.673; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a080ee; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a080ee; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.673; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@3493d94a main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.674; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 4
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.673; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.675; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.676; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@3493d94a main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.677; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@3c389c07 main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.677; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 21
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.677; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.678; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@65b4b373 main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.678; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@3c389c07 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.679; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.679; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 23
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.680; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@65b4b373 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.681; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 25
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.682; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 75
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.683; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.709; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=6
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.712; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.716; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:45.719; org.apache.solr.core.SolrCore; [collection1] webapp=/hk_tv path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.809; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1433378821564792832)} 0 18
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.828; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={update.distrib=FROMLEADER&_version_=-1433378821572132864&update.from=http://127.0.0.1:63320/hk_tv/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1433378821572132864)} 0 2
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.829; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={update.distrib=FROMLEADER&_version_=-1433378821572132864&update.from=http://127.0.0.1:63320/hk_tv/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1433378821572132864)} 0 2
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.829; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={update.distrib=FROMLEADER&_version_=-1433378821572132864&update.from=http://127.0.0.1:63320/hk_tv/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1433378821572132864)} 0 2
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.830; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1433378821572132864)} 0 16
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.839; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={wt=javabin&version=2} {add=[0 (1433378821594152960)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.863; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={distrib.from=http://127.0.0.1:63320/hk_tv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1433378821602541568)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.864; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={distrib.from=http://127.0.0.1:63320/hk_tv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1433378821602541568)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.864; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={distrib.from=http://127.0.0.1:63320/hk_tv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1433378821602541568)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.865; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={wt=javabin&version=2} {add=[0 (1433378821602541568)]} 0 22
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.872; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={wt=javabin&version=2} {add=[1 (1433378821630853120)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.883; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={distrib.from=http://127.0.0.1:63320/hk_tv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1433378821637144576)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.883; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={distrib.from=http://127.0.0.1:63320/hk_tv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1433378821637144576)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.883; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={distrib.from=http://127.0.0.1:63320/hk_tv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1433378821637144576)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.885; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={wt=javabin&version=2} {add=[1 (1433378821637144576)]} 0 9
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.890; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={wt=javabin&version=2} {add=[2 (1433378821650776064)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.895; org.apache.solr.update.processor.DistributedUpdateProcessor; test.distrib.skip.servers was found and contains:[http://127.0.0.1:63328/hk_tv/collection1/]
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.896; org.apache.solr.update.processor.DistributedUpdateProcessor; check url:http://127.0.0.1:63328/hk_tv/collection1/ against:[http://127.0.0.1:63328/hk_tv/collection1/] result:true
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.896; org.apache.solr.update.processor.DistributedUpdateProcessor; check url:http://127.0.0.1:63335/hk_tv/collection1/ against:[http://127.0.0.1:63328/hk_tv/collection1/] result:false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.897; org.apache.solr.update.processor.DistributedUpdateProcessor; check url:http://127.0.0.1:63347/hk_tv/collection1/ against:[http://127.0.0.1:63328/hk_tv/collection1/] result:false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.904; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={distrib.from=http://127.0.0.1:63320/hk_tv/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:63328/hk_tv/collection1/&wt=javabin&version=2} {add=[2 (1433378821659164672)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.904; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={distrib.from=http://127.0.0.1:63320/hk_tv/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:63328/hk_tv/collection1/&wt=javabin&version=2} {add=[2 (1433378821659164672)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.906; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={test.distrib.skip.servers=http://127.0.0.1:63328/hk_tv/collection1/&wt=javabin&version=2} {add=[2 (1433378821659164672)]} 0 11
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.911; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={wt=javabin&version=2} {add=[3 (1433378821672796160)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.917; org.apache.solr.update.processor.DistributedUpdateProcessor; test.distrib.skip.servers was found and contains:[http://127.0.0.1:63335/hk_tv/collection1/, http://127.0.0.1:63328/hk_tv/collection1/]
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.917; org.apache.solr.update.processor.DistributedUpdateProcessor; check url:http://127.0.0.1:63328/hk_tv/collection1/ against:[http://127.0.0.1:63335/hk_tv/collection1/, http://127.0.0.1:63328/hk_tv/collection1/] result:true
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.918; org.apache.solr.update.processor.DistributedUpdateProcessor; check url:http://127.0.0.1:63335/hk_tv/collection1/ against:[http://127.0.0.1:63335/hk_tv/collection1/, http://127.0.0.1:63328/hk_tv/collection1/] result:true
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.918; org.apache.solr.update.processor.DistributedUpdateProcessor; check url:http://127.0.0.1:63347/hk_tv/collection1/ against:[http://127.0.0.1:63335/hk_tv/collection1/, http://127.0.0.1:63328/hk_tv/collection1/] result:false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.926; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={distrib.from=http://127.0.0.1:63320/hk_tv/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:63328/hk_tv/collection1/&wt=javabin&version=2} {add=[3 (1433378821682233344)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.927; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={test.distrib.skip.servers=http://127.0.0.1:63328/hk_tv/collection1/&test.distrib.skip.servers=http://127.0.0.1:63335/hk_tv/collection1/&wt=javabin&version=2} {add=[3 (1433378821682233344)]} 0 11
[junit4:junit4] 1> INFO - 2013-04-26 11:42:47.932; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:48.022; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1eb3d168; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1eb3d168; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:48.024; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-04-26 11:42:48.063; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@7f3dea3e main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:48.064; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-26 11:42:48.065; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@7f3dea3e main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):C4)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:48.066; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/hk_tv path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 134
[junit4:junit4] 1> INFO - 2013-04-26 11:42:48.071; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:48.141; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; 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-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 1> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1366976537634/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4763de64; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:48.142; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 6
[junit4:junit4] 1> INFO - 2013-04-26 11:42:48.150; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@2793a81c main
[junit4:junit4] 1> INFO - 2013-04-26 11:42:48.151; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-26 11:42:48.152; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@2793a81c main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):C4)}
[junit4:junit4] 1> INFO - 2013-04-26 11:42:48.153; org.apache.solr.update.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:63328/hk_tv/collection1/, StdNode: http://127.0.0.1:63335/hk_tv/collection1/, StdNode: http://127.0.0.1:63347/hk_tv/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 1> INFO - 2013-04-26 11:42:48.157; org.apache.solr.update.Direc
[...truncated too long message...]
version_=1433379233045938176}, {id=224, _version_=1433379234639773696}, {id=26, _version_=1433379230864900096}, {id=258, _version_=1433379235192373248}, {id=155, _version_=1433379233355268096}, {id=48, _version_=1433379231368216576}, {id=38, _version_=1433379231152209920}, {id=156, _version_=1433379233373093888}, {id=82, _version_=1433379232083345408}, {id=192, _version_=1433379234120728576}, {id=185, _version_=1433379233968685056}, {id=215, _version_=1433379234497167360}, {id=80, _version_=1433379232043499520}, {id=256, _version_=1433379235155673088}, {id=302, _version_=1433379235885481984}, {id=182, _version_=1433379233912061952}, {id=92, _version_=1433379232281526272}, {id=93, _version_=1433379232299352064}, {id=260, _version_=1433379235221733376}, {id=113, _version_=1433379232642236416}, {id=194, _version_=1433379234150088704}, {id=89, _version_=1433379232229097472}, {id=14, _version_=1433379230622679040}, {id=229, _version_=1433379234714222592}, {id=254, _version_=1433379235128410112}, {id=276, _version_=1433379235475488768}, {id=19, _version_=1433379230725439488}, {id=13, _version_=1433379230602756096}, {id=150, _version_=1433379233265090560}, {id=30, _version_=1433379230957174784}, {id=231, _version_=1433379234754068480}, {id=198, _version_=1433379234213003264}, {id=207, _version_=1433379234363998208}, {id=84, _version_=1433379232125288448}, {id=11, _version_=1433379230560813056}, {id=170, _version_=1433379233695006720}, {id=114, _version_=1433379232657965056}, {id=290, _version_=1433379235693592576}, {id=40, _version_=1433379231198347264}, {id=171, _version_=1433379233712832512}, {id=298, _version_=1433379235819421696}, {id=271, _version_=1433379235393699840}, {id=128, _version_=1433379232895991808}, {id=117, _version_=1433379232714588160}, {id=153, _version_=1433379233320665088}, {id=110, _version_=1433379232589807616}, {id=73, _version_=1433379231919767552}, {id=133, _version_=1433379232981975040}, {id=41, _version_=1433379231220367360}, {id=54, _version_=1433379231501385728}, {id=146, _version_=1433379233196933120}, {id=236, _version_=1433379234829565952}, {id=112, _version_=1433379232624410624}, {id=66, _version_=1433379231761432576}, {id=58, _version_=1433379231583174656}, {id=245, _version_=1433379234970075136}, {id=270, _version_=1433379235377971200}, {id=212, _version_=1433379234451030016}, {id=230, _version_=1433379234729951232}, {id=266, _version_=1433379235316105216}, {id=143, _version_=1433379233142407168}, {id=22, _version_=1433379230782062592}, {id=280, _version_=1433379235534209024}, {id=50, _version_=1433379231416451072}, {id=18, _version_=1433379230705516544}, {id=10, _version_=1433379230545084416}, {id=214, _version_=1433379234480390144}, {id=226, _version_=1433379234669133824}, {id=294, _version_=1433379235752312832}, {id=189, _version_=1433379234030551040}, {id=111, _version_=1433379232608681984}, {id=67, _version_=1433379231783452672}, {id=142, _version_=1433379233126678528}, {id=70, _version_=1433379231853707264}, {id=255, _version_=1433379235142041600}, {id=227, _version_=1433379234684862464}, {id=109, _version_=1433379232571981824}, {id=52, _version_=1433379231460491264}, {id=232, _version_=1433379234769797120}, {id=274, _version_=1433379235445080064}, {id=135, _version_=1433379233013432320}, {id=240, _version_=1433379234896674816}, {id=173, _version_=1433379233750581248}, {id=141, _version_=1433379233111998464}, {id=100, _version_=1433379232417841152}, {id=37, _version_=1433379231131238400}, {id=76, _version_=1433379231975342080}, {id=91, _version_=1433379232264749056}, {id=7, _version_=1433379230487412736}, {id=125, _version_=1433379232846708736}, {id=225, _version_=1433379234654453760}, {id=180, _version_=1433379233877458944}, {id=275, _version_=1433379235460808704}, {id=211, _version_=1433379234434252800}, {id=28, _version_=1433379230913134592}, {id=206, _version_=1433379234346172416}, {id=278, _version_=1433379235504848896}, {id=27, _version_=1433379230885871616}, {id=242, _version_=1433379234926034944}, {id=235, _version_=1433379234814885888}, {id=86, _version_=1433379232170377216}, {id=217, _version_=1433379234526527488}, {id=163, _version_=1433379233534574592}, {id=8, _version_=1433379230507335680}, {id=165, _version_=1433379233592246272}, {id=176, _version_=1433379233804058624}, {id=174, _version_=1433379233768407040}, {id=36, _version_=1433379231106072576}, {id=222, _version_=1433379234604122112}, {id=101, _version_=1433379232433569792}, {id=65, _version_=1433379231739412480}, {id=77, _version_=1433379231991070720}, {id=119, _version_=1433379232746045440}, {id=57, _version_=1433379231568494592}, {id=250, _version_=1433379235068641280}, {id=124, _version_=1433379232828882944}, {id=287, _version_=1433379235647455232}, {id=120, _version_=1433379232761774080}, {id=45, _version_=1433379231303204864}, {id=31, _version_=1433379230980243456}, {id=166, _version_=1433379233612169216}, {id=300, _version_=1433379235848781824}, {id=181, _version_=1433379233895284736}, {id=122, _version_=1433379232797425664}, {id=85, _version_=1433379232148357120}, {id=138, _version_=1433379233062715392}, {id=203, _version_=1433379234296889344}, {id=289, _version_=1433379235678912512}, {id=303, _version_=1433379235901210624}, {id=63, _version_=1433379231696420864}, {id=219, _version_=1433379234556936192}, {id=16, _version_=1433379230663573504}, {id=286, _version_=1433379235629629440}, {id=267, _version_=1433379235333931008}, {id=184, _version_=1433379233949810688}, {id=121, _version_=1433379232779599872}, {id=154, _version_=1433379233336393728}, {id=164, _version_=1433379233556594688}, {id=102, _version_=1433379232451395584}, {id=238, _version_=1433379234867314688}, {id=53, _version_=1433379231480414208}, {id=220, _version_=1433379234572664832}, {id=56, _version_=1433379231550668800}, {id=193, _version_=1433379234135408640}, {id=284, _version_=1433379235595026432}, {id=162, _version_=1433379233503117312}, {id=204, _version_=1433379234312617984}, {id=264, _version_=1433379235282550784}, {id=285, _version_=1433379235612852224}, {id=297, _version_=1433379235803693056}, {id=123, _version_=1433379232813154304}]
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=SyncSliceTest -Dtests.method=testDistribSearch -Dtests.seed=73A43C6F70D44E13 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=mk -Dtests.timezone=UTC -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 859s J0 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:63335/hk_tv/collection1lastClient and got 5 from http://127.0.0.1:63347/hk_tv/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([73A43C6F70D44E13:F242B277078B2E2F]: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-26 11:56:36.648; org.apache.solr.SolrTestCaseJ4; ###deleteCore
[junit4:junit4] 2> 859027 T273 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 1> WARN - 2013-04-26 11:56:37.705; org.apache.solr.common.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-04-26 11:56:37.705; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> WARN - 2013-04-26 11:56:37.706; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene40, sim=DefaultSimilarity, locale=mk, timezone=UTC
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Oracle Corporation 1.7.0_17 (64-bit)/cpus=16,threads=4,free=303908912,total=478150656
[junit4:junit4] 2> NOTE: All tests run in this JVM: [CoreContainerCoreInitFailuresTest, URLClassifyProcessorTest, XmlUpdateRequestHandlerTest, TestRealTimeGet, SampleTest, CachingDirectoryFactoryTest, DistanceFunctionTest, RegexBoostProcessorTest, StatelessScriptUpdateProcessorFactoryTest, FieldMutatingUpdateProcessorTest, TestSolrXml, RequiredFieldsTest, TestSolrQueryParserDefaultOperatorResource, SyncSliceTest]
[junit4:junit4] Completed on J0 in 860.31s, 1 test, 1 failure <<< FAILURES!
[...truncated 660 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/build.xml:384: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/build.xml:364: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/lucene/common-build.xml:887: There were test failures: 294 suites, 1222 tests, 1 failure, 27 ignored (8 assumptions)
Total time: 56 minutes 15 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure