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/05/20 11:38:37 UTC
[JENKINS] Lucene-Solr-Tests-4.3-Java6 - Build # 11 - Still Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.3-Java6/11/
2 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:38557 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:38557 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([C021E6778DD94DDD:41C7686FFA862DE1]: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:208)
at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
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.CollectionsAPIDistributedZkTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:42364/t_mhp 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:42364/t_mhp returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([C021E6778DD94DDD:41C7686FFA862DE1]: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)
Build Log:
[...truncated 8763 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.374; org.apache.solr.BaseDistributedSearchTestCase; Setting hostContext system property: /
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.379; org.apache.solr.SolrTestCaseJ4; ###Starting testDistribSearch
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.381; 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-05-20 09:21:51.381; org.apache.solr.cloud.ZkTestServer$ZKServerMain; Starting server
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.482; org.apache.solr.cloud.ZkTestServer; start zk server on port:16382
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.483; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.487; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@2f6263df name:ZooKeeperConnection Watcher:127.0.0.1:16382 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.487; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.488; org.apache.solr.common.cloud.SolrZkClient; makePath: /solr
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.505; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.512; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1a373b03 name:ZooKeeperConnection Watcher:127.0.0.1:16382/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.512; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.513; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.516; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/shards
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.526; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.528; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/shards
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.531; 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-05-20 09:21:51.532; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.543; 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-05-20 09:21:51.545; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.648; 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-05-20 09:21:51.648; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.651; 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-05-20 09:21:51.652; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.655; 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-05-20 09:21:51.656; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.659; 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-05-20 09:21:51.659; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.662; 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-05-20 09:21:51.663; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.666; 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-05-20 09:21:51.667; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.669; 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-05-20 09:21:51.670; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.924; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.934; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:25973
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.935; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.935; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.936; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369041711680
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.936; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369041711680/solr.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.937; org.apache.solr.core.CoreContainer; New CoreContainer 1488185068
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.937; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369041711680/'
[junit4:junit4] 1> INFO - 2013-05-20 09:21:51.938; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369041711680/'
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.101; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.102; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.103; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.103; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.104; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.104; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.105; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.105; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.106; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.106; 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-05-20 09:21:52.124; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.124; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:16382/solr
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.125; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.126; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.128; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@2239c331 name:ZooKeeperConnection Watcher:127.0.0.1:16382 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.129; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.131; 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-05-20 09:21:52.144; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.146; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@64b6ea43 name:ZooKeeperConnection Watcher:127.0.0.1:16382/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.146; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.148; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.158; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/collection-queue-work
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.161; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.168; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:25973_
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.170; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:25973_
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.173; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/election
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.189; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/leader
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.192; org.apache.solr.cloud.Overseer; Overseer (id=89721517597523971-127.0.0.1:25973_-n_0000000000) starting
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.204; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue-work
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.215; org.apache.solr.cloud.OverseerCollectionProcessor; Process current queue of collection creations
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.215; org.apache.solr.common.cloud.SolrZkClient; makePath: /clusterstate.json
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.218; org.apache.solr.common.cloud.SolrZkClient; makePath: /aliases.json
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.225; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.227; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Starting to work on the main queue
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.231; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369041711680/collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.231; org.apache.solr.cloud.ZkController; Check for collection zkNode:control_collection
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.232; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.232; org.apache.solr.cloud.ZkController; Load collection config from:/collections/control_collection
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.233; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369041711680/collection1/'
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.235; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369041711680/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.235; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369041711680/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.284; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.341; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.442; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.447; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-20 09:21:52.997; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.002; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.004; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.009; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.030; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.030; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369041711680/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/control/data/
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.031; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@689e8c34
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.031; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.032; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/control/data
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.032; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/control/data/index/
[junit4:junit4] 1> WARN - 2013-05-20 09:21:53.032; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.033; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/control/data/index
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.037; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@493f57c lockFactory=org.apache.lucene.store.NativeFSLockFactory@4973eff0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.038; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.040; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.041; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.041; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.042; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.043; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.043; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.043; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.044; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.044; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.054; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.061; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@540cedb main
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.061; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/control/data/tlog
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.062; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.062; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.065; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@540cedb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.067; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.067; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.730; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.731; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"1",
[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:25973_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:25973"}
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.731; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection control_collection with numShards 1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.732; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:53.747; 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-05-20 09:21:54.070; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:54.070; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:25973 collection:control_collection shard:shard1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:54.071; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-05-20 09:21:54.089; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-20 09:21:54.091; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-20 09:21:54.091; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-20 09:21:54.092; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:25973/collection1/
[junit4:junit4] 1> INFO - 2013-05-20 09:21:54.092; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-20 09:21:54.092; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:25973/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-20 09:21:54.093; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:25973/collection1/
[junit4:junit4] 1> INFO - 2013-05-20 09:21:54.093; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.250; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.270; 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-05-20 09:21:55.323; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:25973/collection1/ and leader is http://127.0.0.1:25973/collection1/
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.323; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:25973
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.323; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.323; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.324; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.325; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.326; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.327; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.328; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.344; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.346; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.348; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@3562de45 name:ZooKeeperConnection Watcher:127.0.0.1:16382/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.348; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.350; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.352; org.apache.solr.cloud.ChaosMonkey; monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.601; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.605; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:38557
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.605; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.606; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.606; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369041715352
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.607; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369041715352/solr.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.607; org.apache.solr.core.CoreContainer; New CoreContainer 571059552
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.608; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369041715352/'
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.609; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369041715352/'
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.767; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.768; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.769; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.769; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.770; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.770; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.771; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.771; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.772; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.772; 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-05-20 09:21:55.788; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.789; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:16382/solr
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.789; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.790; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.793; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@2f1e24e6 name:ZooKeeperConnection Watcher:127.0.0.1:16382 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.793; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.811; 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-05-20 09:21:55.822; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.824; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@47fda79c name:ZooKeeperConnection Watcher:127.0.0.1:16382/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.824; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:21:55.834; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.783; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.784; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"1",
[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:25973_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:25973"}
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.802; 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-05-20 09:21:56.802; 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-05-20 09:21:56.802; 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-05-20 09:21:56.838; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38557_
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.840; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:38557_
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.842; 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-05-20 09:21:56.842; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.842; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.843; 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-05-20 09:21:56.843; 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-05-20 09:21:56.844; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.854; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369041715352/collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.855; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.855; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.856; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369041715352/collection1/'
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.859; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369041715352/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.859; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369041715352/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.907; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 1> INFO - 2013-05-20 09:21:56.964; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.066; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.071; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.626; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.630; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.633; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.638; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.659; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.659; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369041715352/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty1/
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.660; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@689e8c34
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.660; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.661; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.661; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty1/index/
[junit4:junit4] 1> WARN - 2013-05-20 09:21:57.661; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.662; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty1/index
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.666; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30b1e5fa lockFactory=org.apache.lucene.store.NativeFSLockFactory@17d1357e),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.666; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.669; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.669; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.670; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.671; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.671; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.671; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.672; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.672; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.673; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.682; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.689; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@49acb697 main
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.690; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty1/tlog
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.691; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.691; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.696; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@49acb697 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.698; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-20 09:21:57.698; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.307; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.308; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"2",
[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:38557_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:38557"}
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.308; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection collection1 with numShards 2
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.308; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.313; 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-05-20 09:21:58.313; 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-05-20 09:21:58.313; 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-05-20 09:21:58.701; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.701; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:38557 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.702; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.721; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.732; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.732; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.732; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:38557/collection1/
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.733; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.733; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:38557/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.733; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:38557/collection1/
[junit4:junit4] 1> INFO - 2013-05-20 09:21:58.733; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 1> INFO - 2013-05-20 09:21:59.826; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:21:59.914; 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-05-20 09:21:59.914; 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-05-20 09:21:59.914; 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-05-20 09:21:59.972; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:38557/collection1/ and leader is http://127.0.0.1:38557/collection1/
[junit4:junit4] 1> INFO - 2013-05-20 09:21:59.972; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38557
[junit4:junit4] 1> INFO - 2013-05-20 09:21:59.972; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-20 09:21:59.972; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-20 09:21:59.973; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.002; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.003; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.003; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.004; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.265; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.269; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:40875
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.269; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.270; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.270; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369041720020
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.271; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369041720020/solr.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.271; org.apache.solr.core.CoreContainer; New CoreContainer 1261977626
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.272; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369041720020/'
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.273; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369041720020/'
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.432; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.433; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.433; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.434; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.434; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.435; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.435; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.436; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.436; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.437; 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-05-20 09:22:00.454; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.455; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:16382/solr
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.455; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.456; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.485; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@4e1b292b name:ZooKeeperConnection Watcher:127.0.0.1:16382 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.486; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.488; 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-05-20 09:22:00.501; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.503; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@288a4f51 name:ZooKeeperConnection Watcher:127.0.0.1:16382/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.503; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:22:00.515; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.449; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.450; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"2",
[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:38557_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:38557"}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.467; 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-05-20 09:22:01.467; 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-05-20 09:22:01.467; 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-05-20 09:22:01.467; 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-05-20 09:22:01.518; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40875_
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.520; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:40875_
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.522; 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-05-20 09:22:01.522; 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-05-20 09:22:01.523; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.523; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.523; 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-05-20 09:22:01.523; 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-05-20 09:22:01.524; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.531; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.536; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369041720020/collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.537; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.537; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.538; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.539; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369041720020/collection1/'
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.540; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369041720020/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.541; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369041720020/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.595; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.652; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.754; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:01.759; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.307; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.311; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.314; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.319; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.340; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.340; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369041720020/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty2/
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.341; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@689e8c34
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.341; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.342; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty2
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.342; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty2/index/
[junit4:junit4] 1> WARN - 2013-05-20 09:22:02.343; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.343; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty2/index
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.347; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@231f0698 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6eec6192),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.347; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.350; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.350; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.351; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.352; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.352; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.353; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.353; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.354; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.354; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.364; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.371; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@33a13f07 main
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.371; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty2/tlog
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.372; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.372; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.377; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@33a13f07 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.379; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.379; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.972; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.973; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"3",
[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:40875_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40875"}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.973; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.973; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-05-20 09:22:02.988; 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-05-20 09:22:02.988; 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-05-20 09:22:02.988; 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-05-20 09:22:02.988; 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-05-20 09:22:03.382; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:03.382; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:40875 collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-05-20 09:22:03.383; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 1> INFO - 2013-05-20 09:22:03.401; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-20 09:22:03.412; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-20 09:22:03.412; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-20 09:22:03.413; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:40875/collection1/
[junit4:junit4] 1> INFO - 2013-05-20 09:22:03.413; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-20 09:22:03.413; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:40875/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-20 09:22:03.413; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:40875/collection1/
[junit4:junit4] 1> INFO - 2013-05-20 09:22:03.414; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.492; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.510; 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-05-20 09:22:04.510; 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-05-20 09:22:04.510; 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-05-20 09:22:04.510; 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-05-20 09:22:04.550; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:40875/collection1/ and leader is http://127.0.0.1:40875/collection1/
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.550; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40875
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.550; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.550; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.551; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.552; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.553; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.554; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.555; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.819; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.823; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:53921
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.824; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.824; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.825; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369041724570
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.825; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369041724570/solr.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.826; org.apache.solr.core.CoreContainer; New CoreContainer 425972851
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.827; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369041724570/'
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.827; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369041724570/'
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.995; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.995; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.996; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.996; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.997; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.997; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.998; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.998; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.999; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-20 09:22:04.999; 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-05-20 09:22:05.015; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-20 09:22:05.016; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:16382/solr
[junit4:junit4] 1> INFO - 2013-05-20 09:22:05.017; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-20 09:22:05.018; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:22:05.021; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@48218ec5 name:ZooKeeperConnection Watcher:127.0.0.1:16382 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-20 09:22:05.021; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:22:05.049; 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-05-20 09:22:05.060; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:22:05.062; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@6dfd1ed2 name:ZooKeeperConnection Watcher:127.0.0.1:16382/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-20 09:22:05.062; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:22:05.108; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.016; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.017; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"3",
[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:40875_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40875"}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.047; 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-05-20 09:22:06.047; 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-05-20 09:22:06.047; 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-05-20 09:22:06.047; 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-05-20 09:22:06.047; 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-05-20 09:22:06.111; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53921_
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.113; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:53921_
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.115; 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-05-20 09:22:06.115; 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-05-20 09:22:06.115; 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-05-20 09:22:06.115; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.115; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.116; 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-05-20 09:22:06.116; 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-05-20 09:22:06.116; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.123; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.123; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.128; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369041724570/collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.129; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.129; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.129; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.131; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369041724570/collection1/'
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.132; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369041724570/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.133; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369041724570/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.182; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.239; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.340; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.346; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.898; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.902; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.904; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.909; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.930; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.931; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369041724570/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty3/
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.931; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@689e8c34
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.932; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.932; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.933; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty3/index/
[junit4:junit4] 1> WARN - 2013-05-20 09:22:06.933; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.934; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty3/index
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.937; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@264b6a5a lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a72196),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.937; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.940; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.941; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.941; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.942; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.943; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.943; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.943; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.944; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.944; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.954; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.961; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@61e661ea main
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.961; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty3/tlog
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.962; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.963; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.967; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@61e661ea main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.969; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-20 09:22:06.970; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.558; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.559; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"4",
[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:53921_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:53921"}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.559; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.559; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.577; 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-05-20 09:22:07.577; 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-05-20 09:22:07.577; 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-05-20 09:22:07.577; 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-05-20 09:22:07.577; 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-05-20 09:22:07.972; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.972; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:53921 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.975; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:53921/collection1/ and leader is http://127.0.0.1:38557/collection1/
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.975; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53921
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.975; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.975; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.976; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.977; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.977; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.977; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.977; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.978; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.979; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.979; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.980; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-20 09:22:07.998; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.242; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.245; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:34909
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.246; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.246; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.247; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369041727997
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.248; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369041727997/solr.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.248; org.apache.solr.core.CoreContainer; New CoreContainer 1295497643
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.249; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369041727997/'
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.249; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369041727997/'
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.408; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.409; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.409; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.410; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.410; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.411; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.411; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.412; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.412; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.413; 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-05-20 09:22:08.430; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.431; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:16382/solr
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.431; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.432; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.435; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@40a0bbe9 name:ZooKeeperConnection Watcher:127.0.0.1:16382 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.436; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.449; 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-05-20 09:22:08.461; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.463; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@3ca2bc3d name:ZooKeeperConnection Watcher:127.0.0.1:16382/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.464; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-20 09:22:08.475; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.081; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.082; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"4",
[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:53921_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:53921"}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.098; 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-05-20 09:22:09.098; 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-05-20 09:22:09.098; 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-05-20 09:22:09.098; 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-05-20 09:22:09.098; 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-05-20 09:22:09.098; 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-05-20 09:22:09.479; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34909_
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.511; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:34909_
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.513; 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-05-20 09:22:09.513; 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-05-20 09:22:09.513; 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-05-20 09:22:09.514; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.514; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.514; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.515; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.515; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.515; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.515; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.523; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.523; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.528; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369041727997/collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.529; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.529; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.530; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.531; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369041727997/collection1/'
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.533; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369041727997/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.533; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369041727997/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.587; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.645; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.746; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:09.751; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.473; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.474; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:53921_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2476
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.800; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.804; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.806; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.815; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.837; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.837; 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/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369041727997/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty4/
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.838; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@689e8c34
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.838; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.839; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty4
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.839; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty4/index/
[junit4:junit4] 1> WARN - 2013-05-20 09:22:10.839; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.840; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty4/index
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.843; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@f6d0d90 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16252bfa),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.844; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.846; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.847; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.847; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.848; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.849; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.849; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.849; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.850; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.850; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.860; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.867; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@108ddd1a main
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.867; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty4/tlog
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.868; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.869; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.873; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@108ddd1a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.875; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-20 09:22:10.875; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.105; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.106; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"5",
[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:34909_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34909"}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.106; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.107; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.126; 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-05-20 09:22:12.126; 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-05-20 09:22:12.126; 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-05-20 09:22:12.126; 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-05-20 09:22:12.126; 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-05-20 09:22:12.126; 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-05-20 09:22:12.476; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:38557/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.476; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:53921 START replicas=[http://127.0.0.1:38557/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-05-20 09:22:12.476; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.477; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.478; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.478; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.478; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.478; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:38557/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.479; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.484; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.495; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.498; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30b1e5fa lockFactory=org.apache.lucene.store.NativeFSLockFactory@17d1357e),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.498; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.499; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30b1e5fa lockFactory=org.apache.lucene.store.NativeFSLockFactory@17d1357e),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30b1e5fa lockFactory=org.apache.lucene.store.NativeFSLockFactory@17d1357e),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.499; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.500; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@5d958a8c realtime
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.500; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.501; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.501; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.502; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.504; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.504; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.505; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.505; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.505; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.507; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.508; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.509; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty3/index.20130520062212508
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.509; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@18952ea6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3d093c2d) fullCopy=false
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.512; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.513; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.514; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.514; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.516; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@264b6a5a lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a72196),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@264b6a5a lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a72196),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.516; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.517; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.517; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@61b9d13f main
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.518; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@61b9d13f main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.519; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty3/index.20130520062212508 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty3/index.20130520062212508;done=true>>]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.519; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty3/index.20130520062212508
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.519; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty3/index.20130520062212508
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.519; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.520; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.520; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.520; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.558; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.904; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.904; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:34909 collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.907; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:34909/collection1/ and leader is http://127.0.0.1:40875/collection1/
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.907; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34909
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.908; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.908; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.909; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.909; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.909; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.910; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.910; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.910; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.911; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.911; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.911; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.926; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.927; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.927; org.apache.solr.cloud.AbstractFullDistribZkTestBase; Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.928; org.apache.solr.cloud.AbstractDistribZkTestBase; Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 1> INFO - 2013-05-20 09:22:12.929; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:13.631; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:13.632; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"4",
[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:53921_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:53921"}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:13.636; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"5",
[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:34909_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34909"}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:13.650; 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-05-20 09:22:13.650; 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-05-20 09:22:13.650; 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-05-20 09:22:13.650; 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-05-20 09:22:13.650; 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-05-20 09:22:13.650; 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-05-20 09:22:13.928; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-05-20 09:22:13.928; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:34909_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 1> INFO - 2013-05-20 09:22:13.930; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:14.932; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.930; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:40875/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.930; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:34909 START replicas=[http://127.0.0.1:40875/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-05-20 09:22:15.931; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.931; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.931; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.931; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.932; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.932; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:40875/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.933; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.934; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.938; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.944; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.946; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@231f0698 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6eec6192),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.947; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.947; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@231f0698 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6eec6192),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@231f0698 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6eec6192),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.948; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.948; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@6ec0f6eb realtime
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.949; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.949; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.950; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.950; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.952; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.952; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.953; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.953; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.953; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.955; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.956; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.957; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty4/index.20130520062215956
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.957; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@55938afd lockFactory=org.apache.lucene.store.NativeFSLockFactory@26f74133) fullCopy=false
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.960; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.961; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.962; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.962; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.964; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@f6d0d90 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16252bfa),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@f6d0d90 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16252bfa),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.964; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.964; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.965; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@110fef18 main
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.966; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@110fef18 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.966; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty4/index.20130520062215956 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty4/index.20130520062215956;done=true>>]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.967; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty4/index.20130520062215956
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.967; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369041711380/jetty4/index.20130520062215956
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.967; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.967; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.968; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.968; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-20 09:22:15.969; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.658; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.659; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"5",
[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:34909_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34909"}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.675; 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-05-20 09:22:16.675; 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-05-20 09:22:16.675; 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-05-20 09:22:16.675; 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-05-20 09:22:16.675; 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-05-20 09:22:16.675; 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-05-20 09:22:16.936; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.937; org.apache.solr.cloud.AbstractDistribZkTestBase; Recoveries finished - collection: collection1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.944; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.947; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@493f57c lockFactory=org.apache.lucene.store.NativeFSLockFactory@4973eff0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.947; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.948; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@493f57c lockFactory=org.apache.lucene.store.NativeFSLockFactory@4973eff0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@493f57c lockFactory=org.apache.lucene.store.NativeFSLockFactory@4973eff0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.948; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.949; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@44d9f77d main
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.949; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.950; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@44d9f77d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.952; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.964; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.965; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@231f0698 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6eec6192),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@231f0698 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6eec6192),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.966; org.apache.solr.core.SolrDeletionPolicy; newest commit = 3[segments_3]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.967; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1882c281 main
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.967; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.968; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1882c281 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.968; org.apache.solr.update.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:38557/collection1/, StdNode: http://127.0.0.1:53921/collection1/, StdNode: http://127.0.0.1:34909/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.971; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.972; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30b1e5fa lockFactory=org.apache.lucene.store.NativeFSLockFactory@17d1357e),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30b1e5fa lockFactory=org.apache.lucene.store.NativeFSLockFactory@17d1357e),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.973; org.apache.solr.core.SolrDeletionPolicy; newest commit = 3[segments_3]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.973; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@2aa2718b main
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.973; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.974; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@2aa2718b main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.975; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.977; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.977; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.979; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@264b6a5a lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a72196),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@264b6a5a lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a72196),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.979; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@f6d0d90 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16252bfa),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@f6d0d90 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16252bfa),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.980; org.apache.solr.core.SolrDeletionPolicy; newest commit = 3[segments_3]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.980; org.apache.solr.core.SolrDeletionPolicy; newest commit = 3[segments_3]
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.981; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@7285e309 main
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.981; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@e112e6e main
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.981; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.982; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.982; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@e112e6e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.982; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@7285e309 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.983; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= 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-05-20 09:22:16.983; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= 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-05-20 09:22:16.984; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 20
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.985; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-20 09:22:16.988; org.apache.solr.core.SolrCore; [collection1] webapp= 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-05-20 09:22:16.990; org.apache.solr.core.SolrCore; [collection1] webapp= 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-05-20 09:22:16.991; org.apache.solr.core.SolrCore; [collection1] webapp= 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-05-20 09:22:16.993; org.apache.solr.core.SolrCore; [collection1] webapp= 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-05-20 09:22:18.999; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435544310510518272)} 0 2
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.007; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435544310515761152&update.from=http://127.0.0.1:40875/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435544310515761152)} 0 1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.010; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435544310519955456&update.from=http://127.0.0.1:38557/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435544310519955456)} 0 1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.011; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1435544310519955456)} 0 5
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.011; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435544310515761152)} 0 9
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.015; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1435544310528344064)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.019; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1435544310530441216)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.020; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1435544310530441216)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.023; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1435544310537781248)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.029; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1435544310540926976)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.030; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1435544310540926976)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.033; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1435544310548267008)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.039; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1435544310551412736)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.040; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1435544310551412736)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.043; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1435544310558752768)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.049; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1435544310562947072)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.050; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[3 (1435544310562947072)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.051; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3]} 0 5
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.053; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1435544310569238528)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.060; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1435544310574481408)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.061; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[4 (1435544310574481408)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.061; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4]} 0 5
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.064; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1435544310580772864)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.072; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1435544310586015744)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.073; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[5 (1435544310586015744)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.074; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5]} 0 7
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.076; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1435544310593355776)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.081; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1435544310596501504)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.082; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1435544310596501504)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.085; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1435544310602792960)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.092; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1435544310608035840)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.093; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[7 (1435544310608035840)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.094; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7]} 0 6
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.096; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1435544310614327296)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.101; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1435544310617473024)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.102; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1435544310617473024)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.105; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1435544310623764480)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.110; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1435544310626910208)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.111; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1435544310626910208)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.114; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1435544310633201664)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.119; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1435544310636347392)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.120; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1435544310636347392)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.123; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1435544310642638848)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.128; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1435544310645784576)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.129; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1435544310645784576)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.131; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1435544310651027456)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.136; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1435544310654173184)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.137; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1435544310654173184)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.140; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1435544310660464640)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.145; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1435544310663610368)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.146; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1435544310663610368)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.149; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1435544310669901824)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.156; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1435544310675144704)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.157; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[14 (1435544310675144704)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.157; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14]} 0 5
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.160; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1435544310681436160)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.167; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1435544310686679040)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.168; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[15 (1435544310686679040)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.168; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15]} 0 5
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.171; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1435544310692970496)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.178; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1435544310698213376)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.179; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[16 (1435544310698213376)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.179; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16]} 0 5
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.182; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1435544310704504832)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.189; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1435544310709747712)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.190; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[17 (1435544310709747712)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.191; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17]} 0 6
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.193; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1435544310716039168)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.200; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1435544310721282048)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.201; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[18 (1435544310721282048)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.202; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18]} 0 5
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.204; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1435544310727573504)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.211; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1435544310732816384)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.212; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[19 (1435544310732816384)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.212; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19]} 0 5
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.215; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1435544310739107840)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.220; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1435544310742253568)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.221; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1435544310742253568)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.224; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1435544310748545024)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.232; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1435544310753787904)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.233; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[21 (1435544310753787904)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.234; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21]} 0 7
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.236; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1435544310761127936)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.243; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1435544310766370816)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.244; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[22 (1435544310766370816)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.245; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22]} 0 6
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.247; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1435544310772662272)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.252; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1435544310775808000)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.253; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1435544310775808000)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.256; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1435544310782099456)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.261; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1435544310785245184)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.262; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1435544310785245184)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.264; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1435544310790488064)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.269; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1435544310793633792)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.270; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1435544310793633792)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.273; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1435544310799925248)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.280; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1435544310805168128)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.281; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[26 (1435544310805168128)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.282; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26]} 0 6
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.284; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1435544310811459584)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.289; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1435544310814605312)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.290; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1435544310814605312)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.293; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1435544310820896768)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.298; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1435544310824042496)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.299; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1435544310824042496)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.302; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1435544310830333952)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.307; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1435544310833479680)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.308; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1435544310833479680)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.311; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1435544310839771136)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.319; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1435544310845014016)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.320; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[30 (1435544310845014016)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.321; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30]} 0 7
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.323; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1435544310852354048)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.331; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1435544310857596928)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.332; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[31 (1435544310857596928)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.333; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31]} 0 7
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.336; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1435544310865985536)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.342; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1435544310869131264)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.343; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1435544310869131264)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.346; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1435544310876471296)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.353; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40875/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1435544310881714176)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.354; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38557/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[33 (1435544310881714176)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.355; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33]} 0 6
[junit4:junit4] 1> INFO - 2013-05-20 09:22:19.357; org.apache.solr.update.
[...truncated too long message...]
198db
[junit4:junit4] 1> INFO - 2013-05-20 09:28:54.571; 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-05-20 09:28:54.571; org.apache.solr.update.SolrCoreState; Closing SolrCoreState
[junit4:junit4] 1> INFO - 2013-05-20 09:28:54.572; org.apache.solr.update.DefaultSolrCoreState; SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 1> INFO - 2013-05-20 09:28:54.572; org.apache.solr.update.DefaultSolrCoreState; closing IndexWriter with IndexWriterCloser
[junit4:junit4] 1> INFO - 2013-05-20 09:28:54.573; org.apache.solr.core.SolrCore; [halfdeletedcollection_shard1_replica1] Closing main searcher on request.
[junit4:junit4] 1> INFO - 2013-05-20 09:28:54.573; org.apache.solr.core.CachingDirectoryFactory; Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 1> INFO - 2013-05-20 09:28:54.573; 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/J1/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369041925751/halfdeletedcollection_shard1_replica1/data [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369041925751/halfdeletedcollection_shard1_replica1/data;done=false>>]
[junit4:junit4] 1> INFO - 2013-05-20 09:28:54.574; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369041925751/halfdeletedcollection_shard1_replica1/data
[junit4:junit4] 1> INFO - 2013-05-20 09:28:54.574; 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/J1/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369041925751/halfdeletedcollection_shard1_replica1/data/index [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369041925751/halfdeletedcollection_shard1_replica1/data/index;done=false>>]
[junit4:junit4] 1> INFO - 2013-05-20 09:28:54.575; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369041925751/halfdeletedcollection_shard1_replica1/data/index
[junit4:junit4] 1> INFO - 2013-05-20 09:28:54.577; org.apache.solr.cloud.Overseer$ClusterStateUpdater; According to ZK I (id=89721531289042956-127.0.0.1:17071_t_mhp-n_0000000004) am no longer a leader.
[junit4:junit4] 1> INFO - 2013-05-20 09:28:54.579; org.eclipse.jetty.server.handler.ContextHandler; stopped o.e.j.s.ServletContextHandler{/t_mhp,null}
[junit4:junit4] 1> INFO - 2013-05-20 09:28:54.637; org.apache.solr.SolrTestCaseJ4; ###Ending testDistribSearch
[junit4:junit4] 1> INFO - 2013-05-20 09:28:54.640; org.apache.solr.cloud.ZkTestServer; connecting to 127.0.0.1:61894 61894
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.3-Java6/solr/build/solr-core/test/J1/./solrtest-CollectionsAPIDistributedZkTest-1369041920297
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=CollectionsAPIDistributedZkTest -Dtests.method=testDistribSearch -Dtests.seed=C021E6778DD94DDD -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_MA -Dtests.timezone=US/Indiana-Starke -Dtests.file.encoding=US-ASCII
[junit4:junit4] ERROR 215s J1 | CollectionsAPIDistributedZkTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:42364/t_mhp returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([C021E6778DD94DDD:41C7686FFA862DE1]: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-05-20 09:28:54.830; org.apache.solr.SolrTestCaseJ4; ###deleteCore
[junit4:junit4] 2> 214550 T1810 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 1> WARN - 2013-05-20 09:28:55.880; org.apache.solr.common.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-05-20 09:28:55.880; 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-05-20 09:28:55.880; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {timestamp=Pulsing41(freqCutoff=20 minBlockSize=36 maxBlockSize=113), range_facet_l=Pulsing41(freqCutoff=20 minBlockSize=36 maxBlockSize=113), id=PostingsFormat(name=Direct), range_facet_sl=PostingsFormat(name=Direct), a_t=Pulsing41(freqCutoff=20 minBlockSize=36 maxBlockSize=113), text=PostingsFormat(name=Memory doPackFST= false), range_facet_si=Pulsing41(freqCutoff=20 minBlockSize=36 maxBlockSize=113), _version_=PostingsFormat(name=Memory doPackFST= true), other_tl1=PostingsFormat(name=Memory doPackFST= true), multiDefault=Pulsing41(freqCutoff=20 minBlockSize=36 maxBlockSize=113), a_si=PostingsFormat(name=Memory doPackFST= true), intDefault=PostingsFormat(name=Memory doPackFST= true)}, docValues:{}, sim=DefaultSimilarity, locale=ar_MA, timezone=US/Indiana-Starke
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=4,free=189289048,total=432799744
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestFieldResource, FieldAnalysisRequestHandlerTest, TestPropInject, TestSolrQueryParserDefaultOperatorResource, DirectUpdateHandlerTest, TestMultiCoreConfBootstrap, RequestHandlersTest, TestSerializedLuceneMatchVersion, TestDefaultSimilarityFactory, ZkNodePropsTest, SolrCmdDistributorTest, TestQueryTypes, XsltUpdateRequestHandlerTest, RequiredFieldsTest, BadIndexSchemaTest, SignatureUpdateProcessorFactoryTest, TestNumberUtils, SolrIndexConfigTest, TestDistributedGrouping, TestPartialUpdateDeduplication, TestSolrXMLSerializer, TestLMJelinekMercerSimilarityFactory, TestBM25SimilarityFactory, SuggesterWFSTTest, TestHashPartitioner, SortByFunctionTest, TestBinaryField, TestUtils, ConvertedLegacyTest, BadCopyFieldTest, EchoParamsTest, IndexSchemaRuntimeFieldTest, TermVectorComponentDistributedTest, TestFoldingMultitermQuery, OutputWriterTest, TestDynamicFieldResource, TestDFRSimilarityFactory, SolrCoreCheckLockOnStartupTest, HardAutoCommitTest, DocValuesMultiTest, TestFastOutputStream, TestArbitraryIndexDir, DocumentAnalysisRequestHandlerTest, TestLuceneMatchVersion, TestSchemaSimilarityResource, TestSuggestSpellingConverter, IndexBasedSpellCheckerTest, TestAnalyzedSuggestions, TestSolr4Spatial, FileUtilsTest, TestCollationField, DateMathParserTest, CurrencyFieldOpenExchangeTest, TestCodecSupport, SpellPossibilityIteratorTest, FullSolrCloudDistribCmdsTest, TestSchemaVersionResource, UpdateParamsTest, TestJmxMonitoredMap, NumericFieldsTest, TestStressReorder, CopyFieldTest, NotRequiredUniqueKeyTest, ClusterStateTest, ShardSplitTest, TestCSVResponseWriter, TestComponentsName, ChaosMonkeySafeLeaderTest, BasicDistributedZk2Test, CollectionsAPIDistributedZkTest]
[junit4:junit4] Completed on J1 in 215.84s, 1 test, 1 error <<< FAILURES!
[...truncated 449 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: 291 suites, 1206 tests, 2 errors, 27 ignored (8 assumptions)
Total time: 46 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