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/06/25 22:39:16 UTC
[JENKINS] Lucene-Solr-Tests-4.3-Java6 - Build # 107 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.3-Java6/107/
2 tests failed.
REGRESSION: org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:42828 returned non ok status:500, message:Server Error
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:42828 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([61BC8F2CC004970C:E05A0134B75BF730]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:372)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.deleteCollectionWithDownNodes(CollectionsAPIDistributedZkTest.java:206)
at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.doTest(CollectionsAPIDistributedZkTest.java:148)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
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:616)
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:679)
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:54446/fs_qo returned non ok status:500, message:Server Error
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:54446/fs_qo returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([61BC8F2CC004970C:E05A0134B75BF730]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:372)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:150)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
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:616)
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:679)
Build Log:
[...truncated 8585 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.603; org.apache.solr.BaseDistributedSearchTestCase; Setting hostContext system property: /fs_qo/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.609; org.apache.solr.SolrTestCaseJ4; ###Starting testDistribSearch
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.611; 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-06-25 20:11:05.612; org.apache.solr.cloud.ZkTestServer$ZKServerMain; Starting server
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.713; org.apache.solr.cloud.ZkTestServer; start zk server on port:54439
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.714; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.722; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@7ee34a3c name:ZooKeeperConnection Watcher:127.0.0.1:54439 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.723; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.723; org.apache.solr.common.cloud.SolrZkClient; makePath: /solr
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.728; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.737; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@882b92b name:ZooKeeperConnection Watcher:127.0.0.1:54439/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.737; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.738; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.748; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/shards
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.751; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.754; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/shards
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.757; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.758; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.769; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.770; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.874; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.875; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.884; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.885; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.889; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.889; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.893; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/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-06-25 20:11:05.894; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.897; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.898; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.902; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.902; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.906; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-06-25 20:11:05.907; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.155; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.165; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:54442
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.167; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.167; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.168; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372191065911
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.169; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372191065911/solr.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.169; org.apache.solr.core.CoreContainer; New CoreContainer 469177055
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.170; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372191065911/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.171; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372191065911/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.328; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.329; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.330; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.330; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.331; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.332; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.332; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.333; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.333; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.334; 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-06-25 20:11:06.350; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.351; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:54439/solr
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.352; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.353; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.356; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@7f6fa3f name:ZooKeeperConnection Watcher:127.0.0.1:54439 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.356; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.359; 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-06-25 20:11:06.370; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.373; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@3e4327dc name:ZooKeeperConnection Watcher:127.0.0.1:54439/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.373; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.375; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.385; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/collection-queue-work
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.390; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.392; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54442_fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.399; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:54442_fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.402; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/election
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.417; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/leader
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.420; org.apache.solr.cloud.Overseer; Overseer (id=89927913676341251-127.0.0.1:54442_fs_qo-n_0000000000) starting
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.430; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue-work
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.440; org.apache.solr.cloud.OverseerCollectionProcessor; Process current queue of collection creations
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.441; org.apache.solr.common.cloud.SolrZkClient; makePath: /clusterstate.json
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.444; org.apache.solr.common.cloud.SolrZkClient; makePath: /aliases.json
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.451; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.454; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Starting to work on the main queue
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.458; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372191065911/collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.459; org.apache.solr.cloud.ZkController; Check for collection zkNode:control_collection
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.459; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.460; org.apache.solr.cloud.ZkController; Load collection config from:/collections/control_collection
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.462; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372191065911/collection1/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.463; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-controljetty-1372191065911/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.464; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-controljetty-1372191065911/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.512; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.572; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.674; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:06.680; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.222; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.225; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.227; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.231; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.256; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.256; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372191065911/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372191065610/control/data/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.256; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@578b1f8f
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.257; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.257; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372191065610/control/data
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.258; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372191065610/control/data/index/
[junit4:junit4] 1> WARN - 2013-06-25 20:11:07.258; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372191065610/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.258; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372191065610/control/data/index
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.261; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6d1692c lockFactory=org.apache.lucene.store.NativeFSLockFactory@2dc68dc6),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.262; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.264; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.264; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.265; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.265; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.266; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.266; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.266; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.267; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.267; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.273; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.278; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@26f997aa main
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.279; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372191065610/control/data/tlog
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.280; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.280; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.283; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@26f997aa main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.285; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.285; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.959; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.959; 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:54442_fs_qo",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54442/fs_qo"}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.960; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection control_collection with numShards 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:07.960; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:08.005; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:08.314; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:08.314; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:54442/fs_qo collection:control_collection shard:shard1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:08.315; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-06-25 20:11:08.334; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-06-25 20:11:08.337; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-06-25 20:11:08.337; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-06-25 20:11:08.338; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:54442/fs_qo/collection1/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:08.338; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-06-25 20:11:08.338; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:54442/fs_qo/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-06-25 20:11:08.339; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:54442/fs_qo/collection1/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:08.339; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.510; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.530; 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-06-25 20:11:09.570; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:54442/fs_qo/collection1/ and leader is http://127.0.0.1:54442/fs_qo/collection1/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.570; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54442/fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.570; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.571; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.571; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.573; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.574; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.575; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.576; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.592; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.594; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.596; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@77cd6a5b name:ZooKeeperConnection Watcher:127.0.0.1:54439/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.597; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.599; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.601; org.apache.solr.cloud.ChaosMonkey; monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.849; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.852; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:54446
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.853; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.854; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.854; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372191069602
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.855; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372191069602/solr.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.855; org.apache.solr.core.CoreContainer; New CoreContainer 997885503
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.856; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372191069602/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:09.857; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372191069602/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.014; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.015; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.016; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.016; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.017; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.017; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.018; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.019; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.019; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.020; 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-06-25 20:11:10.038; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.038; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:54439/solr
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.039; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.040; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.043; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@713f8452 name:ZooKeeperConnection Watcher:127.0.0.1:54439 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.044; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.059; 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-06-25 20:11:10.072; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.074; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@35b220a3 name:ZooKeeperConnection Watcher:127.0.0.1:54439/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.075; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:10.088; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.037; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.038; 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:54442_fs_qo_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:54442_fs_qo",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54442/fs_qo"}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.055; 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-06-25 20:11:11.055; 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-06-25 20:11:11.055; 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-06-25 20:11:11.092; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54446_fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.094; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:54446_fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.097; 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-06-25 20:11:11.097; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.097; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.097; 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-06-25 20:11:11.098; 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-06-25 20:11:11.099; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.110; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372191069602/collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.110; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.111; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.111; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.113; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372191069602/collection1/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.115; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty1-1372191069602/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.115; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty1-1372191069602/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.163; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.219; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.321; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.327; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.871; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.875; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.878; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.883; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.911; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.912; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372191069602/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty1/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.912; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@578b1f8f
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.913; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.914; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.914; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty1/index/
[junit4:junit4] 1> WARN - 2013-06-25 20:11:11.914; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.915; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty1/index
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.919; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@b101344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b89f302),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.919; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.923; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.923; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.924; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.925; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.926; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.926; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.926; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.927; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.928; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.938; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.945; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@47fb58c9 main
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.946; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty1/tlog
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.947; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.947; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.953; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@47fb58c9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.956; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-06-25 20:11:11.956; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-06-25 20:11:12.561; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:12.562; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"2",
[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:54446_fs_qo",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54446/fs_qo"}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:12.562; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection collection1 with numShards 2
[junit4:junit4] 1> INFO - 2013-06-25 20:11:12.563; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:12.576; 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-06-25 20:11:12.576; 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-06-25 20:11:12.576; 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-06-25 20:11:12.990; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:12.990; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:54446/fs_qo collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:12.991; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-06-25 20:11:13.008; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-06-25 20:11:13.020; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-06-25 20:11:13.020; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-06-25 20:11:13.020; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:54446/fs_qo/collection1/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:13.021; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-06-25 20:11:13.021; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:54446/fs_qo/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-06-25 20:11:13.021; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:54446/fs_qo/collection1/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:13.022; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.081; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.103; 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-06-25 20:11:14.103; 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-06-25 20:11:14.103; 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-06-25 20:11:14.110; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:54446/fs_qo/collection1/ and leader is http://127.0.0.1:54446/fs_qo/collection1/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.110; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54446/fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.110; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.111; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.111; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.114; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.115; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.116; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.116; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.406; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.409; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:54457
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.410; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.410; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.411; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372191074138
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.411; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372191074138/solr.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.412; org.apache.solr.core.CoreContainer; New CoreContainer 1076656857
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.413; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372191074138/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.413; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372191074138/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.576; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.577; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.578; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.578; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.579; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.579; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.580; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.580; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.581; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.581; 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-06-25 20:11:14.598; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.599; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:54439/solr
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.599; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.600; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.603; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@2e484dfd name:ZooKeeperConnection Watcher:127.0.0.1:54439 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.604; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.607; 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-06-25 20:11:14.618; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.621; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@12e1e74d name:ZooKeeperConnection Watcher:127.0.0.1:54439/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.621; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:14.633; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.610; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.611; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:54446_fs_qo_collection1",
[junit4:junit4] 1> "numShards":"2",
[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:54446_fs_qo",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54446/fs_qo"}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.638; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54457_fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.640; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:54457_fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.652; 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-06-25 20:11:15.652; 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-06-25 20:11:15.652; 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-06-25 20:11:15.652; 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-06-25 20:11:15.654; 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-06-25 20:11:15.660; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.661; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.661; 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-06-25 20:11:15.662; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.663; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.663; 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-06-25 20:11:15.667; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372191074138/collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.667; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.668; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.668; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.670; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372191074138/collection1/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.672; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty2-1372191074138/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.672; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty2-1372191074138/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.721; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.778; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.879; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:15.885; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.432; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.437; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.439; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.445; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.472; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.473; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372191074138/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty2/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.473; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@578b1f8f
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.474; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.475; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty2
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.475; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty2/index/
[junit4:junit4] 1> WARN - 2013-06-25 20:11:16.475; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.476; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty2/index
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.480; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6213b905 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4fb5b8a4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.480; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.483; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.484; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.485; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.485; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.486; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.487; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.487; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.488; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.489; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.498; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.506; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@26f6d704 main
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.506; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty2/tlog
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.507; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.508; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.513; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@26f6d704 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.516; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-06-25 20:11:16.516; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.162; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.163; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"2",
[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:54457_fs_qo",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54457/fs_qo"}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.164; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.164; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.205; 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-06-25 20:11:17.206; 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-06-25 20:11:17.206; 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-06-25 20:11:17.206; 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-06-25 20:11:17.523; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.523; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:54457/fs_qo collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.524; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.542; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.552; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.552; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.552; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:54457/fs_qo/collection1/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.553; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.553; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:54457/fs_qo/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.553; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:54457/fs_qo/collection1/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:17.554; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 1> INFO - 2013-06-25 20:11:18.711; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:18.730; 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-06-25 20:11:18.730; 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-06-25 20:11:18.730; 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-06-25 20:11:18.730; 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-06-25 20:11:18.740; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:54457/fs_qo/collection1/ and leader is http://127.0.0.1:54457/fs_qo/collection1/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:18.740; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54457/fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:18.740; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-06-25 20:11:18.741; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-06-25 20:11:18.741; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-06-25 20:11:18.743; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:18.744; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:18.745; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-06-25 20:11:18.745; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.013; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.017; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:54460
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.017; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.018; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.019; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372191078762
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.019; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372191078762/solr.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.020; org.apache.solr.core.CoreContainer; New CoreContainer 830205441
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.021; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372191078762/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.021; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372191078762/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.182; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.183; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.183; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.184; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.184; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.185; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.186; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.186; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.187; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.187; 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-06-25 20:11:19.206; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.206; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:54439/solr
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.207; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.208; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.212; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@34ef98ac name:ZooKeeperConnection Watcher:127.0.0.1:54439 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.212; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.226; 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-06-25 20:11:19.239; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.242; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@313eadd5 name:ZooKeeperConnection Watcher:127.0.0.1:54439/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.242; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:19.253; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.238; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.239; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:54457_fs_qo_collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard2",
[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:54457_fs_qo",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54457/fs_qo"}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.268; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54460_fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.290; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:54460_fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.294; 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-06-25 20:11:20.295; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.296; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.296; 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-06-25 20:11:20.296; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.296; 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-06-25 20:11:20.297; 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-06-25 20:11:20.348; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.348; 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-06-25 20:11:20.350; 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-06-25 20:11:20.351; 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-06-25 20:11:20.351; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.352; 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-06-25 20:11:20.353; 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-06-25 20:11:20.355; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372191078762/collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.356; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.356; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.357; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.358; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372191078762/collection1/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.360; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty3-1372191078762/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.361; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty3-1372191078762/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.409; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.470; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.572; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:20.578; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.124; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.129; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.131; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.137; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.164; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.165; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372191078762/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty3/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.165; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@578b1f8f
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.166; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.167; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty3
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.167; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty3/index/
[junit4:junit4] 1> WARN - 2013-06-25 20:11:21.167; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.168; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty3/index
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.172; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5d8409fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b7524e),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.172; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.175; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.176; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.177; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.178; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.178; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.179; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.179; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.180; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.181; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.190; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.197; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1019b028 main
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.198; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty3/tlog
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.199; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.199; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.205; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1019b028 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.208; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.209; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.853; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.854; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"2",
[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:54460_fs_qo",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54460/fs_qo"}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.854; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.854; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:21.870; 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-06-25 20:11:21.870; 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-06-25 20:11:21.870; 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-06-25 20:11:21.870; 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-06-25 20:11:21.870; 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-06-25 20:11:22.224; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.224; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:54460/fs_qo collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.228; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:54460/fs_qo/collection1/ and leader is http://127.0.0.1:54446/fs_qo/collection1/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.228; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54460/fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.228; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.229; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.229; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.230; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.230; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.230; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.231; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.232; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.232; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.232; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.233; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.260; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:54460_fs_qo_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.513; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.517; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:54464
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.517; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.518; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.518; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372191082258
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.519; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372191082258/solr.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.520; org.apache.solr.core.CoreContainer; New CoreContainer 234927446
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.520; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372191082258/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.521; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372191082258/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.678; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.679; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.680; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.680; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.681; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.682; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.682; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.683; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.683; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.684; 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-06-25 20:11:22.700; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.701; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:54439/solr
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.702; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.703; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.706; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@4f7bb842 name:ZooKeeperConnection Watcher:127.0.0.1:54439 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.707; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.723; 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-06-25 20:11:22.733; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.736; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@57c650ac name:ZooKeeperConnection Watcher:127.0.0.1:54439/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.736; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-06-25 20:11:22.749; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.376; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.377; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:54460_fs_qo_collection1",
[junit4:junit4] 1> "numShards":"2",
[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:54460_fs_qo",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54460/fs_qo"}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.393; 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-06-25 20:11:23.393; 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-06-25 20:11:23.393; 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-06-25 20:11:23.393; 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-06-25 20:11:23.393; 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-06-25 20:11:23.393; 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-06-25 20:11:23.753; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54464_fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.755; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:54464_fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.758; 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-06-25 20:11:23.758; 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-06-25 20:11:23.758; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.758; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.758; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.758; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.759; 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-06-25 20:11:23.760; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.759; 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-06-25 20:11:23.759; 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-06-25 20:11:23.760; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.760; 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-06-25 20:11:23.774; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372191082258/collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.774; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.775; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.775; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.777; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372191082258/collection1/'
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.778; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty4-1372191082258/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.779; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty4-1372191082258/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.828; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.884; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.986; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:23.992; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.263; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 127.0.0.1:54460_fs_qo_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.263; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:54460_fs_qo_collection1&state=recovering&nodeName=127.0.0.1:54460_fs_qo&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.542; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.547; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.549; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.555; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.582; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.582; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372191082258/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty4/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.582; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@578b1f8f
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.583; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.584; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty4
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.584; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty4/index/
[junit4:junit4] 1> WARN - 2013-06-25 20:11:24.585; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.586; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty4/index
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.589; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@290a887e lockFactory=org.apache.lucene.store.NativeFSLockFactory@4eb725a7),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.590; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.593; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.594; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.594; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.595; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.596; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.597; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.597; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.598; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.598; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.608; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.616; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@42b3eff7 main
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.616; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty4/tlog
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.617; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.618; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.623; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@42b3eff7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.626; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.627; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.899; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.900; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"2",
[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:54464_fs_qo",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54464/fs_qo"}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.900; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.900; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-06-25 20:11:24.905; 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-06-25 20:11:24.905; 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-06-25 20:11:24.906; 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-06-25 20:11:24.905; 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-06-25 20:11:24.906; 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-06-25 20:11:24.905; 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-06-25 20:11:25.630; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.630; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:54464/fs_qo collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.637; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:54464/fs_qo/collection1/ and leader is http://127.0.0.1:54457/fs_qo/collection1/
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.638; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54464/fs_qo
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.638; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.639; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.639; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.640; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.640; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.640; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.641; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.642; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.642; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.642; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.643; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.668; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.670; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:54464_fs_qo_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.670; org.apache.solr.cloud.AbstractFullDistribZkTestBase; Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.671; org.apache.solr.cloud.AbstractDistribZkTestBase; Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 1> INFO - 2013-06-25 20:11:25.672; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.265; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:54446/fs_qo/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.265; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:54460/fs_qo START replicas=[http://127.0.0.1:54446/fs_qo/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-06-25 20:11:26.265; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.266; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.266; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.267; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.267; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.267; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:54446/fs_qo/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.268; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.274; org.apache.solr.core.SolrCore; [collection1] webapp=/fs_qo path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.283; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.285; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@b101344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b89f302),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.286; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.287; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@b101344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b89f302),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@b101344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b89f302),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.288; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.288; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@619f9377 realtime
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.289; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.289; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.290; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.290; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.293; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.294; org.apache.solr.core.SolrCore; [collection1] webapp=/fs_qo path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.295; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.295; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.295; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.298; org.apache.solr.core.SolrCore; [collection1] webapp=/fs_qo path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.300; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.301; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty3/index.20130626021126300
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.301; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@10dbbf61 lockFactory=org.apache.lucene.store.NativeFSLockFactory@29ee65b1) fullCopy=false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.304; org.apache.solr.core.SolrCore; [collection1] webapp=/fs_qo path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.306; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.307; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.307; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.309; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5d8409fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b7524e),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5d8409fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b7524e),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.310; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.310; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.310; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@4dcc8fa3 main
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.312; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@4dcc8fa3 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.313; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty3/index.20130626021126300 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty3/index.20130626021126300;done=true>>]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.313; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty3/index.20130626021126300
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.313; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty3/index.20130626021126300
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.314; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.314; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.314; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.314; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.341; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.418; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.419; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:54464_fs_qo_collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard2",
[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:54464_fs_qo",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54464/fs_qo"}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.441; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:54460_fs_qo_collection1",
[junit4:junit4] 1> "numShards":"2",
[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:54460_fs_qo",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54460/fs_qo"}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.453; 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-06-25 20:11:26.453; 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-06-25 20:11:26.453; 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-06-25 20:11:26.453; 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-06-25 20:11:26.453; 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-06-25 20:11:26.453; 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-06-25 20:11:26.671; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 127.0.0.1:54464_fs_qo_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.671; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:54464_fs_qo_collection1&state=recovering&nodeName=127.0.0.1:54464_fs_qo&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 1> INFO - 2013-06-25 20:11:26.674; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:27.676; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.673; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:54457/fs_qo/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.673; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:54464/fs_qo START replicas=[http://127.0.0.1:54457/fs_qo/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-06-25 20:11:28.674; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.674; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.674; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.675; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.675; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.676; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:54457/fs_qo/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.676; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.679; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.682; org.apache.solr.core.SolrCore; [collection1] webapp=/fs_qo path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.689; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.691; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6213b905 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4fb5b8a4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.692; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.693; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6213b905 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4fb5b8a4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6213b905 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4fb5b8a4),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.693; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.694; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@23eb5a67 realtime
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.694; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.695; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo 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-06-25 20:11:28.696; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.696; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.698; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.699; org.apache.solr.core.SolrCore; [collection1] webapp=/fs_qo path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.699; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.700; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.700; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.702; org.apache.solr.core.SolrCore; [collection1] webapp=/fs_qo path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.703; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.704; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty4/index.20130626021128704
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.705; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@67c2a1c7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4c54b365) fullCopy=false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.707; org.apache.solr.core.SolrCore; [collection1] webapp=/fs_qo path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.708; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.709; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.710; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.711; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@290a887e lockFactory=org.apache.lucene.store.NativeFSLockFactory@4eb725a7),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@290a887e lockFactory=org.apache.lucene.store.NativeFSLockFactory@4eb725a7),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.712; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.712; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.713; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@fb0c124 main
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.714; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@fb0c124 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.715; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty4/index.20130626021128704 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty4/index.20130626021128704;done=true>>]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.715; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty4/index.20130626021128704
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.715; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1372191065610/jetty4/index.20130626021128704
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.716; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.716; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.716; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.717; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-06-25 20:11:28.718; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.469; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.470; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:54464_fs_qo_collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard2",
[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:54464_fs_qo",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54464/fs_qo"}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.486; 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-06-25 20:11:29.486; 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-06-25 20:11:29.486; 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-06-25 20:11:29.486; 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-06-25 20:11:29.486; 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-06-25 20:11:29.486; 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-06-25 20:11:29.682; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.683; org.apache.solr.cloud.AbstractDistribZkTestBase; Recoveries finished - collection: collection1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.691; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.694; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6d1692c lockFactory=org.apache.lucene.store.NativeFSLockFactory@2dc68dc6),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.695; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.696; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6d1692c lockFactory=org.apache.lucene.store.NativeFSLockFactory@2dc68dc6),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6d1692c lockFactory=org.apache.lucene.store.NativeFSLockFactory@2dc68dc6),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.696; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.697; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@669b9a30 main
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.697; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.698; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@669b9a30 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.699; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.712; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.714; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6213b905 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4fb5b8a4),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6213b905 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4fb5b8a4),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.714; org.apache.solr.core.SolrDeletionPolicy; newest commit = 3[segments_3]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.715; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@6769ba97 main
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.715; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.716; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@6769ba97 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.728; org.apache.solr.update.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:54446/fs_qo/collection1/, StdNode: http://127.0.0.1:54460/fs_qo/collection1/, StdNode: http://127.0.0.1:54464/fs_qo/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.736; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.738; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@b101344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b89f302),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@b101344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b89f302),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.738; org.apache.solr.core.SolrDeletionPolicy; newest commit = 3[segments_3]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.739; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@6d1dfaf2 main
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.739; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.740; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@6d1dfaf2 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.741; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.742; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.743; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.743; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5d8409fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b7524e),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5d8409fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b7524e),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.744; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@290a887e lockFactory=org.apache.lucene.store.NativeFSLockFactory@4eb725a7),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@290a887e lockFactory=org.apache.lucene.store.NativeFSLockFactory@4eb725a7),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.744; org.apache.solr.core.SolrDeletionPolicy; newest commit = 3[segments_3]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.745; org.apache.solr.core.SolrDeletionPolicy; newest commit = 3[segments_3]
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.745; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@91d4d65 main
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.746; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@3bbfa8f1 main
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.746; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.747; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.747; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@91d4d65 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.748; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@3bbfa8f1 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.748; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.749; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.750; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 38
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.751; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-06-25 20:11:29.755; org.apache.solr.core.SolrCore; [collection1] webapp=/fs_qo 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-06-25 20:11:29.758; org.apache.solr.core.SolrCore; [collection1] webapp=/fs_qo 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-06-25 20:11:29.760; org.apache.solr.core.SolrCore; [collection1] webapp=/fs_qo 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-06-25 20:11:29.762; org.apache.solr.core.SolrCore; [collection1] webapp=/fs_qo 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-06-25 20:11:31.774; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438846646245916672)} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.789; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={update.distrib=FROMLEADER&_version_=-1438846646251159552&update.from=http://127.0.0.1:54446/fs_qo/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438846646251159552)} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.794; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={update.distrib=FROMLEADER&_version_=-1438846646262693888&update.from=http://127.0.0.1:54457/fs_qo/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438846646262693888)} 0 2
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.795; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438846646262693888)} 0 7
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.796; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438846646251159552)} 0 19
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.800; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[a!0 (1438846646274228224)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.827; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1438846646299394048)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.828; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!0 (1438846646299394048)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.829; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[a!0]} 0 26
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.833; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[b!1 (1438846646308831232)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.840; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1438846646313025536)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.841; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[b!1 (1438846646313025536)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.845; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[c!2 (1438846646321414144)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.855; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1438846646328754176)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.856; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!2 (1438846646328754176)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.856; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[c!2]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.860; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[d!3 (1438846646337142784)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.870; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1438846646344482816)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.871; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!3 (1438846646344482816)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.871; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[d!3]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.875; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[e!4 (1438846646352871424)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.882; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1438846646357065728)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.883; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[e!4 (1438846646357065728)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.887; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[f!5 (1438846646365454336)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.897; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1438846646372794368)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.898; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1438846646372794368)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.898; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[f!5]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.902; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[g!6 (1438846646381182976)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.912; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1438846646388523008)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.913; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!6 (1438846646388523008)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.913; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[g!6]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.917; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[h!7 (1438846646396911616)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.927; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1438846646404251648)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.928; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!7 (1438846646404251648)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.928; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[h!7]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.932; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[i!8 (1438846646412640256)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.939; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1438846646416834560)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.940; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[i!8 (1438846646416834560)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.944; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[j!9 (1438846646425223168)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.954; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1438846646432563200)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.955; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!9 (1438846646432563200)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.955; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[j!9]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.959; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[k!10 (1438846646440951808)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.966; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1438846646445146112)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.967; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[k!10 (1438846646445146112)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.971; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[l!11 (1438846646453534720)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.978; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1438846646457729024)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.979; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[l!11 (1438846646457729024)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.983; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[m!12 (1438846646466117632)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.993; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1438846646473457664)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.993; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!12 (1438846646473457664)]} 0 4
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.994; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[m!12]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:31.998; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[n!13 (1438846646481846272)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.008; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1438846646489186304)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.009; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!13 (1438846646489186304)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.009; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[n!13]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.013; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[o!14 (1438846646497574912)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.023; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1438846646504914944)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.023; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!14 (1438846646504914944)]} 0 4
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.024; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[o!14]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.028; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[p!15 (1438846646513303552)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.038; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1438846646520643584)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.039; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!15 (1438846646520643584)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.039; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[p!15]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.043; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[q!16 (1438846646529032192)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.053; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1438846646536372224)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.054; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1438846646536372224)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.054; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[q!16]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.058; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[r!17 (1438846646544760832)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.065; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1438846646548955136)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.066; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[r!17 (1438846646548955136)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.070; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[s!18 (1438846646557343744)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.080; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1438846646564683776)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.081; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!18 (1438846646564683776)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.081; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[s!18]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.085; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[t!19 (1438846646573072384)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.092; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1438846646577266688)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.093; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[t!19 (1438846646577266688)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.097; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[u!20 (1438846646585655296)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.104; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1438846646589849600)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.105; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[u!20 (1438846646589849600)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.109; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[v!21 (1438846646598238208)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.119; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1438846646605578240)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.120; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!21 (1438846646605578240)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.120; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[v!21]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.124; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[w!22 (1438846646613966848)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.131; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1438846646618161152)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.132; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[w!22 (1438846646618161152)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.136; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[x!23 (1438846646626549760)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.146; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1438846646633889792)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.147; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!23 (1438846646633889792)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.147; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[x!23]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.153; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[y!24 (1438846646644375552)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.160; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1438846646648569856)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.161; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[y!24 (1438846646648569856)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.165; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[z!25 (1438846646656958464)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.172; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1438846646661152768)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.173; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[z!25 (1438846646661152768)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.177; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[a!26 (1438846646669541376)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.187; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1438846646676881408)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.187; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!26 (1438846646676881408)]} 0 4
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.188; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[a!26]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.192; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[b!27 (1438846646685270016)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.199; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1438846646689464320)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.200; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[b!27 (1438846646689464320)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.203; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[c!28 (1438846646696804352)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.210; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1438846646700998656)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.211; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[c!28 (1438846646700998656)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.215; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[d!29 (1438846646709387264)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.222; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1438846646713581568)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.223; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[d!29 (1438846646713581568)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.227; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[e!30 (1438846646721970176)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.237; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1438846646729310208)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.238; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!30 (1438846646729310208)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.238; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[e!30]} 0 8
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.242; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[f!31 (1438846646737698816)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.252; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54457/fs_qo/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1438846646745038848)]} 0 1
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.253; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={distrib.from=http://127.0.0.1:54446/fs_qo/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1438846646745038848)]} 0 5
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.254; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[f!31]} 0 9
[junit4:junit4] 1> INFO - 2013-06-25 20:11:32.258; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/fs_qo path=/update params={wt=javabin&version=2} {add=[g!32 (1438846646754476032
[...truncated too long message...]
.CollectionsAPIDistributedZkTest-jetty4-1372191789022/awholynewcollection_2_shard1_replica1/data;done=false>>]
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.354; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1372191789022/awholynewcollection_2_shard1_replica1/data
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.354; org.apache.solr.core.SolrCore; [halfdeletedcollection_shard2_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@fc52c95
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.360; org.apache.solr.update.DirectUpdateHandler2; closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.361; org.apache.solr.update.SolrCoreState; Closing SolrCoreState
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.361; org.apache.solr.update.DefaultSolrCoreState; SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.362; org.apache.solr.update.DefaultSolrCoreState; closing IndexWriter with IndexWriterCloser
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.362; org.apache.solr.core.SolrCore; [halfdeletedcollection_shard2_replica1] Closing main searcher on request.
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.363; org.apache.solr.core.CachingDirectoryFactory; Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.363; 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-06-25 20:26:51.363; org.apache.solr.core.CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1372191789022/halfdeletedcollection_shard2_replica1/data [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1372191789022/halfdeletedcollection_shard2_replica1/data;done=false>>]
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.364; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1372191789022/halfdeletedcollection_shard2_replica1/data
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.364; org.apache.solr.core.CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1372191789022/halfdeletedcollection_shard2_replica1/data/index [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1372191789022/halfdeletedcollection_shard2_replica1/data/index;done=false>>]
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.365; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1372191789022/halfdeletedcollection_shard2_replica1/data/index
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.377; org.eclipse.jetty.server.handler.ContextHandler; stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.434; org.apache.solr.SolrTestCaseJ4; ###Ending testDistribSearch
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.436; org.apache.solr.cloud.ZkTestServer; connecting to 127.0.0.1:42815 42815
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/./solrtest-CollectionsAPIDistributedZkTest-1372191783611
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=CollectionsAPIDistributedZkTest -Dtests.method=testDistribSearch -Dtests.seed=61BC8F2CC004970C -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=no_NO -Dtests.timezone=EET -Dtests.file.encoding=ISO8859-1
[junit4:junit4] ERROR 228s J0 | CollectionsAPIDistributedZkTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:42828 returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([61BC8F2CC004970C:E05A0134B75BF730]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:372)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.deleteCollectionWithDownNodes(CollectionsAPIDistributedZkTest.java:206)
[junit4:junit4] > at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.doTest(CollectionsAPIDistributedZkTest.java:148)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:679)
[junit4:junit4] 1> INFO - 2013-06-25 20:26:51.631; org.apache.solr.SolrTestCaseJ4; ###deleteCore
[junit4:junit4] 2> 228036 T1973 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 1> WARN - 2013-06-25 20:26:52.669; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-06-25 20:26:52.669; 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-06-25 20:26:52.669; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-06-25 20:26:52.670; org.apache.solr.common.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene41, sim=DefaultSimilarity, locale=no_NO, timezone=EET
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=1,free=129308640,total=436600832
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SuggesterFSTTest, TermVectorComponentTest, SoftAutoCommitTest, ZkCLITest, QueryElevationComponentTest, SyncSliceTest, DocValuesTest, TestDynamicFieldResource, PeerSyncTest, CircularListTest, TestIBSimilarityFactory, TestSchemaNameResource, TestSerializedLuceneMatchVersion, TestSolrXml, SOLR749Test, LoggingHandlerTest, TestLMDirichletSimilarityFactory, TestDynamicFieldCollectionResource, TermsComponentTest, TestDocSet, WordBreakSolrSpellCheckerTest, DocumentBuilderTest, SliceStateUpdateTest, SolrInfoMBeanTest, TestClassNameShortening, TestRealTimeGet, TestManagedSchema, TestFunctionQuery, AlternateDirectoryTest, TestXIncludeConfig, TestCopyFieldCollectionResource, ShowFileRequestHandlerTest, TestSurroundQueryParser, ShardRoutingTest, CoreAdminHandlerTest, BasicFunctionalityTest, SystemInfoHandlerTest, RAMDirectoryFactoryTest, TestWriterPerf, TestJoin, TestPseudoReturnFields, TestStressRecovery, TestDefaultSearchFieldResource, ExternalFileFieldSortTest, SchemaVersionSpecificBehaviorTest, MoreLikeThisHandlerTest, TestPerFieldSimilarity, TestSchemaVersionResource, FastVectorHighlighterTest, UpdateRequestProcessorFactoryTest, TestCoreContainer, TestLFUCache, PrimUtilsTest, FileBasedSpellCheckerTest, TestConfig, TestFaceting, ClusterStateUpdateTest, BasicDistributedZkTest, TestDocumentBuilder, DateFieldTest, TestPluginEnable, PluginInfoTest, QueryEqualityTest, TestCharFilters, ResourceLoaderTest, RegexBoostProcessorTest, TestQuerySenderListener, TestSolrCoreProperties, DirectSolrConnectionTest, TestSolrDeletionPolicy2, TestTrie, BasicDistributedZk2Test, CollectionsAPIDistributedZkTest]
[junit4:junit4] Completed on J0 in 229.32s, 1 test, 1 error <<< FAILURES!
[...truncated 448 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/build.xml:381: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/build.xml:361: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/lucene/common-build.xml:887: There were test failures: 292 suites, 1209 tests, 2 errors, 14 ignored (8 assumptions)
Total time: 50 minutes 12 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure