You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/05/15 04:43:06 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1616 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1616/
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:52398/rrmz/r returned non ok status:500, message:Server Error
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:52398/rrmz/r returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([F747ADDCF737337F:76A123C480685343]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:679)
Build Log:
[...truncated 9095 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 1> INFO - 2013-05-15 02:17:31.927; org.apache.solr.BaseDistributedSearchTestCase; Setting hostContext system property: /rrmz/r
[junit4:junit4] 1> INFO - 2013-05-15 02:17:31.931; org.apache.solr.SolrTestCaseJ4; ###Starting testDistribSearch
[junit4:junit4] 1> INFO - 2013-05-15 02:17:31.932; org.apache.solr.cloud.ZkTestServer; STARTING ZK TEST SERVER
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:31.933; org.apache.solr.cloud.ZkTestServer$ZKServerMain; Starting server
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.034; org.apache.solr.cloud.ZkTestServer; start zk server on port:57167
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.035; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.042; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@109e7b6d name:ZooKeeperConnection Watcher:127.0.0.1:57167 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.042; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.043; org.apache.solr.common.cloud.SolrZkClient; makePath: /solr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.053; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.055; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@60e4b5a name:ZooKeeperConnection Watcher:127.0.0.1:57167/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.055; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.055; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.059; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/shards
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.071; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.074; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/shards
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.077; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.078; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.088; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.089; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.192; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.193; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.203; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.204; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.207; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.208; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.212; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.212; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.215; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.216; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.219; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.220; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.223; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.224; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.403; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.410; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:57170
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.411; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.411; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.412; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368584252235
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.412; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368584252235/solr.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.412; org.apache.solr.core.CoreContainer; New CoreContainer 965526079
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.413; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368584252235/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.413; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368584252235/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.497; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.497; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.497; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.498; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.498; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.498; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.499; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.499; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.499; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.500; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.512; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.512; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:57167/solr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.512; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.513; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.516; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@205b4aa9 name:ZooKeeperConnection Watcher:127.0.0.1:57167 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.516; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.518; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.527; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.530; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@6552fec6 name:ZooKeeperConnection Watcher:127.0.0.1:57167/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.530; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.532; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.543; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/collection-queue-work
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.547; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.549; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57170_rrmz%2Fr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.551; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:57170_rrmz%2Fr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.560; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/election
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.573; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/leader
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.587; org.apache.solr.cloud.Overseer; Overseer (id=89691537534943235-127.0.0.1:57170_rrmz%2Fr-n_0000000000) starting
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.597; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue-work
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.609; org.apache.solr.cloud.OverseerCollectionProcessor; Process current queue of collection creations
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.610; org.apache.solr.common.cloud.SolrZkClient; makePath: /clusterstate.json
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.613; org.apache.solr.common.cloud.SolrZkClient; makePath: /aliases.json
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.615; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.619; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Starting to work on the main queue
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.621; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368584252235/collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.622; org.apache.solr.cloud.ZkController; Check for collection zkNode:control_collection
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.622; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.623; org.apache.solr.cloud.ZkController; Load collection config from:/collections/control_collection
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.624; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368584252235/collection1/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.625; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368584252235/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.626; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368584252235/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.664; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.706; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.808; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:32.814; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.280; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.284; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.287; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.292; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.318; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.318; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368584252235/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/control/data/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.318; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4440ece0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.319; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.319; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/control/data
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.319; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/control/data/index/
[junit4:junit4] 1> WARN - 2013-05-15 02:17:33.319; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.320; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/control/data/index
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.322; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6064d97e lockFactory=org.apache.lucene.store.NativeFSLockFactory@7984f946),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.323; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.325; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.325; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.325; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.326; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.326; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.326; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.326; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.327; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.327; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.332; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.336; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1ab166ea main
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.337; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/control/data/tlog
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.338; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.338; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.340; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1ab166ea main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.341; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-15 02:17:33.341; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.124; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.126; 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:57170_rrmz%2Fr",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:57170/rrmz/r"}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.126; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection control_collection with numShards 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.126; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.168; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.343; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.343; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:57170/rrmz/r collection:control_collection shard:shard1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.344; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.375; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.387; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.387; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.388; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:57170/rrmz/r/collection1/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.388; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.388; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:57170/rrmz/r/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.389; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:57170/rrmz/r/collection1/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:34.389; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.674; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.696; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.730; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:57170/rrmz/r/collection1/ and leader is http://127.0.0.1:57170/rrmz/r/collection1/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.730; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57170/rrmz/r
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.730; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.730; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.731; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.733; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.735; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.735; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.736; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.751; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.753; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.756; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@6c92cd07 name:ZooKeeperConnection Watcher:127.0.0.1:57167/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.756; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.758; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:35.761; org.apache.solr.cloud.ChaosMonkey; monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.418; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.421; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:52398
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.421; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.422; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.422; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368584255762
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.423; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368584255762/solr.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.423; org.apache.solr.core.CoreContainer; New CoreContainer 844708601
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.423; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368584255762/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.424; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368584255762/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.504; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.505; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.505; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.505; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.506; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.506; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.506; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.507; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.507; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.507; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.518; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.519; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:57167/solr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.519; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.520; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.523; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@225a26 name:ZooKeeperConnection Watcher:127.0.0.1:57167 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.524; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.526; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.535; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.573; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@217b4794 name:ZooKeeperConnection Watcher:127.0.0.1:57167/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.574; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:36.578; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.205; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.206; 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:57170_rrmz%2Fr",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:57170/rrmz/r"}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.221; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.221; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.221; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.583; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52398_rrmz%2Fr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.585; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:52398_rrmz%2Fr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.592; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.592; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.592; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.592; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.592; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.593; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.601; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368584255762/collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.602; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.603; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.603; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.604; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368584255762/collection1/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.605; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368584255762/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.606; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368584255762/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.642; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.684; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.786; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:37.790; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.192; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.195; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.197; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.201; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.228; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.228; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368584255762/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty1/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.228; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4440ece0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.229; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.229; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.229; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty1/index/
[junit4:junit4] 1> WARN - 2013-05-15 02:17:38.229; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.230; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty1/index
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.232; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67d3d5b4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6844f2eb),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.232; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.234; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.235; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.235; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.235; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.236; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.236; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.236; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.237; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.237; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.242; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.246; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@c5082c8 main
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.247; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty1/tlog
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.247; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.248; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.251; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@c5082c8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.252; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.252; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.728; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.729; 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:52398_rrmz%2Fr",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:52398/rrmz/r"}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.729; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection collection1 with numShards 2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.730; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.747; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.747; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:38.747; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:39.283; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:39.283; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:52398/rrmz/r collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:39.284; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-05-15 02:17:39.304; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-15 02:17:39.314; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-15 02:17:39.315; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-15 02:17:39.315; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:52398/rrmz/r/collection1/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:39.315; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-15 02:17:39.315; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:52398/rrmz/r/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-15 02:17:39.315; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:52398/rrmz/r/collection1/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:39.315; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.252; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.293; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.294; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.294; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.342; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:52398/rrmz/r/collection1/ and leader is http://127.0.0.1:52398/rrmz/r/collection1/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.342; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52398/rrmz/r
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.342; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.343; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.343; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.345; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.347; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.347; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.348; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.507; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.510; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:30518
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.510; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.510; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.511; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368584260358
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.511; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368584260358/solr.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.511; org.apache.solr.core.CoreContainer; New CoreContainer 157347457
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.512; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368584260358/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.512; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368584260358/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.579; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.580; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.580; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.581; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.581; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.581; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.581; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.582; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.582; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.582; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.594; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.594; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:57167/solr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.595; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.595; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.599; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@3b5b91a1 name:ZooKeeperConnection Watcher:127.0.0.1:57167 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.599; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.614; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.622; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.625; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@3264a2e9 name:ZooKeeperConnection Watcher:127.0.0.1:57167/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.625; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:40.635; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.642; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:30518_rrmz%2Fr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.646; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:30518_rrmz%2Fr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.670; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.670; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.670; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.670; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.671; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.670; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.671; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.713; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368584260358/collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.714; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.715; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.716; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.718; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368584260358/collection1/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.720; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368584260358/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.720; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368584260358/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.777; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.808; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.809; 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:52398_rrmz%2Fr",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:52398/rrmz/r"}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.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-05-15 02:17:41.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-05-15 02:17:41.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-05-15 02:17:41.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-05-15 02:17:41.838; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.939; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:41.945; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.508; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.510; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.512; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.517; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.546; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.546; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368584260358/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty2/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.546; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4440ece0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.547; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.547; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.547; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty2/index/
[junit4:junit4] 1> WARN - 2013-05-15 02:17:42.548; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.548; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty2/index
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.550; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@128a54b lockFactory=org.apache.lucene.store.NativeFSLockFactory@13ffa638),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.550; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.553; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.553; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.553; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.554; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.554; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.554; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.555; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.555; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.555; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.560; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.565; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1b814d97 main
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.565; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty2/tlog
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.566; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.566; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.569; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1b814d97 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.571; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-15 02:17:42.571; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.336; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.337; 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:30518_rrmz%2Fr",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:30518/rrmz/r"}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.337; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.337; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.412; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.412; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.412; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.412; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.601; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.601; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:30518/rrmz/r collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.602; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.619; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.631; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.631; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.632; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:30518/rrmz/r/collection1/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.632; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.632; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:30518/rrmz/r/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.632; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:30518/rrmz/r/collection1/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:43.633; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:44.919; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:44.938; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:44.939; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:44.939; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:44.939; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:44.974; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:30518/rrmz/r/collection1/ and leader is http://127.0.0.1:30518/rrmz/r/collection1/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:44.974; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:30518/rrmz/r
[junit4:junit4] 1> INFO - 2013-05-15 02:17:44.974; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-15 02:17:44.974; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-15 02:17:44.975; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-15 02:17:44.977; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:44.978; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:44.979; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-15 02:17:44.980; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.224; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.227; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:60985
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.228; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.228; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.229; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368584264995
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.229; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368584264995/solr.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.230; org.apache.solr.core.CoreContainer; New CoreContainer 1332149555
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.231; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368584264995/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.231; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368584264995/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.332; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.332; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.333; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.333; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.334; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.334; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.335; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.335; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.336; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.336; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.353; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.353; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:57167/solr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.354; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.355; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.358; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@7865af68 name:ZooKeeperConnection Watcher:127.0.0.1:57167 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.359; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.373; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.387; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.390; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@6adc63e9 name:ZooKeeperConnection Watcher:127.0.0.1:57167/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.390; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:45.400; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.404; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60985_rrmz%2Fr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.406; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:60985_rrmz%2Fr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.409; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.409; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.409; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.410; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.410; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.410; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.410; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.410; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.437; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.441; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368584264995/collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.441; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.442; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.442; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.443; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368584264995/collection1/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.444; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368584264995/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.444; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368584264995/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.453; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.454; 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:30518_rrmz%2Fr",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:30518/rrmz/r"}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.480; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.490; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.490; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.490; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.490; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.490; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.524; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.644; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:46.648; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.132; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.136; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.139; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.144; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.176; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.177; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368584264995/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty3/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.177; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4440ece0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.178; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.178; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.178; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty3/index/
[junit4:junit4] 1> WARN - 2013-05-15 02:17:47.179; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.180; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty3/index
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.183; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6b6087b0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2fefbef6),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.183; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.186; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.186; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.187; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.187; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.188; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.188; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.189; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.189; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.190; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.198; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.205; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@35f04f50 main
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.205; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty3/tlog
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.206; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.207; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.211; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@35f04f50 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.213; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-15 02:17:47.213; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.047; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.047; 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:60985_rrmz%2Fr",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:60985/rrmz/r"}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.048; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.048; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.053; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.053; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.053; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.053; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.053; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.245; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.245; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:60985/rrmz/r collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.275; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:60985/rrmz/r/collection1/ and leader is http://127.0.0.1:52398/rrmz/r/collection1/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.275; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60985/rrmz/r
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.275; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.276; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.276; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.277; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.277; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.277; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.277; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.278; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.279; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.280; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.280; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.293; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.519; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.522; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:19270
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.523; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.523; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.524; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368584268293
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.524; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368584268293/solr.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.525; org.apache.solr.core.CoreContainer; New CoreContainer 1095017671
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.526; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368584268293/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.526; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368584268293/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.636; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.637; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.638; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.638; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.639; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.639; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.640; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.640; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.640; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.641; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.656; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.657; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:57167/solr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.657; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.658; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.661; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@35e406c1 name:ZooKeeperConnection Watcher:127.0.0.1:57167 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.662; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.677; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.688; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.691; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@45e0691 name:ZooKeeperConnection Watcher:127.0.0.1:57167/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.691; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-15 02:17:48.701; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.567; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.567; 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:60985_rrmz%2Fr",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:60985/rrmz/r"}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.581; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.582; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.582; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.581; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.581; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.581; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.705; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:19270_rrmz%2Fr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.707; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:19270_rrmz%2Fr
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.709; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.709; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.709; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.710; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.710; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.710; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.710; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.711; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.711; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.712; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.712; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.719; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.725; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368584268293/collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.725; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.726; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.726; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.728; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368584268293/collection1/'
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.729; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368584268293/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.729; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368584268293/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.769; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.818; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.919; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:49.923; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.295; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.295; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:60985_rrmz%252Fr&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.311; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.314; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.315; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.320; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.348; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.348; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368584268293/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.348; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4440ece0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.349; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.350; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.350; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4/index/
[junit4:junit4] 1> WARN - 2013-05-15 02:17:50.350; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.351; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4/index
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.354; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ed9e917 lockFactory=org.apache.lucene.store.NativeFSLockFactory@49fbc6e9),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.355; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.357; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.358; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.359; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.359; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.360; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.360; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.360; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.361; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.361; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.369; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.376; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@43689616 main
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.377; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4/tlog
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.378; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.378; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.382; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@43689616 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.384; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-15 02:17:50.384; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.088; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.089; 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:19270_rrmz%2Fr",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:19270/rrmz/r"}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.089; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.090; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.126; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.127; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.126; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.126; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.126; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.126; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.387; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.387; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:19270/rrmz/r collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.392; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:19270/rrmz/r/collection1/ and leader is http://127.0.0.1:30518/rrmz/r/collection1/
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.392; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:19270/rrmz/r
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.392; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.392; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.393; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.393; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.393; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.393; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.394; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.395; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.395; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.395; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.396; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.411; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.413; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.413; org.apache.solr.cloud.AbstractFullDistribZkTestBase; Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.414; org.apache.solr.cloud.AbstractDistribZkTestBase; Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 1> INFO - 2013-05-15 02:17:51.414; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.297; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:52398/rrmz/r/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.297; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:60985/rrmz/r START replicas=[http://127.0.0.1:52398/rrmz/r/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-05-15 02:17:52.297; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.298; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.298; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.298; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.298; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.299; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:52398/rrmz/r/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.299; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.304; org.apache.solr.core.SolrCore; [collection1] webapp=/rrmz/r path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.308; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.310; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67d3d5b4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6844f2eb),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.310; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.311; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67d3d5b4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6844f2eb),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67d3d5b4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6844f2eb),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.311; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.311; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@492cbd32 realtime
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.312; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.312; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.313; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.313; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.315; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.315; org.apache.solr.core.SolrCore; [collection1] webapp=/rrmz/r path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.315; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.316; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.316; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.318; org.apache.solr.core.SolrCore; [collection1] webapp=/rrmz/r path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.318; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.319; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty3/index.20130515041752319
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.319; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@73421109 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7af86d80) fullCopy=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.322; org.apache.solr.core.SolrCore; [collection1] webapp=/rrmz/r path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.323; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.324; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.324; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.325; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6b6087b0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2fefbef6),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6b6087b0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2fefbef6),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.325; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.326; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.326; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@33758f41 main
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.327; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@33758f41 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.327; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty3/index.20130515041752319 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty3/index.20130515041752319;done=true>>]
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.327; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty3/index.20130515041752319
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.327; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty3/index.20130515041752319
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.327; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.328; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.328; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.328; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.355; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.416; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.632; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.633; 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:19270_rrmz%2Fr",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:19270/rrmz/r"}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.637; 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:60985_rrmz%2Fr",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:60985/rrmz/r"}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.652; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.652; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.652; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.652; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.652; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:52.652; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:53.415; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 1> INFO - 2013-05-15 02:17:53.415; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:19270_rrmz%252Fr&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2002
[junit4:junit4] 1> INFO - 2013-05-15 02:17:53.418; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:54.420; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.417; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:30518/rrmz/r/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.417; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:19270/rrmz/r START replicas=[http://127.0.0.1:30518/rrmz/r/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-05-15 02:17:55.417; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.418; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.418; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.418; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.418; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.418; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:30518/rrmz/r/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.418; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.423; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.427; org.apache.solr.core.SolrCore; [collection1] webapp=/rrmz/r path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.429; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.431; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@128a54b lockFactory=org.apache.lucene.store.NativeFSLockFactory@13ffa638),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.432; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.433; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@128a54b lockFactory=org.apache.lucene.store.NativeFSLockFactory@13ffa638),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@128a54b lockFactory=org.apache.lucene.store.NativeFSLockFactory@13ffa638),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.433; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.434; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@2ee6f4da realtime
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.434; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.434; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.435; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.436; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.437; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.438; org.apache.solr.core.SolrCore; [collection1] webapp=/rrmz/r path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.438; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.439; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.439; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.441; org.apache.solr.core.SolrCore; [collection1] webapp=/rrmz/r path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.442; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.443; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4/index.20130515041755442
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.443; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@74306356 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a07007b) fullCopy=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.446; org.apache.solr.core.SolrCore; [collection1] webapp=/rrmz/r path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.447; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.448; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.448; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.450; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ed9e917 lockFactory=org.apache.lucene.store.NativeFSLockFactory@49fbc6e9),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ed9e917 lockFactory=org.apache.lucene.store.NativeFSLockFactory@49fbc6e9),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.450; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.451; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.451; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@49fc6909 main
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.452; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@49fc6909 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.452; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4/index.20130515041755442 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4/index.20130515041755442;done=true>>]
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.453; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4/index.20130515041755442
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.453; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4/index.20130515041755442
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.453; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.453; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.454; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.454; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.475; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.662; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.663; 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:19270_rrmz%2Fr",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:19270/rrmz/r"}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.678; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.678; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.678; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.678; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.678; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:55.678; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.427; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.428; org.apache.solr.cloud.AbstractDistribZkTestBase; Recoveries finished - collection: collection1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.436; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.438; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6064d97e lockFactory=org.apache.lucene.store.NativeFSLockFactory@7984f946),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.438; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.439; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6064d97e lockFactory=org.apache.lucene.store.NativeFSLockFactory@7984f946),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6064d97e lockFactory=org.apache.lucene.store.NativeFSLockFactory@7984f946),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.439; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.439; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@5df7cdad main
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.440; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.440; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@5df7cdad main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.441; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.451; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.451; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67d3d5b4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6844f2eb),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67d3d5b4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6844f2eb),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.452; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.452; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@28685ae8 main
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.452; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.453; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@28685ae8 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.454; org.apache.solr.update.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:60985/rrmz/r/collection1/, StdNode: http://127.0.0.1:30518/rrmz/r/collection1/, StdNode: http://127.0.0.1:19270/rrmz/r/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.457; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.458; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@128a54b lockFactory=org.apache.lucene.store.NativeFSLockFactory@13ffa638),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@128a54b lockFactory=org.apache.lucene.store.NativeFSLockFactory@13ffa638),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.459; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.459; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@ada67ac main
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.460; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.461; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@ada67ac main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.461; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.465; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.465; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.466; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6b6087b0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2fefbef6),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6b6087b0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2fefbef6),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.467; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ed9e917 lockFactory=org.apache.lucene.store.NativeFSLockFactory@49fbc6e9),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ed9e917 lockFactory=org.apache.lucene.store.NativeFSLockFactory@49fbc6e9),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.467; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.467; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.468; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@3a38f1ec main
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.468; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@395bc76d main
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.468; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.469; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@3a38f1ec main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.469; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.470; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.469; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@395bc76d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.471; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.471; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 21
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.473; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.476; org.apache.solr.core.SolrCore; [collection1] webapp=/rrmz/r path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.479; org.apache.solr.core.SolrCore; [collection1] webapp=/rrmz/r path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.481; org.apache.solr.core.SolrCore; [collection1] webapp=/rrmz/r path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:56.483; org.apache.solr.core.SolrCore; [collection1] webapp=/rrmz/r path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.489; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435064628398784512)} 0 2
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.496; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={update.distrib=FROMLEADER&_version_=-1435064628402978816&update.from=http://127.0.0.1:52398/rrmz/r/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435064628402978816)} 0 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.499; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={update.distrib=FROMLEADER&_version_=-1435064628407173120&update.from=http://127.0.0.1:30518/rrmz/r/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435064628407173120)} 0 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.500; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1435064628407173120)} 0 5
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.501; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435064628402978816)} 0 10
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.504; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[0 (1435064628415561728)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.511; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1435064628419756032)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.511; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[0 (1435064628419756032)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.515; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[1 (1435064628427096064)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.521; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1435064628432338944)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.522; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1435064628432338944)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.523; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[1]} 0 7
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.525; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[2 (1435064628438630400)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.534; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1435064628443873280)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.534; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[2 (1435064628443873280)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.535; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[2]} 0 7
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.537; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[3 (1435064628451213312)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.544; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1435064628456456192)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.546; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[3 (1435064628456456192)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.547; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[3]} 0 7
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.550; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[4 (1435064628464844800)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.558; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1435064628470087680)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.559; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[4 (1435064628470087680)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.560; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[4]} 0 7
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.562; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[5 (1435064628477427712)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.567; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1435064628480573440)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.568; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[5 (1435064628480573440)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.570; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[6 (1435064628485816320)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.578; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1435064628491059200)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.579; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[6 (1435064628491059200)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.579; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[6]} 0 6
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.582; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[7 (1435064628498399232)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.590; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1435064628503642112)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.591; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[7 (1435064628503642112)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.591; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[7]} 0 6
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.594; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[8 (1435064628510982144)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.601; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1435064628516225024)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.602; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1435064628516225024)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.602; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[8]} 0 5
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.605; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[9 (1435064628522516480)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.610; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1435064628525662208)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.611; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[9 (1435064628525662208)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.613; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[10 (1435064628530905088)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.624; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1435064628536147968)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.624; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (1435064628536147968)]} 0 6
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.625; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[10]} 0 9
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.627; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[11 (1435064628545585152)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.634; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1435064628550828032)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.635; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[11 (1435064628550828032)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.636; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[11]} 0 6
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.638; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[12 (1435064628557119488)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.646; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1435064628562362368)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.647; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[12 (1435064628562362368)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.648; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[12]} 0 7
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.650; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[13 (1435064628569702400)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.655; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1435064628572848128)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.656; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[13 (1435064628572848128)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.658; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[14 (1435064628578091008)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.664; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1435064628581236736)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.665; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[14 (1435064628581236736)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.667; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[15 (1435064628587528192)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.674; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1435064628592771072)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.675; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[15 (1435064628592771072)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.675; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[15]} 0 5
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.678; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[16 (1435064628599062528)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.684; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1435064628602208256)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.685; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[16 (1435064628602208256)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.687; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[17 (1435064628608499712)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.692; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1435064628611645440)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.693; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[17 (1435064628611645440)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.695; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[18 (1435064628616888320)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.700; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1435064628620034048)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.701; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[18 (1435064628620034048)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.703; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[19 (1435064628625276928)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.709; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1435064628628422656)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.710; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[19 (1435064628628422656)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.712; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[20 (1435064628634714112)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.719; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1435064628637859840)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.719; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[20 (1435064628637859840)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.722; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[21 (1435064628645199872)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.729; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1435064628650442752)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.730; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[21 (1435064628650442752)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.730; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[21]} 0 5
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.733; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[22 (1435064628656734208)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.741; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1435064628661977088)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.742; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[22 (1435064628661977088)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.742; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[22]} 0 6
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.745; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[23 (1435064628669317120)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.752; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1435064628674560000)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.753; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[23 (1435064628674560000)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.753; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[23]} 0 5
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.757; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[24 (1435064628680851456)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.763; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1435064628683997184)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.763; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[24 (1435064628683997184)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.766; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[25 (1435064628691337216)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.776; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1435064628697628672)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.776; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[25 (1435064628697628672)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.777; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[25]} 0 8
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.780; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[26 (1435064628706017280)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.788; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1435064628711260160)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.796; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[26 (1435064628711260160)]} 0 11
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.797; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[26]} 0 14
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.800; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[27 (1435064628725940224)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.805; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1435064628729085952)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.806; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[27 (1435064628729085952)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.808; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[28 (1435064628735377408)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.816; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1435064628740620288)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.817; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[28 (1435064628740620288)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.818; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[28]} 0 7
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.820; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[29 (1435064628747960320)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.826; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1435064628751106048)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.827; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[29 (1435064628751106048)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.830; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[30 (1435064628758446080)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.837; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1435064628763688960)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.839; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[30 (1435064628763688960)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.840; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[30]} 0 7
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.843; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[31 (1435064628772077568)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.851; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1435064628777320448)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.852; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[31 (1435064628777320448)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.853; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[31]} 0 7
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.855; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[32 (1435064628784660480)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.862; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1435064628789903360)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.863; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[32 (1435064628789903360)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.863; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[32]} 0 5
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.866; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[33 (1435064628796194816)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.874; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1435064628801437696)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.875; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[33 (1435064628801437696)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.876; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[33]} 0 7
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.878; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[34 (1435064628808777728)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.884; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1435064628811923456)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.885; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[34 (1435064628811923456)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.887; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[35 (1435064628818214912)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.895; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1435064628823457792)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.896; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[35 (1435064628823457792)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.896; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[35]} 0 6
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.899; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={wt=javabin&version=2} {add=[36 (1435064628830797824)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.908; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:52398/rrmz/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1435064628836040704)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-15 02:17:58.908; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/rrmz/r path=/update params={distrib.from=http://127.0.0.1:30518/rrmz/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[36 (1435064628836040704)]} 0 4
[junit4:junit4] 1> IN
[...truncated too long message...]
er: http://127.0.0.1:19270/rrmz/r/collection1/
[junit4:junit4] 1> INFO - 2013-05-15 02:22:22.972; org.apache.solr.core.SolrCore; [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@54924c97
[junit4:junit4] 1> INFO - 2013-05-15 02:22:22.973; org.apache.solr.update.DirectUpdateHandler2; closing DirectUpdateHandler2{commits=4,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=794,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 1> INFO - 2013-05-15 02:22:22.974; org.apache.solr.update.SolrCoreState; Closing SolrCoreState
[junit4:junit4] 1> INFO - 2013-05-15 02:22:22.974; org.apache.solr.update.DefaultSolrCoreState; SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 1> INFO - 2013-05-15 02:22:22.974; org.apache.solr.update.DefaultSolrCoreState; closing IndexWriter with IndexWriterCloser
[junit4:junit4] 1> ERROR - 2013-05-15 02:22:22.975; org.apache.solr.update.TransactionLog; Error: Forcing close of tlog{file=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4/tlog/tlog.0000000000000000003 refcount=1}
[junit4:junit4] 1> INFO - 2013-05-15 02:22:22.977; org.apache.solr.core.SolrCore; [collection1] Closing main searcher on request.
[junit4:junit4] 1> INFO - 2013-05-15 02:22:22.978; org.apache.solr.core.CachingDirectoryFactory; Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 1> INFO - 2013-05-15 02:22:22.978; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4/index;done=false>>]
[junit4:junit4] 1> INFO - 2013-05-15 02:22:22.978; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4/index
[junit4:junit4] 1> INFO - 2013-05-15 02:22:22.978; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4;done=false>>]
[junit4:junit4] 1> INFO - 2013-05-15 02:22:22.978; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368584251932/jetty4
[junit4:junit4] 1> INFO - 2013-05-15 02:22:22.979; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 1> WARN - 2013-05-15 02:22:22.979; org.apache.solr.cloud.LeaderElector$1;
[junit4:junit4] 1> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election/89691537534943244-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-05-15 02:22:22.980; 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-05-15 02:22:22.980; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-15 02:22:22.980; org.apache.solr.common.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-05-15 02:22:22.980; org.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-05-15 02:22:22.980; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-15 02:22:22.981; 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=DummyCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=DUMMY, chunkSize=437), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=DUMMY, chunkSize=437)), sim=DefaultSimilarity, locale=zh_TW, timezone=Arctic/Longyearbyen
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=3,free=129723760,total=496500736
[junit4:junit4] 2> NOTE: All tests run in this JVM: [HardAutoCommitTest, TestSolrQueryParserResource, TestBM25SimilarityFactory, URLClassifyProcessorTest, SolrCoreCheckLockOnStartupTest, EchoParamsTest, TestLuceneMatchVersion, TermVectorComponentDistributedTest, NoCacheHeaderTest, TestJmxMonitoredMap, DocumentAnalysisRequestHandlerTest, XmlUpdateRequestHandlerTest, IndexReaderFactoryTest, ClusterStateTest, UpdateParamsTest, TestRecovery, SuggesterWFSTTest, TestLMJelinekMercerSimilarityFactory, TestDistributedGrouping, TestSolrXMLSerializer, TestSchemaNameResource, TestSchemaSimilarityResource, BasicZkTest, SampleTest, DOMUtilTest, TestMergePolicyConfig, IndexSchemaRuntimeFieldTest, TestFiltering, TestSolrQueryParserDefaultOperatorResource, NotRequiredUniqueKeyTest, FieldAnalysisRequestHandlerTest, OpenExchangeRatesOrgProviderTest, TestShardHandlerFactory, TestRandomFaceting, DirectUpdateHandlerTest, DocValuesMultiTest, TestPropInject, DefaultValueUpdateProcessorTest, HighlighterTest, TestAtomicUpdateErrorCases, StandardRequestHandlerTest, SignatureUpdateProcessorFactoryTest, RequestHandlersTest, TestFastOutputStream, TestJmxIntegration, TestSuggestSpellingConverter, TestCoreDiscovery, FullSolrCloudDistribCmdsTest, SortByFunctionTest, TestSolrXml, DirectSolrSpellCheckerTest, CopyFieldTest, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J1 in 291.87s, 1 test, 1 error <<< FAILURES!
[...truncated 570 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:383: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:363: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:887: There were test failures: 296 suites, 1234 tests, 1 error, 27 ignored (8 assumptions)
Total time: 55 minutes 48 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure