You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/04/15 04:54:18 UTC
[JENKINS] Lucene-Solr-Tests-trunk-java7 - Build # 3889 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-java7/3889/
1 tests failed.
FAILED: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Wrong doc count on shard1_1 expected:<324> but was:<325>
Stack Trace:
java.lang.AssertionError: Wrong doc count on shard1_1 expected:<324> but was:<325>
at __randomizedtesting.SeedInfo.seed([1AC4C091FB3BB78D:9B224E898C64D7B1]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.apache.solr.cloud.ShardSplitTest.checkDocCountsAndShardStates(ShardSplitTest.java:155)
at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:154)
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:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9739 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.586; org.apache.solr.BaseDistributedSearchTestCase; Setting hostContext system property: /rv_lw/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.592; org.apache.solr.SolrTestCaseJ4; ###Starting testDistribSearch
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.594; org.apache.solr.cloud.ZkTestServer; STARTING ZK TEST SERVER
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.595; org.apache.solr.cloud.ZkTestServer$ZKServerMain; Starting server
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.696; org.apache.solr.cloud.ZkTestServer; start zk server on port:29486
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.698; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.704; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@42fb0e77 name:ZooKeeperConnection Watcher:127.0.0.1:29486 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.704; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.705; org.apache.solr.common.cloud.SolrZkClient; makePath: /solr
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.712; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.723; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@310b5ee2 name:ZooKeeperConnection Watcher:127.0.0.1:29486/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.724; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.725; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.730; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/shards
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.733; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.742; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/shards
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.746; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.747; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.761; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.762; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.867; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.869; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.873; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.874; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.882; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.883; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.887; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.888; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.891; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.893; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.896; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.897; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.901; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-15 02:47:01.902; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.130; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.135; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:29489
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.136; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.137; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.137; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1365994021908
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.138; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1365994021908/solr.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.139; org.apache.solr.core.CoreContainer; New CoreContainer 1654657807
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.140; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1365994021908/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.140; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1365994021908/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.219; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.220; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.221; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.221; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.222; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.223; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.223; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.224; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.225; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.225; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.251; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.273; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:29486/solr
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.274; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.275; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.279; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@75a53f24 name:ZooKeeperConnection Watcher:127.0.0.1:29486 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.279; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.291; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.304; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.306; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@2ea57316 name:ZooKeeperConnection Watcher:127.0.0.1:29486/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.307; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.310; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.321; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/collection-queue-work
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.325; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.328; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:29489_rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.334; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:29489_rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.339; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/election
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.361; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/leader
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.365; org.apache.solr.cloud.Overseer; Overseer (id=89521784199643139-127.0.0.1:29489_rv_lw-n_0000000000) starting
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.378; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue-work
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.390; org.apache.solr.cloud.OverseerCollectionProcessor; Process current queue of collection creations
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.391; org.apache.solr.common.cloud.SolrZkClient; makePath: /clusterstate.json
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.395; org.apache.solr.common.cloud.SolrZkClient; makePath: /aliases.json
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.398; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.403; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Starting to work on the main queue
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.406; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1365994021908/collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.407; org.apache.solr.cloud.ZkController; Check for collection zkNode:control_collection
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.408; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.408; org.apache.solr.cloud.ZkController; Load collection config from:/collections/control_collection
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.410; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1365994021908/collection1/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.412; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1365994021908/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.413; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1365994021908/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.470; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.535; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.637; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:02.656; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.396; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.409; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.414; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.433; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.441; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.448; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-15 02:47:03.449; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-15 02:47:03.450; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.450; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-15 02:47:03.451; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-15 02:47:03.452; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.452; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.453; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1365994021908/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/control/data/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.453; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@66b6983c
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.454; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.455; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/control/data
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.456; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/control/data/index/
[junit4:junit4] 1> WARN - 2013-04-15 02:47:03.456; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.457; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/control/data/index
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.461; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@53237e60 lockFactory=org.apache.lucene.store.NativeFSLockFactory@67708b2b),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.461; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.465; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.466; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.467; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.467; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.468; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.469; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.469; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.470; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.470; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.486; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.494; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@57d7a67 main
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.495; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/control/data/tlog
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.496; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.497; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.501; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@57d7a67 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.504; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.505; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.908; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.909; 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:29489_rv_lw",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:29489/rv_lw"}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.909; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection control_collection with numShards 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.910; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:03.962; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:04.508; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:04.508; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:29489/rv_lw collection:control_collection shard:shard1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:04.510; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-04-15 02:47:04.540; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:04.552; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:04.553; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-04-15 02:47:04.553; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:29489/rv_lw/collection1/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:04.554; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-04-15 02:47:04.554; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:29489/rv_lw/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-04-15 02:47:04.555; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:29489/rv_lw/collection1/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:04.555; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.479; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.529; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.591; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:29489/rv_lw/collection1/ and leader is http://127.0.0.1:29489/rv_lw/collection1/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.591; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:29489/rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.592; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.592; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.593; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.595; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.596; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.598; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.598; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.614; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.616; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.619; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@7020c30e name:ZooKeeperConnection Watcher:127.0.0.1:29486/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.620; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.623; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.626; org.apache.solr.cloud.ChaosMonkey; monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.850; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.853; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:29493
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.854; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.855; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.855; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365994025627
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.856; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365994025627/solr.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.857; org.apache.solr.core.CoreContainer; New CoreContainer 509844958
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.858; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365994025627/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.858; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365994025627/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.935; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.936; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.936; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.937; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.938; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.938; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.939; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.940; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.940; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.941; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.966; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.988; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:29486/solr
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.989; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.991; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.994; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@49c00fc9 name:ZooKeeperConnection Watcher:127.0.0.1:29486 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-15 02:47:05.995; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:06.008; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:06.024; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:06.027; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@972713a name:ZooKeeperConnection Watcher:127.0.0.1:29486/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-15 02:47:06.028; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:06.040; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.044; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.045; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:29493_rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.052; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:29493_rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.052; 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:29489_rv_lw",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:29489/rv_lw"}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.058; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.058; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.070; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.070; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.074; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.075; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.076; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365994025627/collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.076; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.076; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.077; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.078; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.079; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365994025627/collection1/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.081; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365994025627/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.082; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365994025627/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.137; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.203; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.305; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:07.333; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.065; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.076; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.080; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.103; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.110; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.120; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-15 02:47:08.123; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-15 02:47:08.364; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.366; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-15 02:47:08.367; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-15 02:47:08.368; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.368; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.369; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365994025627/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty1/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.370; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@66b6983c
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.371; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.372; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.372; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty1/index/
[junit4:junit4] 1> WARN - 2013-04-15 02:47:08.373; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.373; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty1/index
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.378; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6992881d lockFactory=org.apache.lucene.store.NativeFSLockFactory@6d2940b9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.378; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.383; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.383; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.384; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.385; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.386; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.387; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.388; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.389; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.389; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.405; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.413; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@5c09720f main
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.414; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty1/tlog
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.416; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.416; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.424; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@5c09720f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.428; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.429; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.576; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.577; 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:29493_rv_lw",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:29493/rv_lw"}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.577; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection collection1 with numShards 2
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.577; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.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: 2)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.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: 2)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:08.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: 2)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:09.432; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:09.432; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:29493/rv_lw collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:09.433; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-04-15 02:47:09.459; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:09.462; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:09.462; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-04-15 02:47:09.463; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:29493/rv_lw/collection1/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:09.463; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-04-15 02:47:09.464; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:29493/rv_lw/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-04-15 02:47:09.464; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:29493/rv_lw/collection1/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:09.464; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.196; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.240; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.240; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.240; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.287; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:29493/rv_lw/collection1/ and leader is http://127.0.0.1:29493/rv_lw/collection1/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.287; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:29493/rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.288; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.288; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.288; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.291; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.292; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.293; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.294; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.538; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.541; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:49655
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.543; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.543; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.544; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365994030313
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.545; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365994030313/solr.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.546; org.apache.solr.core.CoreContainer; New CoreContainer 762187434
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.546; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365994030313/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.547; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365994030313/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.619; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.620; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.621; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.622; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.622; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.623; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.624; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.624; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.625; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.626; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.649; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.671; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:29486/solr
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.672; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.673; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.676; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@35519eee name:ZooKeeperConnection Watcher:127.0.0.1:29486 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.677; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.680; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.694; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.696; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@5a9402cc name:ZooKeeperConnection Watcher:127.0.0.1:29486/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.697; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:10.708; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.712; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49655_rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.717; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:49655_rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.721; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.721; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.721; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.721; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.721; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.722; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.723; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.735; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365994030313/collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.735; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.736; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.736; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.738; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365994030313/collection1/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.740; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365994030313/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.740; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365994030313/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.754; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.755; 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:29493_rv_lw",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:29493/rv_lw"}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.767; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.767; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.767; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.767; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.792; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.838; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.939; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:11.957; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.643; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.654; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.658; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.673; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.679; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.684; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-15 02:47:12.686; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-15 02:47:12.688; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.688; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-15 02:47:12.722; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-15 02:47:12.723; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.723; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.724; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365994030313/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty2/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.724; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@66b6983c
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.725; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.726; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty2
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.726; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty2/index/
[junit4:junit4] 1> WARN - 2013-04-15 02:47:12.726; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.727; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty2/index
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.730; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6b22b9c lockFactory=org.apache.lucene.store.NativeFSLockFactory@13e703b6),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.731; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.734; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.734; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.735; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.736; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.737; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.738; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.738; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.739; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.740; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.752; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.758; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@11e05f68 main
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.759; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty2/tlog
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.760; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.760; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.766; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@11e05f68 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.769; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-15 02:47:12.770; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.271; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.272; 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:49655_rv_lw",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:49655/rv_lw"}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.273; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.273; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.287; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.287; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.287; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.287; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.773; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.773; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:49655/rv_lw collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.775; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.878; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.904; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.905; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.905; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:49655/rv_lw/collection1/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.906; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.906; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:49655/rv_lw/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.906; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:49655/rv_lw/collection1/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:13.907; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 1> INFO - 2013-04-15 02:47:14.792; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:14.830; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:14.830; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:14.830; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:14.830; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:14.836; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:49655/rv_lw/collection1/ and leader is http://127.0.0.1:49655/rv_lw/collection1/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:14.836; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49655/rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:14.836; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-04-15 02:47:14.837; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-15 02:47:14.837; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-15 02:47:14.847; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:14.848; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:14.849; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-15 02:47:14.850; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.073; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.076; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:31174
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.077; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.078; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.078; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365994034865
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.079; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365994034865/solr.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.080; org.apache.solr.core.CoreContainer; New CoreContainer 126966583
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.081; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365994034865/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.081; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365994034865/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.153; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.154; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.155; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.155; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.156; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.157; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.157; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.158; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.159; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.159; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.180; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.201; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:29486/solr
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.202; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.204; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.207; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@37903b59 name:ZooKeeperConnection Watcher:127.0.0.1:29486 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.207; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.211; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.222; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.224; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1e8d8eaa name:ZooKeeperConnection Watcher:127.0.0.1:29486/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.224; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:15.236; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.239; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:31174_rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.245; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:31174_rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.250; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.250; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.250; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.250; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.250; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.250; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.251; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.250; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.252; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.258; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365994034865/collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.258; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.259; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.260; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.261; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365994034865/collection1/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.263; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365994034865/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.263; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365994034865/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.317; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.348; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.349; 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:49655_rv_lw",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:49655/rv_lw"}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.354; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.354; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.354; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.354; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.354; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.387; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.489; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:16.503; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.169; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.180; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.184; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.200; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.208; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.216; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-15 02:47:17.218; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-15 02:47:17.220; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.220; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-15 02:47:17.222; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-15 02:47:17.222; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.223; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.224; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365994034865/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty3/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.224; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@66b6983c
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.225; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.227; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.227; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty3/index/
[junit4:junit4] 1> WARN - 2013-04-15 02:47:17.228; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.229; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty3/index
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.233; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4345e997 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4cfa6cfc),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.233; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.238; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.239; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.240; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.241; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.243; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.243; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.244; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.245; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.246; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.261; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.267; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@50cddb3e main
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.267; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty3/tlog
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.268; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.269; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.275; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@50cddb3e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.279; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.280; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.868; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.870; 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:31174_rv_lw",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:31174/rv_lw"}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.870; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.870; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.883; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.883; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.883; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.883; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:17.883; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.283; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.283; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:31174/rv_lw collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.286; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:31174/rv_lw/collection1/ and leader is http://127.0.0.1:29493/rv_lw/collection1/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.287; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:31174/rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.287; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.287; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.288; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.288; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.290; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.291; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.291; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.291; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.292; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.292; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.293; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.315; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.536; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.540; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:26928
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.540; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.541; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.542; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365994038313
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.543; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365994038313/solr.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.543; org.apache.solr.core.CoreContainer; New CoreContainer 163798032
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.544; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365994038313/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.545; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365994038313/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.624; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.625; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.626; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.626; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.627; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.628; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.628; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.629; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.630; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.630; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.652; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.673; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:29486/solr
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.674; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.676; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.730; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@5e62fb22 name:ZooKeeperConnection Watcher:127.0.0.1:29486 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.731; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.779; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.790; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.803; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@31925428 name:ZooKeeperConnection Watcher:127.0.0.1:29486/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.804; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-15 02:47:18.910; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.388; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.389; 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:31174_rv_lw",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:31174/rv_lw"}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.402; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.402; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.402; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.402; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.402; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.402; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.915; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:26928_rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.918; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:26928_rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.921; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.921; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.922; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.922; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.921; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.921; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.921; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.923; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.923; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.922; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.924; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.931; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.936; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365994038313/collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.936; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.937; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.937; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.939; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365994038313/collection1/'
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.941; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365994038313/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.942; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365994038313/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-15 02:47:19.994; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.057; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.158; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.170; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.317; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.318; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:31174_rv_lw&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2004
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.879; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.892; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.897; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.911; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.917; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.922; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-15 02:47:20.924; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-15 02:47:20.926; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.926; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-15 02:47:20.927; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-15 02:47:20.928; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.928; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.929; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365994038313/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.929; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@66b6983c
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.930; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.931; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.931; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4/index/
[junit4:junit4] 1> WARN - 2013-04-15 02:47:20.932; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.932; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4/index
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.936; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6dcbad13 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1579c85f),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.936; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.940; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.940; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.941; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.942; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.943; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.943; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.944; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.944; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.945; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.959; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.966; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@3b0ffce7 main
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.966; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4/tlog
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.967; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.968; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.972; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@3b0ffce7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.975; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-15 02:47:20.975; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.320; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:29493/rv_lw/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.320; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:31174/rv_lw START replicas=[http://127.0.0.1:29493/rv_lw/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-04-15 02:47:22.321; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.322; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.322; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.322; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.322; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.323; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:29493/rv_lw/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.323; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.329; org.apache.solr.core.SolrCore; [collection1] webapp=/rv_lw path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.338; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.341; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6992881d lockFactory=org.apache.lucene.store.NativeFSLockFactory@6d2940b9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.342; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.343; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6992881d lockFactory=org.apache.lucene.store.NativeFSLockFactory@6d2940b9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6992881d lockFactory=org.apache.lucene.store.NativeFSLockFactory@6d2940b9),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.343; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.344; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@52722b7 realtime
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.345; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.345; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.346; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.347; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.350; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.350; org.apache.solr.core.SolrCore; [collection1] webapp=/rv_lw path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.351; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.351; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.352; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.354; org.apache.solr.core.SolrCore; [collection1] webapp=/rv_lw path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.355; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.356; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty3/index.20130414224722355
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.356; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@617db50 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c5d49a1) fullCopy=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.359; org.apache.solr.core.SolrCore; [collection1] webapp=/rv_lw 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-04-15 02:47:22.360; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.361; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.362; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.364; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4345e997 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4cfa6cfc),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4345e997 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4cfa6cfc),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.364; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.365; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.365; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@5910e260 main
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.366; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@5910e260 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.367; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty3/index.20130414224722355 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty3/index.20130414224722355;done=true>>]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.368; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty3/index.20130414224722355
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.368; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty3/index.20130414224722355
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.368; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.369; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.369; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.369; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.378; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.409; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.410; 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:26928_rv_lw",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:26928/rv_lw"}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.411; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.411; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.414; 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:31174_rv_lw",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:31174/rv_lw"}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.418; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.419; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.418; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.418; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.418; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.418; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.979; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.979; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:26928/rv_lw collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.985; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:26928/rv_lw/collection1/ and leader is http://127.0.0.1:49655/rv_lw/collection1/
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.985; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:26928/rv_lw
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.986; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.986; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.987; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.987; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.989; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.990; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.990; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.990; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.992; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.992; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-15 02:47:22.994; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:23.006; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-04-15 02:47:23.008; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:23.009; org.apache.solr.cloud.AbstractFullDistribZkTestBase; Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 1> INFO - 2013-04-15 02:47:23.009; org.apache.solr.cloud.AbstractDistribZkTestBase; Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 1> INFO - 2013-04-15 02:47:23.010; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:23.926; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:23.927; 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:26928_rv_lw",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:26928/rv_lw"}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:23.955; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:23.955; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:23.955; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:23.955; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:23.955; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:23.955; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:24.008; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:24.009; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:26928_rv_lw&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1003
[junit4:junit4] 1> INFO - 2013-04-15 02:47:24.012; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:25.015; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.011; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:49655/rv_lw/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.011; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:26928/rv_lw START replicas=[http://127.0.0.1:49655/rv_lw/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-04-15 02:47:26.012; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.012; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.012; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.012; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.013; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.014; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:49655/rv_lw/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.014; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.018; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.020; org.apache.solr.core.SolrCore; [collection1] webapp=/rv_lw path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.023; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.025; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6b22b9c lockFactory=org.apache.lucene.store.NativeFSLockFactory@13e703b6),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.026; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.026; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6b22b9c lockFactory=org.apache.lucene.store.NativeFSLockFactory@13e703b6),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6b22b9c lockFactory=org.apache.lucene.store.NativeFSLockFactory@13e703b6),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.027; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.027; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@58541921 realtime
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.028; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.028; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw 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-04-15 02:47:26.029; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.029; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.031; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.031; org.apache.solr.core.SolrCore; [collection1] webapp=/rv_lw path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.032; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.032; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.032; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.035; org.apache.solr.core.SolrCore; [collection1] webapp=/rv_lw path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.036; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.037; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4/index.20130414224726036
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.037; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@74b248e0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@24637102) fullCopy=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.040; org.apache.solr.core.SolrCore; [collection1] webapp=/rv_lw 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-04-15 02:47:26.041; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.042; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.042; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.043; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6dcbad13 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1579c85f),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6dcbad13 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1579c85f),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.044; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.044; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.044; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@41bdb131 main
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.045; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@41bdb131 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.045; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4/index.20130414224726036 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4/index.20130414224726036;done=true>>]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.046; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4/index.20130414224726036
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.046; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4/index.20130414224726036
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.046; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.046; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.047; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.047; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.048; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.962; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.964; 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:26928_rv_lw",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:26928/rv_lw"}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.976; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.976; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.976; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.976; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.976; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:26.976; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.020; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.021; org.apache.solr.cloud.AbstractDistribZkTestBase; Recoveries finished - collection: collection1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.029; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.033; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@53237e60 lockFactory=org.apache.lucene.store.NativeFSLockFactory@67708b2b),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.034; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.035; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@53237e60 lockFactory=org.apache.lucene.store.NativeFSLockFactory@67708b2b),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@53237e60 lockFactory=org.apache.lucene.store.NativeFSLockFactory@67708b2b),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.036; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.036; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@29a03ce2 main
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.037; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.038; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@29a03ce2 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.039; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.056; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.059; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6b22b9c lockFactory=org.apache.lucene.store.NativeFSLockFactory@13e703b6),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6b22b9c lockFactory=org.apache.lucene.store.NativeFSLockFactory@13e703b6),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.060; org.apache.solr.core.SolrDeletionPolicy; newest commit = 3[segments_3]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.060; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@6d8c7f10 main
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.061; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.062; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@6d8c7f10 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.063; org.apache.solr.update.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:29493/rv_lw/collection1/, StdNode: http://127.0.0.1:31174/rv_lw/collection1/, StdNode: http://127.0.0.1:26928/rv_lw/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.067; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.068; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6992881d lockFactory=org.apache.lucene.store.NativeFSLockFactory@6d2940b9),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6992881d lockFactory=org.apache.lucene.store.NativeFSLockFactory@6d2940b9),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.069; org.apache.solr.core.SolrDeletionPolicy; newest commit = 3[segments_3]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.070; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@248943be main
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.070; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.071; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@248943be main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.073; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw 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-04-15 02:47:27.074; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.074; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.075; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6dcbad13 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1579c85f),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6dcbad13 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1579c85f),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.075; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4345e997 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4cfa6cfc),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4345e997 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4cfa6cfc),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.076; org.apache.solr.core.SolrDeletionPolicy; newest commit = 3[segments_3]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.076; org.apache.solr.core.SolrDeletionPolicy; newest commit = 3[segments_3]
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.077; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@19567e75 main
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.078; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@7c36c639 main
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.078; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.079; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@19567e75 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.079; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.080; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.079; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@7c36c639 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.081; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.082; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 26
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.084; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.086; org.apache.solr.core.SolrCore; [collection1] webapp=/rv_lw path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.089; org.apache.solr.core.SolrCore; [collection1] webapp=/rv_lw path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.090; org.apache.solr.core.SolrCore; [collection1] webapp=/rv_lw path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:27.093; org.apache.solr.core.SolrCore; [collection1] webapp=/rv_lw path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.098; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1432348576025935872)} 0 2
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.106; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={update.distrib=FROMLEADER&_version_=-1432348576031178752&update.from=http://127.0.0.1:49655/rv_lw/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1432348576031178752)} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.110; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={update.distrib=FROMLEADER&_version_=-1432348576034324480&update.from=http://127.0.0.1:29493/rv_lw/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1432348576034324480)} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.111; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1432348576034324480)} 0 6
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.111; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1432348576031178752)} 0 9
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.115; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[0 (1432348576043761664)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.121; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1432348576046907392)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.121; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[0 (1432348576046907392)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.125; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[1 (1432348576054247424)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.133; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1432348576060538880)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.134; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1432348576060538880)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.135; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[1]} 0 7
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.137; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[2 (1432348576067878912)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.145; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1432348576072073216)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.145; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[2 (1432348576072073216)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.146; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[2]} 0 6
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.148; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[3 (1432348576079413248)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.153; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1432348576082558976)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.154; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[3 (1432348576082558976)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.156; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[4 (1432348576087801856)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.164; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1432348576093044736)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.165; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[4 (1432348576093044736)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.166; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[4]} 0 7
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.168; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[5 (1432348576100384768)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.175; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1432348576105627648)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.176; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[5 (1432348576105627648)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.176; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[5]} 0 5
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.179; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[6 (1432348576111919104)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.186; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1432348576117161984)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.187; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[6 (1432348576117161984)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.188; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[6]} 0 6
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.190; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[7 (1432348576123453440)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.195; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1432348576126599168)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.196; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[7 (1432348576126599168)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.199; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[8 (1432348576132890624)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.207; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1432348576138133504)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.208; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1432348576138133504)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.209; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[8]} 0 7
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.211; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[9 (1432348576145473536)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.218; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1432348576150716416)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.219; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[9 (1432348576150716416)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.220; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[9]} 0 6
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.222; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[10 (1432348576157007872)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.229; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1432348576162250752)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.230; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (1432348576162250752)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.230; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[10]} 0 5
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.234; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[11 (1432348576168542208)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.241; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1432348576174833664)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.242; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[11 (1432348576174833664)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.242; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[11]} 0 5
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.246; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[12 (1432348576181125120)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.251; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1432348576185319424)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.252; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[12 (1432348576185319424)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.255; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[13 (1432348576190562304)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.260; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1432348576194756608)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.261; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[13 (1432348576194756608)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.264; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[14 (1432348576199999488)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.271; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1432348576206290944)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.272; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[14 (1432348576206290944)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.273; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[14]} 0 6
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.276; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[15 (1432348576212582400)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.280; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1432348576215728128)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.281; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[15 (1432348576215728128)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.285; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[16 (1432348576222019584)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.292; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1432348576227262464)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.292; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[16 (1432348576227262464)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.293; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[16]} 0 6
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.296; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[17 (1432348576233553920)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.300; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1432348576236699648)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.301; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[17 (1432348576236699648)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.305; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[18 (1432348576242991104)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.309; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1432348576246136832)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.310; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[18 (1432348576246136832)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.314; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[19 (1432348576252428288)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.318; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1432348576255574016)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.319; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[19 (1432348576255574016)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.322; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[20 (1432348576260816896)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.329; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1432348576266059776)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.330; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[20 (1432348576266059776)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.331; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[20]} 0 7
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.334; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[21 (1432348576273399808)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.338; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1432348576276545536)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.339; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[21 (1432348576276545536)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.343; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[22 (1432348576282836992)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.350; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1432348576288079872)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.350; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[22 (1432348576288079872)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.351; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[22]} 0 6
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.354; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[23 (1432348576294371328)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.362; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1432348576300662784)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.363; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[23 (1432348576300662784)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.363; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[23]} 0 6
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.367; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[24 (1432348576308002816)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.375; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1432348576314294272)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.376; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[24 (1432348576314294272)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.376; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[24]} 0 6
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.380; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[25 (1432348576321634304)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.386; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1432348576325828608)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.387; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[25 (1432348576325828608)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.390; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[26 (1432348576332120064)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.397; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1432348576338411520)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.398; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[26 (1432348576338411520)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.399; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[26]} 0 6
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.402; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[27 (1432348576344702976)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.411; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1432348576352043008)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.412; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[27 (1432348576352043008)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.413; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[27]} 0 7
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.416; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[28 (1432348576359383040)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.424; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1432348576365674496)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.425; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[28 (1432348576365674496)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.425; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[28]} 0 6
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.429; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[29 (1432348576373014528)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.434; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1432348576377208832)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.435; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[29 (1432348576377208832)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.439; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[30 (1432348576383500288)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.447; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:49655/rv_lw/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1432348576389791744)]} 0 0
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.448; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={distrib.from=http://127.0.0.1:29493/rv_lw/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[30 (1432348576389791744)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.448; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&version=2} {add=[30]} 0 6
[junit4:junit4] 1> INFO - 2013-04-15 02:47:29.452; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rv_lw path=/update params={wt=javabin&v
[...truncated too long message...]
.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4
[junit4:junit4] 1> INFO - 2013-04-15 02:51:16.137; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4/index;done=false>>]
[junit4:junit4] 1> INFO - 2013-04-15 02:51:16.137; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365994021593/jetty4/index
[junit4:junit4] 1> INFO - 2013-04-15 02:51:16.137; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 1> WARN - 2013-04-15 02:51:16.138; org.apache.solr.cloud.LeaderElector$1;
[junit4:junit4] 1> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election/89521784199643148-5-n_0000000001
[junit4:junit4] 1> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 1> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 1> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4:junit4] 1> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:152)
[junit4:junit4] 1> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:149)
[junit4:junit4] 1> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 1> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:149)
[junit4:junit4] 1> at org.apache.solr.cloud.ElectionContext.cancelElection(ElectionContext.java:63)
[junit4:junit4] 1> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:246)
[junit4:junit4] 1> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4] 1> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[junit4:junit4] 1> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 1> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 1> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 1> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 1> INFO - 2013-04-15 02:51:16.139; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> WARN - 2013-04-15 02:51:16.139; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-04-15 02:51:16.140; org.apache.solr.common.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-04-15 02:51:16.140; org.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> WARN - 2013-04-15 02:51:16.140; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-04-15 02:51:16.141; org.apache.solr.cloud.LeaderElector$1;
[junit4:junit4] 1> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 1> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 1> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 1> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 1> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 1> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 1> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 1> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 1> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 1> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 1> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 1> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 1> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2> NOTE: test params are: codec=CheapBastard, sim=DefaultSimilarity, locale=bg_BG, timezone=America/St_Thomas
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Oracle Corporation 1.7.0_17 (64-bit)/cpus=16,threads=3,free=116898352,total=511705088
[junit4:junit4] 2> NOTE: All tests run in this JVM: [ClusterStateTest, DocumentAnalysisRequestHandlerTest, CollectionsAPIDistributedZkTest, TestSchemaVersionResource, HardAutoCommitTest, LeaderElectionIntegrationTest, MultiTermTest, TestCSVResponseWriter, TestRangeQuery, TestSerializedLuceneMatchVersion, JSONWriterTest, PingRequestHandlerTest, TestMergePolicyConfig, IndexReaderFactoryTest, RequestHandlersTest, TestPartialUpdateDeduplication, TestSystemIdResolver, DateMathParserTest, TestAtomicUpdateErrorCases, FullSolrCloudDistribCmdsTest, TestReload, TestIndexSearcher, ConvertedLegacyTest, StandardRequestHandlerTest, TestDefaultSimilarityFactory, SampleTest, HighlighterTest, StatsComponentTest, TestLMJelinekMercerSimilarityFactory, OpenCloseCoreStressTest, TestCodecSupport, DocValuesMultiTest, TestSchemaNameResource, DebugComponentTest, ZkNodePropsTest, TestQuerySenderNoQuery, DisMaxRequestHandlerTest, TestQueryTypes, TestUtils, IndexBasedSpellCheckerTest, TestCoreDiscovery, TestSolrXMLSerializer, DefaultValueUpdateProcessorTest, TestZkChroot, TestElisionMultitermQuery, CurrencyFieldOpenExchangeTest, DirectSolrSpellCheckerTest, TestBM25SimilarityFactory, XmlUpdateRequestHandlerTest, BasicZkTest, TimeZoneUtilsTest, ShardRoutingCustomTest, URLClassifyProcessorTest, SolrIndexConfigTest, TestLazyCores, SolrRequestParserTest, TestJmxIntegration, XsltUpdateRequestHandlerTest, UpdateParamsTest, TestPropInject, TermVectorComponentDistributedTest, TestMultiCoreConfBootstrap, SimplePostToolTest, FieldAnalysisRequestHandlerTest, DirectUpdateHandlerTest, TestRandomFaceting, TestFoldingMultitermQuery, UniqFieldsUpdateProcessorFactoryTest, ChaosMonkeySafeLeaderTest, UnloadDistributedZkTest, RecoveryZkTest, TestReplicationHandler, ZkSolrClientTest, TestDistributedSearch, TestFaceting, TestHashPartitioner, TestStressReorder, SpellCheckComponentTest, SolrCmdDistributorTest, PeerSyncTest, BadIndexSchemaTest, TestSort, TestFunctionQuery, BasicFunctionalityTest, OverseerCollectionProcessorTest, SoftAutoCommitTest, CurrencyFieldXmlFileTest, SolrIndexSplitterTest, SignatureUpdateProcessorFactoryTest, SpellCheckCollatorTest, TestStressLucene, SpatialFilterTest, TestCSVLoader, SolrCoreCheckLockOnStartupTest, TestUpdate, DirectUpdateHandlerOptimizeTest, SortByFunctionTest, DistanceFunctionTest, TestOmitPositions, DocumentBuilderTest, TestIndexingPerformance, TestSolrQueryParser, FastVectorHighlighterTest, IndexSchemaRuntimeFieldTest, RegexBoostProcessorTest, TestCollationField, MBeansHandlerTest, CSVRequestHandlerTest, SearchHandlerTest, TestBinaryResponseWriter, SOLR749Test, TestSolrIndexConfig, BadComponentTest, TestBinaryField, NumericFieldsTest, MinimalSchemaTest, TestConfig, OutputWriterTest, TestFuzzyAnalyzedSuggestions, ExternalFileFieldSortTest, TestSolrCoreProperties, TestPostingsSolrHighlighter, DirectSolrConnectionTest, NotRequiredUniqueKeyTest, TestLuceneMatchVersion, TestPhraseSuggestions, SpellPossibilityIteratorTest, TestCharFilters, TestXIncludeConfig, EchoParamsTest, TestDFRSimilarityFactory, TestNumberUtils, TestLMDirichletSimilarityFactory, TestJmxMonitoredMap, TestPluginEnable, TestFastOutputStream, OpenExchangeRatesOrgProviderTest, PluginInfoTest, PrimUtilsTest, TestSuggestSpellingConverter, SpellingQueryConverterTest, DOMUtilTest, TestSolrJ, TestDocumentBuilder, SliceStateTest, FileUtilsTest, TestRTGBase, SolrTestCaseJ4Test, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J1 in 255.35s, 1 test, 1 failure <<< FAILURES!
[...truncated 25 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:375: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:355: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build.xml:183: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/common-build.xml:438: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:1231: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:875: There were test failures: 289 suites, 1201 tests, 1 failure, 27 ignored (8 assumptions)
Total time: 46 minutes 17 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure