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/14 10:44:31 UTC
[JENKINS] Lucene-Solr-Tests-4.x-java7 - Build # 1243 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-java7/1243/
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:40433 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:40433 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([CB8E88ABF2022E95:4A6806B3855D4EA9]: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:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9523 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.088; org.apache.solr.BaseDistributedSearchTestCase; Setting hostContext system property: /
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.095; org.apache.solr.SolrTestCaseJ4; ###Starting testDistribSearch
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.097; 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-14 08:07:29.098; org.apache.solr.cloud.ZkTestServer$ZKServerMain; Starting server
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.198; org.apache.solr.cloud.ZkTestServer; start zk server on port:23138
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.199; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.203; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1f5fc06f name:ZooKeeperConnection Watcher:127.0.0.1:23138 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.203; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.203; org.apache.solr.common.cloud.SolrZkClient; makePath: /solr
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.217; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.220; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@7435dd99 name:ZooKeeperConnection Watcher:127.0.0.1:23138/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.220; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.220; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.224; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/shards
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.234; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.237; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/shards
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.240; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.240; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.250; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.251; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.360; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.360; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.364; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.364; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.389; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.390; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.396; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.396; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.410; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.411; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.414; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.415; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.434; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.435; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.705; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.709; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:47753
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.710; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.711; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.711; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368518849474
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.712; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368518849474/solr.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.712; org.apache.solr.core.CoreContainer; New CoreContainer 1106017810
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.713; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368518849474/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.713; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368518849474/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.817; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.817; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.818; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.818; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.819; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.819; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.819; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.820; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.820; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.820; 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-14 08:07:29.831; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.832; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:23138/solr
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.832; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.833; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.841; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@374929a8 name:ZooKeeperConnection Watcher:127.0.0.1:23138 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.842; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.847; 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-14 08:07:29.855; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.857; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1a02cc51 name:ZooKeeperConnection Watcher:127.0.0.1:23138/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.857; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.859; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.869; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/collection-queue-work
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.872; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.881; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47753_
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.882; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:47753_
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.885; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/election
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.902; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/leader
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.904; org.apache.solr.cloud.Overseer; Overseer (id=89687251294748675-127.0.0.1:47753_-n_0000000000) starting
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.917; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue-work
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.928; org.apache.solr.cloud.OverseerCollectionProcessor; Process current queue of collection creations
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.929; org.apache.solr.common.cloud.SolrZkClient; makePath: /clusterstate.json
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.935; org.apache.solr.common.cloud.SolrZkClient; makePath: /aliases.json
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.936; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.941; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368518849474/collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.941; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Starting to work on the main queue
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.942; org.apache.solr.cloud.ZkController; Check for collection zkNode:control_collection
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.942; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.943; org.apache.solr.cloud.ZkController; Load collection config from:/collections/control_collection
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.944; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368518849474/collection1/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.945; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368518849474/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-14 08:07:29.945; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368518849474/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.003; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.069; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.170; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.177; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.798; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.801; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.802; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.806; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.826; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.827; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368518849474/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/control/data/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.827; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4add68dd
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.827; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.828; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/control/data
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.828; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/control/data/index/
[junit4:junit4] 1> WARN - 2013-05-14 08:07:30.829; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.829; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/control/data/index
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.832; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2e11bcd lockFactory=org.apache.lucene.store.NativeFSLockFactory@71364357),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.833; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.836; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.837; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.837; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.838; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.839; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.839; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.839; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.840; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.840; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.854; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.861; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@76b1d961 main
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.862; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/control/data/tlog
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.863; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.864; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.867; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@76b1d961 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.870; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-14 08:07:30.870; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.445; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.446; 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:47753_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:47753"}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.446; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection control_collection with numShards 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.447; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.487; org.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-14 08:07:31.873; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.873; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:47753 collection:control_collection shard:shard1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.874; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.889; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.892; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.892; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.892; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:47753/collection1/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.892; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.892; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:47753/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.893; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:47753/collection1/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:31.893; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:32.991; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.012; org.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-14 08:07:33.022; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:47753/collection1/ and leader is http://127.0.0.1:47753/collection1/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.022; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47753
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.022; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.023; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.023; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.025; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.026; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.027; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.028; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.042; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.044; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.047; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@232eccfb name:ZooKeeperConnection Watcher:127.0.0.1:23138/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.047; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.049; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.051; org.apache.solr.cloud.ChaosMonkey; monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.282; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.285; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:40433
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.286; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.287; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.287; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368518853052
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.288; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368518853052/solr.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.288; org.apache.solr.core.CoreContainer; New CoreContainer 1750597777
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.289; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368518853052/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.290; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368518853052/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.414; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.415; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.415; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.416; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.416; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.417; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.418; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.418; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.419; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.419; 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-14 08:07:33.434; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.435; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:23138/solr
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.436; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.437; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.440; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@27b49030 name:ZooKeeperConnection Watcher:127.0.0.1:23138 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.441; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.457; 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-14 08:07:33.468; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.470; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1a5fc370 name:ZooKeeperConnection Watcher:127.0.0.1:23138/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.471; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:33.476; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.479; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40433_
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.495; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:40433_
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.523; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.523; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.523; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.524; 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-14 08:07:34.526; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.527; 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:47753_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:47753"}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.531; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368518853052/collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.531; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.574; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.575; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.577; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368518853052/collection1/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.579; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368518853052/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.579; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368518853052/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.611; org.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-14 08:07:34.611; org.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-14 08:07:34.614; org.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-14 08:07:34.643; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.732; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.833; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:34.838; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.412; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.419; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.423; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.431; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.461; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.462; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368518853052/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty1/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.463; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4add68dd
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.464; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.465; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.465; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty1/index/
[junit4:junit4] 1> WARN - 2013-05-14 08:07:35.465; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.467; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty1/index
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.472; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@61430a89 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2e54d338),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.473; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.477; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.478; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.479; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.480; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.481; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.482; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.482; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.483; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.484; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.505; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.517; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@2e7ed4b4 main
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.518; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty1/tlog
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.519; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.519; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.525; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@2e7ed4b4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.529; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-14 08:07:35.529; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.115; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.116; 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:40433_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40433"}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.116; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection collection1 with numShards 2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.116; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.131; org.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-14 08:07:36.131; org.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-14 08:07:36.131; org.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-14 08:07:36.535; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.535; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:40433 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.536; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.555; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.558; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.559; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.559; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:40433/collection1/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.559; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.559; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:40433/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.559; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:40433/collection1/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:36.560; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.635; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.655; org.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-14 08:07:37.655; org.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-14 08:07:37.655; org.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-14 08:07:37.688; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:40433/collection1/ and leader is http://127.0.0.1:40433/collection1/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.688; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40433
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.688; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.689; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.689; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.691; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.692; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.692; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.693; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.908; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.913; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:57175
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.914; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.914; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.915; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368518857708
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.915; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368518857708/solr.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.916; org.apache.solr.core.CoreContainer; New CoreContainer 1522249495
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.917; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368518857708/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:37.917; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368518857708/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.044; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.045; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.045; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.045; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.046; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.046; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.046; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.047; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.047; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.048; 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-14 08:07:38.063; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.064; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:23138/solr
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.064; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.066; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.069; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1d4fcaf7 name:ZooKeeperConnection Watcher:127.0.0.1:23138 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.070; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.086; 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-14 08:07:38.100; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.103; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@53e1a0f4 name:ZooKeeperConnection Watcher:127.0.0.1:23138/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.103; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:38.109; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.113; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57175_
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.115; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:57175_
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.118; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.118; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.118; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.118; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.119; 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-14 08:07:39.119; 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-14 08:07:39.119; 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-14 08:07:39.133; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368518857708/collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.133; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.134; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.134; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.135; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368518857708/collection1/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.136; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368518857708/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.136; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368518857708/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.166; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.167; 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:40433_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40433"}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.172; org.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-14 08:07:39.172; org.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-14 08:07:39.172; org.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-14 08:07:39.172; org.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-14 08:07:39.176; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.219; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.320; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:39.347; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.121; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.129; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.132; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.138; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.161; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.162; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368518857708/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty2/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.162; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4add68dd
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.163; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.165; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.165; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty2/index/
[junit4:junit4] 1> WARN - 2013-05-14 08:07:40.165; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.166; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty2/index
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.173; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6405a044 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6ca248f3),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.174; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.177; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.178; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.178; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.179; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.180; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.180; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.180; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.181; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.182; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.200; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.208; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@78f383de main
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.209; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty2/tlog
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.210; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.211; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.216; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@78f383de main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.218; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.218; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.685; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.686; 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:57175_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:57175"}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.686; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.686; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:40.702; org.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-14 08:07:40.702; org.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-14 08:07:40.702; org.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-14 08:07:40.702; org.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-14 08:07:41.222; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:41.222; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:57175 collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:41.224; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 1> INFO - 2013-05-14 08:07:41.272; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-14 08:07:41.284; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-14 08:07:41.284; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-14 08:07:41.285; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:57175/collection1/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:41.285; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-14 08:07:41.286; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:57175/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-14 08:07:41.286; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:57175/collection1/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:41.287; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.209; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.280; org.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-14 08:07:42.280; org.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-14 08:07:42.280; org.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-14 08:07:42.280; org.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-14 08:07:42.333; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:57175/collection1/ and leader is http://127.0.0.1:57175/collection1/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.333; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57175
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.334; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.334; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.334; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.339; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.341; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.342; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.342; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.630; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.634; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:40591
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.635; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.636; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.636; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368518862360
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.637; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368518862360/solr.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.637; org.apache.solr.core.CoreContainer; New CoreContainer 1666252145
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.638; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368518862360/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.639; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368518862360/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.778; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.779; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.779; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.780; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.780; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.781; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.782; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.783; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.783; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.784; 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-14 08:07:42.801; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.802; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:23138/solr
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.802; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.804; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.807; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1031a4e2 name:ZooKeeperConnection Watcher:127.0.0.1:23138 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.808; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.822; 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-14 08:07:42.836; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.839; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@35ed140c name:ZooKeeperConnection Watcher:127.0.0.1:23138/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.839; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:42.853; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.799; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.800; 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:57175_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:57175"}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.823; org.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-14 08:07:43.823; org.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-14 08:07:43.823; org.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-14 08:07:43.823; org.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-14 08:07:43.823; org.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-14 08:07:43.870; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40591_
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.872; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:40591_
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.875; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.876; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.876; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.875; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.875; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.877; 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-14 08:07:43.877; 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-14 08:07:43.876; 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-14 08:07:43.876; 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-14 08:07:43.877; 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-14 08:07:43.893; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368518862360/collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.894; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.894; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.894; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.895; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368518862360/collection1/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.896; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368518862360/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.897; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368518862360/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.940; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-14 08:07:43.993; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.095; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.099; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.648; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.651; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.653; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.658; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.682; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.683; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368518862360/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty3/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.683; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4add68dd
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.684; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.684; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty3
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.685; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty3/index/
[junit4:junit4] 1> WARN - 2013-05-14 08:07:44.685; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.687; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty3/index
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.690; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ac9ef22 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4fec31af),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.691; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.694; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.694; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.695; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.695; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.696; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.696; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.696; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.697; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.697; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.711; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.717; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1c844677 main
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.718; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty3/tlog
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.719; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.719; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.723; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1c844677 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.725; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-14 08:07:44.725; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.331; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.332; 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:40591_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40591"}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.332; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.333; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.348; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.348; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.348; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.348; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.348; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.728; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.728; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:40591 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.732; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:40591/collection1/ and leader is http://127.0.0.1:40433/collection1/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.732; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40591
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.732; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.732; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.733; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.733; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.733; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.733; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.734; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.734; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.735; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.735; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.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-14 08:07:45.755; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-05-14 08:07:45.998; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.002; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:44979
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.003; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.003; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.004; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368518865753
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.004; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368518865753/solr.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.005; org.apache.solr.core.CoreContainer; New CoreContainer 1482502357
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.006; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368518865753/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.006; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368518865753/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.150; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.151; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.151; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.152; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.152; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.153; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.153; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.154; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.155; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.155; 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-14 08:07:46.172; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.173; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:23138/solr
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.174; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.175; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.178; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@3c853001 name:ZooKeeperConnection Watcher:127.0.0.1:23138 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.179; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.199; 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-14 08:07:46.212; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.214; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@2428ddb9 name:ZooKeeperConnection Watcher:127.0.0.1:23138/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.214; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.220; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.856; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.857; 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:40591_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40591"}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:46.871; org.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-14 08:07:46.871; org.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-14 08:07:46.871; org.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-14 08:07:46.871; org.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-14 08:07:46.871; org.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-14 08:07:46.871; org.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-14 08:07:47.224; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44979_
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.227; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:44979_
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.229; 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-14 08:07:47.230; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.230; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.230; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.230; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.230; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.231; 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-14 08:07:47.231; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.230; 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-14 08:07:47.230; 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-14 08:07:47.230; 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-14 08:07:47.231; 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-14 08:07:47.248; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368518865753/collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.249; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.249; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.249; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.251; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368518865753/collection1/'
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.252; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368518865753/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.252; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368518865753/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.297; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.349; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.450; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.456; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.757; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 1> INFO - 2013-05-14 08:07:47.757; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:40591_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2002
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.059; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.062; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.064; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.068; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.093; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.094; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368518865753/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.094; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4add68dd
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.095; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.095; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.095; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4/index/
[junit4:junit4] 1> WARN - 2013-05-14 08:07:48.096; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.097; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4/index
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.100; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1221dc71 lockFactory=org.apache.lucene.store.NativeFSLockFactory@214a3203),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.100; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.103; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.104; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.104; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.105; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.106; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.106; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.106; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.107; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.107; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.121; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.127; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@6adcd3ce main
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.127; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4/tlog
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.128; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.128; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.132; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@6adcd3ce main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.133; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.134; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.380; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.381; 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:44979_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:44979"}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.381; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.381; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:48.397; org.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-14 08:07:48.397; org.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-14 08:07:48.397; org.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-14 08:07:48.397; org.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-14 08:07:48.397; org.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-14 08:07:48.397; org.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-14 08:07:49.136; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.136; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:44979 collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.140; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:44979/collection1/ and leader is http://127.0.0.1:57175/collection1/
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.140; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44979
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.140; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.141; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.141; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.142; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.142; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.142; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.142; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.143; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.144; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.144; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.145; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.162; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.163; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.163; org.apache.solr.cloud.AbstractFullDistribZkTestBase; Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.164; org.apache.solr.cloud.AbstractDistribZkTestBase; Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.164; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.759; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:40433/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.759; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:40591 START replicas=[http://127.0.0.1:40433/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-05-14 08:07:49.760; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.761; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.761; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.761; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.761; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.762; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:40433/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.762; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.769; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.775; 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-14 08:07:49.784; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@61430a89 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2e54d338),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.786; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.787; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@61430a89 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2e54d338),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@61430a89 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2e54d338),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.787; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.788; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@79453076 realtime
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.789; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.789; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.790; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.791; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.793; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.794; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.795; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.795; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.795; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.799; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.800; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.801; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty3/index.20130514040749800
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.801; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@113bb6e4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@480bb14) fullCopy=false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.804; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.806; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.807; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.807; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.810; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ac9ef22 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4fec31af),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ac9ef22 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4fec31af),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.810; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.810; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.811; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@458f980b main
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.812; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@458f980b main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.813; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty3/index.20130514040749800 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty3/index.20130514040749800;done=true>>]
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.813; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty3/index.20130514040749800
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.813; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty3/index.20130514040749800
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.813; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.814; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.814; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.814; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.816; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.902; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.903; 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:44979_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:44979"}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.908; 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:40591_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40591"}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:49.922; org.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-14 08:07:49.922; org.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-14 08:07:49.922; org.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-14 08:07:49.922; org.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-14 08:07:49.922; org.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-14 08:07:49.922; org.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-14 08:07:50.164; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-05-14 08:07:50.164; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:44979_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 1> INFO - 2013-05-14 08:07:50.166; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:51.168; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.166; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:57175/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.166; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:44979 START replicas=[http://127.0.0.1:57175/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-05-14 08:07:52.167; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.167; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.167; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.167; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.168; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.168; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:57175/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.169; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.171; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.176; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.185; 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-14 08:07:52.189; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6405a044 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6ca248f3),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.190; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.191; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6405a044 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6ca248f3),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6405a044 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6ca248f3),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.191; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.192; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@2c8f5d58 realtime
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.193; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.194; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.195; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.196; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.198; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.199; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.200; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.200; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.200; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.203; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.204; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.205; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4/index.20130514040752205
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.206; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@3f4f9c0d lockFactory=org.apache.lucene.store.NativeFSLockFactory@4475915e) fullCopy=false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.208; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.210; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.211; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.211; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.213; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1221dc71 lockFactory=org.apache.lucene.store.NativeFSLockFactory@214a3203),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1221dc71 lockFactory=org.apache.lucene.store.NativeFSLockFactory@214a3203),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.214; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.214; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.214; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@288d3f21 main
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.216; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@288d3f21 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.217; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4/index.20130514040752205 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4/index.20130514040752205;done=true>>]
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.217; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4/index.20130514040752205
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.217; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4/index.20130514040752205
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.218; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.218; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.218; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.218; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.220; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.941; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.942; 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:44979_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:44979"}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:52.957; org.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-14 08:07:52.957; org.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-14 08:07:52.957; org.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-14 08:07:52.957; org.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-14 08:07:52.957; org.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-14 08:07:52.957; org.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-14 08:07:53.175; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.176; org.apache.solr.cloud.AbstractDistribZkTestBase; Recoveries finished - collection: collection1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.186; 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-14 08:07:53.189; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2e11bcd lockFactory=org.apache.lucene.store.NativeFSLockFactory@71364357),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.189; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.190; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2e11bcd lockFactory=org.apache.lucene.store.NativeFSLockFactory@71364357),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2e11bcd lockFactory=org.apache.lucene.store.NativeFSLockFactory@71364357),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.190; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.191; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@5583c7f3 main
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.191; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.193; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@5583c7f3 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.194; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.208; 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-14 08:07:53.210; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6405a044 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6ca248f3),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6405a044 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6ca248f3),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.211; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.211; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@73bd4ac0 main
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.212; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.212; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@73bd4ac0 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.213; org.apache.solr.update.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:40433/collection1/, StdNode: http://127.0.0.1:40591/collection1/, StdNode: http://127.0.0.1:44979/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.217; 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-14 08:07:53.219; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@61430a89 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2e54d338),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@61430a89 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2e54d338),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.220; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.221; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@7ca84c66 main
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.221; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.222; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@7ca84c66 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.223; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.224; 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-14 08:07:53.226; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1221dc71 lockFactory=org.apache.lucene.store.NativeFSLockFactory@214a3203),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1221dc71 lockFactory=org.apache.lucene.store.NativeFSLockFactory@214a3203),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.226; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.227; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@660cf764 main
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.227; 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-14 08:07:53.228; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.229; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ac9ef22 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4fec31af),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ac9ef22 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4fec31af),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.229; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@660cf764 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.229; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.231; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.231; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@20cc2442 main
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.232; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.234; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@20cc2442 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.235; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.236; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 28
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.237; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.241; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.245; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.248; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:53.250; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.257; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1434996048139386880)} 0 2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.271; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1434996048146726912&update.from=http://127.0.0.1:57175/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1434996048146726912)} 0 6
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.276; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1434996048149872640&update.from=http://127.0.0.1:40433/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1434996048149872640)} 0 2
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.277; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1434996048149872640)} 0 12
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.277; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1434996048146726912)} 0 16
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.281; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1434996048166649856)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.288; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1434996048169795584)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.289; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1434996048169795584)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.293; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1434996048178184192)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.300; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1434996048182378496)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.300; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1434996048182378496)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.305; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1434996048190767104)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.314; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1434996048197058560)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.315; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[2 (1434996048197058560)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.316; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2]} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.320; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1434996048207544320)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.330; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1434996048214884352)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.331; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[3 (1434996048214884352)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.331; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3]} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.335; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1434996048222224384)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.345; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1434996048229564416)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.346; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[4 (1434996048229564416)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.347; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4]} 0 9
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.351; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1434996048240050176)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.361; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1434996048246341632)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.362; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[5 (1434996048246341632)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.362; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5]} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.366; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1434996048255778816)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.375; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1434996048262070272)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.376; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[6 (1434996048262070272)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.377; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6]} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.381; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1434996048271507456)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.391; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1434996048277798912)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.392; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[7 (1434996048277798912)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.394; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7]} 0 10
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.398; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1434996048289333248)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.408; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1434996048295624704)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.409; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1434996048295624704)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.410; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8]} 0 9
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.413; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1434996048305061888)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.420; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1434996048308207616)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.421; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1434996048308207616)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.426; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1434996048318693376)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.437; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1434996048326033408)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.438; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (1434996048326033408)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.439; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10]} 0 9
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.442; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1434996048335470592)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.451; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1434996048341762048)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.452; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[11 (1434996048341762048)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.453; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11]} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.456; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1434996048350150656)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.463; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1434996048353296384)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.463; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1434996048353296384)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.467; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1434996048361684992)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.476; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1434996048367976448)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.477; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[13 (1434996048367976448)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.478; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13]} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.481; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1434996048376365056)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.488; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1434996048379510784)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.489; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1434996048379510784)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.493; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1434996048387899392)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.501; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1434996048393142272)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.502; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1434996048393142272)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.506; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1434996048401530880)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.513; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1434996048405725184)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.514; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1434996048405725184)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.518; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1434996048414113792)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.527; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1434996048420405248)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.528; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[17 (1434996048420405248)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.528; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17]} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.532; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1434996048428793856)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.541; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1434996048435085312)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.541; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[18 (1434996048435085312)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.542; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18]} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.546; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1434996048443473920)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.554; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1434996048449765376)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.555; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[19 (1434996048449765376)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.556; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19]} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.560; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1434996048458153984)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.569; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1434996048465494016)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.570; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[20 (1434996048465494016)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.571; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20]} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.575; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1434996048473882624)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.582; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1434996048478076928)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.583; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1434996048478076928)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.587; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1434996048486465536)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.595; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1434996048493805568)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.596; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[22 (1434996048493805568)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.597; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22]} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.601; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1434996048501145600)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.607; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1434996048504291328)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.607; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1434996048504291328)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.612; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1434996048513728512)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.621; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1434996048521068544)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.622; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[24 (1434996048521068544)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.623; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24]} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.627; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1434996048528408576)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.634; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1434996048532602880)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.634; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1434996048532602880)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.638; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1434996048539942912)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.645; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1434996048544137216)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.646; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1434996048544137216)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.649; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1434996048551477248)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.656; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1434996048555671552)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.657; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1434996048555671552)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.661; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1434996048564060160)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.668; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1434996048568254464)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.668; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1434996048568254464)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.672; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1434996048575594496)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.680; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1434996048580837376)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.681; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[29 (1434996048580837376)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.681; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29]} 0 7
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.685; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1434996048589225984)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.691; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1434996048592371712)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.691; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1434996048592371712)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.695; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1434996048599711744)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.704; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1434996048606003200)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.705; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[31 (1434996048606003200)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.706; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31]} 0 9
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.710; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1434996048615440384)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.717; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1434996048620683264)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.718; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1434996048620683264)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.722; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1434996048628023296)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.729; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1434996048632217600)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.730; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1434996048632217600)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.733; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1434996048639557632)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.740; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1434996048644800512)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.741; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1434996048644800512)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.745; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1434996048652140544)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.756; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1434996048660529152)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.758; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[35 (1434996048660529152)]} 0 7
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.760; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35]} 0 12
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.764; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1434996048673112064)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.773; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1434996048678354944)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.776; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1434996048678354944)]} 0 7
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.780; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1434996048689889280)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.788; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1434996048694083584)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.790; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1434996048694083584)]} 0 6
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.794; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1434996048704569344)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.804; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1434996048710860800)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.805; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[38 (1434996048710860800)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.805; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38]} 0 8
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.809; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1434996048719249408)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.816; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57175/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1434996048724492288)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.817; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1434996048724492288)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.821; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1434996048731832320)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.828; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40433/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1434996048736026624)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.828; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1434996048736026624)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.831; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1434996048743366656)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-14 08:07:55.841; org.apache.solr.update.processor.
[...truncated too long message...]
re.SolrCore; [collection1] Closing main searcher on request.
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.514; org.apache.solr.core.CachingDirectoryFactory; Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.514; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4/index;done=false>>]
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.515; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4/index
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.515; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4;done=false>>]
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.516; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096/jetty4
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.517; org.apache.solr.cloud.Overseer$ClusterStateUpdater; According to ZK I (id=89687251294748684-127.0.0.1:44979_-n_0000000004) am no longer a leader.
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.556; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.557; org.eclipse.jetty.server.handler.ContextHandler; stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 1> WARN - 2013-05-14 08:10:24.557; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-14 08:10:24.558; org.apache.solr.common.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.634; org.apache.solr.SolrTestCaseJ4; ###Ending testDistribSearch
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.637; org.apache.solr.cloud.ZkTestServer; connecting to 127.0.0.1:23138 23138
[junit4:junit4] 1> WARN - 2013-05-14 08:10:24.690; org.apache.solr.common.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.703; 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> WARN - 2013-05-14 08:10:24.705; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.706; org.apache.solr.cloud.ChaosMonkey; monkey: stop shard! 47753
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.708; org.apache.solr.SolrTestCaseJ4; ###Ending testDistribSearch
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.708; org.apache.solr.cloud.ZkTestServer; connecting to 127.0.0.1:23138 23138
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeyShardSplitTest-1368518849096
[junit4:junit4] 2> check const of shard1
[junit4:junit4] 2> client0
[junit4:junit4] 2> PROPS:2:{"shard":"shard1","state":"down","core":"collection1","collection":"collection1","node_name":"127.0.0.1:40433_","base_url":"http://127.0.0.1:40433"}
[junit4:junit4] 2> error contacting client: IOException occured when talking to server at: http://127.0.0.1:40433/collection1
[junit4:junit4] 2>
[junit4:junit4] 2> client1
[junit4:junit4] 2> PROPS:4:{"shard":"shard1","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:40591_","base_url":"http://127.0.0.1:40591","leader":"true"}
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:56
[junit4:junit4] 2>
[junit4:junit4] 2> check const of shard2
[junit4:junit4] 2> client0
[junit4:junit4] 2> PROPS:3:{"shard":"shard2","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:57175_","base_url":"http://127.0.0.1:57175","leader":"true"}
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:44
[junit4:junit4] 2>
[junit4:junit4] 2> client1
[junit4:junit4] 2> PROPS:5:{"shard":"shard2","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:44979_","base_url":"http://127.0.0.1:44979"}
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:44
[junit4:junit4] 2>
[junit4:junit4] 2> !!!! WARNING: best effort to remove /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368518849096 FAILED !!!!!
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeyShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=CB8E88ABF2022E95 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=de_CH -Dtests.timezone=America/Dominica -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR 176s J1 | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:40433 returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([CB8E88ABF2022E95:4A6806B3855D4EA9]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 1> INFO - 2013-05-14 08:10:24.854; org.apache.solr.SolrTestCaseJ4; ###deleteCore
[junit4:junit4] 2> 175771 T1554 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> NOTE: test params are: codec=Lucene41, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=de_CH, timezone=America/Dominica
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Oracle Corporation 1.7.0_17 (64-bit)/cpus=16,threads=2,free=327136552,total=532676608
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SolrCoreTest, TestBinaryResponseWriter, TestTrie, TestIBSimilarityFactory, TestSolrJ, TestQueryTypes, TestJmxMonitoredMap, UUIDFieldTest, MoreLikeThisHandlerTest, ZkNodePropsTest, TestComponentsName, TestPartialUpdateDeduplication, FieldAnalysisRequestHandlerTest, OpenExchangeRatesOrgProviderTest, TestSolrQueryParserDefaultOperatorResource, TestZkChroot, JsonLoaderTest, XsltUpdateRequestHandlerTest, DocumentAnalysisRequestHandlerTest, TestPropInject, ClusterStateUpdateTest, TestSweetSpotSimilarityFactory, TestLuceneMatchVersion, SolrCoreCheckLockOnStartupTest, BadIndexSchemaTest, TestWordDelimiterFilterFactory, DirectUpdateHandlerTest, SolrCmdDistributorTest, DebugComponentTest, DisMaxRequestHandlerTest, ExternalFileFieldSortTest, DateFieldTest, TestClassNameShortening, TestSolrDeletionPolicy1, RequiredFieldsTest, UpdateParamsTest, TestReversedWildcardFilterFactory, TestIndexSearcher, LoggingHandlerTest, TestCSVResponseWriter, TestRecovery, PreAnalyzedUpdateProcessorTest, TestBM25SimilarityFactory, DefaultValueUpdateProcessorTest, TestSchemaSimilarityResource, TestMultiCoreConfBootstrap, TestBinaryField, SuggesterTSTTest, TestFieldCollectionResource, ShardRoutingCustomTest, LeaderElectionIntegrationTest, CollectionsAPIDistributedZkTest, SpatialFilterTest, IndexSchemaRuntimeFieldTest, SpellCheckCollatorTest, ZkControllerTest, TestDistributedGrouping, DistanceFunctionTest, AutoCommitTest, TestSolrDeletionPolicy2, TestSolrQueryParser, LukeRequestHandlerTest, StandardRequestHandlerTest, DocValuesMultiTest, CachingDirectoryFactoryTest, DirectUpdateHandlerOptimizeTest, PrimitiveFieldTypeTest, TestStressRecovery, TestFastWriter, TestStressReorder, TestSuggestSpellingConverter, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J1 in 176.06s, 1 test, 1 error <<< FAILURES!
[...truncated 579 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/build.xml:383: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/build.xml:363: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/lucene/common-build.xml:887: There were test failures: 296 suites, 1234 tests, 1 error, 27 ignored (8 assumptions)
Total time: 65 minutes 14 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure