You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/05/12 09:13:45 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.8.0-ea-b86) - Build #
5614 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/5614/
Java: 32bit/jdk1.8.0-ea-b86 -client -XX:+UseConcMarkSweepGC
1 tests failed.
FAILED: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:60890 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:60890 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([92966F67D126457C:1370E17FA6792540]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:387)
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:490)
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 9722 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.594; org.apache.solr.BaseDistributedSearchTestCase; Setting hostContext system property: /
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.598; org.apache.solr.SolrTestCaseJ4; ###Starting testDistribSearch
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.599; 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-12 06:57:08.600; org.apache.solr.cloud.ZkTestServer$ZKServerMain; Starting server
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.700; org.apache.solr.cloud.ZkTestServer; start zk server on port:54624
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.703; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.801; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@182b80d name:ZooKeeperConnection Watcher:127.0.0.1:54624 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.802; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.802; org.apache.solr.common.cloud.SolrZkClient; makePath: /solr
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.810; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.811; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1bd2525 name:ZooKeeperConnection Watcher:127.0.0.1:54624/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.811; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.812; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.820; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/shards
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.828; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.833; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/shards
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.838; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.839; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.847; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.848; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.852; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.853; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.855; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.856; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.860; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.860; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.870; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/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-12 06:57:08.871; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.877; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.878; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.883; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.884; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.887; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.888; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-12 06:57:08.993; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.005; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:43960
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.006; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.007; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.008; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368341828894
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.008; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368341828894/solr.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.009; org.apache.solr.core.CoreContainer; New CoreContainer 6635343
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.009; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368341828894/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.010; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368341828894/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.118; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.118; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.119; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.120; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.120; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.121; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.121; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.122; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.122; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.123; 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-12 06:57:09.128; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.129; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:54624/solr
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.129; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.131; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.133; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@8c5676 name:ZooKeeperConnection Watcher:127.0.0.1:54624 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.134; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.142; 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-12 06:57:09.145; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.146; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@51d36d name:ZooKeeperConnection Watcher:127.0.0.1:54624/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.147; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.148; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.154; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/collection-queue-work
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.164; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.167; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43960_
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.169; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:43960_
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.177; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/election
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.188; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/leader
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.190; org.apache.solr.cloud.Overseer; Overseer (id=89675650079195139-127.0.0.1:43960_-n_0000000000) starting
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.192; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue-work
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.195; org.apache.solr.cloud.OverseerCollectionProcessor; Process current queue of collection creations
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.199; org.apache.solr.common.cloud.SolrZkClient; makePath: /clusterstate.json
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.204; org.apache.solr.common.cloud.SolrZkClient; makePath: /aliases.json
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.206; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.215; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Starting to work on the main queue
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.219; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368341828894/collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.220; org.apache.solr.cloud.ZkController; Check for collection zkNode:control_collection
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.222; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.223; org.apache.solr.cloud.ZkController; Load collection config from:/collections/control_collection
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.224; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368341828894/collection1/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.225; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368341828894/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.226; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368341828894/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.284; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.358; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.360; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:09.365; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.115; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.118; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.120; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.124; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.171; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.171; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368341828894/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/control/data/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.172; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1fa47a6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.172; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.173; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/control/data
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.173; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/control/data/index/
[junit4:junit4] 1> WARN - 2013-05-12 06:57:10.173; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.174; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/control/data/index
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.175; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@8e2752 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f4a30),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.176; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.177; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.178; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.178; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.179; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.180; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.180; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.189; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.189; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.189; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.192; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.200; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@166182e main
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.201; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/control/data/tlog
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.201; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.201; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.205; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@166182e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.205; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.206; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.723; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.724; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "core_node_name":"1",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "base_url":"http://127.0.0.1:43960",
[junit4:junit4] 1> "node_name":"127.0.0.1:43960_",
[junit4:junit4] 1> "state":"down"}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.724; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection control_collection with numShards 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.727; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:10.732; org.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-12 06:57:11.208; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:11.208; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:43960 collection:control_collection shard:shard1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:11.209; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-05-12 06:57:11.220; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-12 06:57:11.222; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-12 06:57:11.223; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-12 06:57:11.223; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:43960/collection1/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:11.223; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-12 06:57:11.223; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:43960/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-12 06:57:11.224; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:43960/collection1/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:11.224; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.237; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.245; org.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-12 06:57:12.283; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:43960/collection1/ and leader is http://127.0.0.1:43960/collection1/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.283; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43960
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.284; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.284; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.284; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.289; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.295; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.295; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.296; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.301; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.306; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.307; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1ff8d98 name:ZooKeeperConnection Watcher:127.0.0.1:54624/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.307; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.313; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.318; org.apache.solr.cloud.ChaosMonkey; monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.422; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.425; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:56692
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.425; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.426; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.426; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368341832318
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.427; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368341832318/solr.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.427; org.apache.solr.core.CoreContainer; New CoreContainer 19928607
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.428; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368341832318/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.429; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368341832318/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.516; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.517; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.517; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.518; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.518; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.519; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.519; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.521; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.521; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.522; 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-12 06:57:12.527; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.529; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:54624/solr
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.530; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.532; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.537; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@19b80d6 name:ZooKeeperConnection Watcher:127.0.0.1:54624 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.538; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.549; 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-12 06:57:12.570; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.572; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@e7e5bc name:ZooKeeperConnection Watcher:127.0.0.1:54624/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.573; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:12.577; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.581; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56692_
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.582; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:56692_
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.585; 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-12 06:57:13.585; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.586; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.587; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.593; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368341832318/collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.593; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.594; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.594; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.595; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368341832318/collection1/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.596; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368341832318/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.596; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368341832318/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.641; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.696; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.697; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.702; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.756; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.757; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core_node_name":"1",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "base_url":"http://127.0.0.1:43960",
[junit4:junit4] 1> "node_name":"127.0.0.1:43960_",
[junit4:junit4] 1> "state":"active"}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:13.761; org.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-12 06:57:13.761; org.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-12 06:57:13.761; org.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-12 06:57:14.281; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.284; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.285; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.289; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.306; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.307; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368341832318/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty1/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.307; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1fa47a6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.307; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.308; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.308; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty1/index/
[junit4:junit4] 1> WARN - 2013-05-12 06:57:14.308; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.309; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty1/index
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.310; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1079263 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f13aa7),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.310; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.312; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.312; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.312; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.313; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.318; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.318; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.319; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.319; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.320; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.322; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.324; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@deba0f main
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.325; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty1/tlog
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.325; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.326; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.330; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@deba0f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.332; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-12 06:57:14.332; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.265; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.266; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "core_node_name":"2",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "base_url":"http://127.0.0.1:56692",
[junit4:junit4] 1> "node_name":"127.0.0.1:56692_",
[junit4:junit4] 1> "state":"down"}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.266; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection collection1 with numShards 2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.266; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.305; org.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-12 06:57:15.305; org.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-12 06:57:15.305; org.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-12 06:57:15.333; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.333; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:56692 collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.334; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.339; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.341; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.342; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.342; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:56692/collection1/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.342; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.343; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:56692/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.343; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:56692/collection1/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:15.343; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.809; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.815; org.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-12 06:57:16.815; org.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-12 06:57:16.815; org.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-12 06:57:16.851; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:56692/collection1/ and leader is http://127.0.0.1:56692/collection1/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.852; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56692
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.852; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.852; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.852; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.854; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.855; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.856; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.856; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.948; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.950; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:60890
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.951; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.952; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.952; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368341836861
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.953; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368341836861/solr.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.953; org.apache.solr.core.CoreContainer; New CoreContainer 20973289
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.954; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368341836861/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:16.954; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368341836861/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.018; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.018; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.019; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.019; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.019; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.020; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.020; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.020; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.021; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.021; 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-12 06:57:17.024; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.025; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:54624/solr
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.025; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.026; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.042; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@efc064 name:ZooKeeperConnection Watcher:127.0.0.1:54624 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.042; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.062; 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-12 06:57:17.065; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.066; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@f1d989 name:ZooKeeperConnection Watcher:127.0.0.1:54624/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.067; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:17.070; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.073; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60890_
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.083; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:60890_
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.086; 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-12 06:57:18.086; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.086; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.086; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.086; 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-12 06:57:18.086; 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-12 06:57:18.088; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.097; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368341836861/collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.097; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.098; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.098; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.099; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368341836861/collection1/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.099; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368341836861/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.099; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368341836861/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.149; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.220; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.221; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.227; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.319; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.320; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "core_node_name":"2",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "base_url":"http://127.0.0.1:56692",
[junit4:junit4] 1> "node_name":"127.0.0.1:56692_",
[junit4:junit4] 1> "state":"active"}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.335; org.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-12 06:57:18.335; org.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-12 06:57:18.335; org.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-12 06:57:18.335; org.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-12 06:57:18.799; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.802; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.804; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.808; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.835; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.835; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368341836861/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty2/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.835; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1fa47a6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.836; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.836; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.836; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty2/index/
[junit4:junit4] 1> WARN - 2013-05-12 06:57:18.837; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.837; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty2/index
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.838; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1c6013 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c8ad4a),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.839; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.840; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.841; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.841; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.842; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.842; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.842; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.843; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.843; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.844; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.846; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.848; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@131fa22 main
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.849; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty2/tlog
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.849; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.850; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.854; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@131fa22 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.856; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-12 06:57:18.856; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-12 06:57:19.839; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:19.840; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "core_node_name":"3",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "base_url":"http://127.0.0.1:60890",
[junit4:junit4] 1> "node_name":"127.0.0.1:60890_",
[junit4:junit4] 1> "state":"down"}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:19.840; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:19.840; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:19.843; org.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-12 06:57:19.843; org.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-12 06:57:19.844; org.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-12 06:57:19.847; org.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-12 06:57:20.858; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:20.858; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:60890 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:20.859; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-05-12 06:57:20.863; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-12 06:57:20.865; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-12 06:57:20.866; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-12 06:57:20.866; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:60890/collection1/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:20.866; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-12 06:57:20.866; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:60890/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-12 06:57:20.867; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:60890/collection1/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:20.867; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.442; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.448; org.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-12 06:57:21.448; org.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-12 06:57:21.448; org.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-12 06:57:21.448; org.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-12 06:57:21.472; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:60890/collection1/ and leader is http://127.0.0.1:60890/collection1/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.473; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60890
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.473; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.473; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.474; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.475; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.481; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.481; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.482; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.563; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.565; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:59085
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.566; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.566; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.567; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368341841485
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.567; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368341841485/solr.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.567; org.apache.solr.core.CoreContainer; New CoreContainer 17296496
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.568; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368341841485/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.568; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368341841485/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.645; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.645; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.646; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.646; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.647; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.647; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.647; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.648; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.648; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.648; 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-12 06:57:21.651; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.652; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:54624/solr
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.652; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.653; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.654; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@58a877 name:ZooKeeperConnection Watcher:127.0.0.1:54624 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.655; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.656; 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-12 06:57:21.659; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.661; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@ddcb3 name:ZooKeeperConnection Watcher:127.0.0.1:54624/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.662; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:21.762; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.765; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59085_
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.767; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:59085_
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.769; 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-12 06:57:22.770; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.770; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.771; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.770; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.772; 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-12 06:57:22.770; 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-12 06:57:22.771; 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-12 06:57:22.780; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.785; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368341841485/collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.785; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.786; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.786; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.787; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368341841485/collection1/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.788; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368341841485/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.788; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368341841485/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.821; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.874; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.876; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.879; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.954; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.955; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core_node_name":"3",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "base_url":"http://127.0.0.1:60890",
[junit4:junit4] 1> "node_name":"127.0.0.1:60890_",
[junit4:junit4] 1> "state":"active"}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:22.958; org.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-12 06:57:22.958; org.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-12 06:57:22.958; org.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-12 06:57:22.958; org.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-12 06:57:22.958; org.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-12 06:57:23.402; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.405; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.407; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.411; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.435; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.435; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368341841485/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty3/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.435; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1fa47a6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.436; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.436; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.436; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty3/index/
[junit4:junit4] 1> WARN - 2013-05-12 06:57:23.436; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.437; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty3/index
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.438; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@16c2bb4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a10a7b),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.438; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.440; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.440; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.441; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.442; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.442; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.442; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.443; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.443; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.444; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.447; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.449; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@a84af5 main
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.449; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty3/tlog
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.450; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.450; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.455; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@a84af5 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.457; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-12 06:57:23.457; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-12 06:57:24.463; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:24.464; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "core_node_name":"4",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59085",
[junit4:junit4] 1> "node_name":"127.0.0.1:59085_",
[junit4:junit4] 1> "state":"down"}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:24.464; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:24.464; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:24.521; org.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-12 06:57:24.521; org.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-12 06:57:24.521; org.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-12 06:57:24.521; org.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-12 06:57:24.521; org.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-12 06:57:25.458; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.459; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:59085 collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.461; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:59085/collection1/ and leader is http://127.0.0.1:56692/collection1/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.461; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59085
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.462; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.462; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.465; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.466; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.466; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.467; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.467; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.467; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.468; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.468; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.469; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.475; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.574; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.583; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:45953
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.583; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.584; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.584; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.585; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472/solr.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.585; org.apache.solr.core.CoreContainer; New CoreContainer 31689320
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.585; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.586; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.658; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.658; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.659; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.659; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.660; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.660; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.660; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.661; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.661; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.661; 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-12 06:57:25.665; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.666; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:54624/solr
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.666; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.667; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.669; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@a87c84 name:ZooKeeperConnection Watcher:127.0.0.1:54624 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.669; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.671; 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-12 06:57:25.682; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.683; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1ab897b name:ZooKeeperConnection Watcher:127.0.0.1:54624/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.684; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-12 06:57:25.687; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.031; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.032; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "core_node_name":"4",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59085",
[junit4:junit4] 1> "node_name":"127.0.0.1:59085_",
[junit4:junit4] 1> "state":"recovering"}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.036; org.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-12 06:57:26.036; org.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-12 06:57:26.036; org.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-12 06:57:26.036; org.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-12 06:57:26.036; org.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-12 06:57:26.036; org.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-12 06:57:26.476; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.477; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={onlyIfLeader=true&coreNodeName=4&checkLive=true&core=collection1&action=PREPRECOVERY&nodeName=127.0.0.1:59085_&version=2&wt=javabin&state=recovering} status=0 QTime=1002
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.689; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45953_
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.691; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:45953_
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.692; 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-12 06:57:26.693; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.693; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.693; 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-12 06:57:26.693; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.693; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.694; 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-12 06:57:26.694; 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-12 06:57:26.693; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.695; 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-12 06:57:26.693; 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-12 06:57:26.694; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.702; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472/collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.702; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.703; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.703; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.704; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472/collection1/'
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.704; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.705; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.784; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.839; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.840; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:26.850; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.405; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.409; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.411; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.426; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.449; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.450; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty4/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.450; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1fa47a6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.451; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.451; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.452; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty4/index/
[junit4:junit4] 1> WARN - 2013-05-12 06:57:27.452; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.453; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty4/index
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.454; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@63d17f lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ca013),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.455; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.457; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.458; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.458; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.459; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.460; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.460; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.461; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.462; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.462; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.466; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.470; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@32d334 main
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.471; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty4/tlog
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.471; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.472; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.486; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.486; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.486; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@32d334 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.541; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.542; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "core_node_name":"5",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "base_url":"http://127.0.0.1:45953",
[junit4:junit4] 1> "node_name":"127.0.0.1:45953_",
[junit4:junit4] 1> "state":"down"}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.542; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.542; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:27.546; org.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-12 06:57:27.546; org.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-12 06:57:27.546; org.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-12 06:57:27.546; org.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-12 06:57:27.546; org.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-12 06:57:27.546; org.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-12 06:57:28.478; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:56692/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.481; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.486; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:59085 START replicas=[http://127.0.0.1:56692/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-05-12 06:57:28.489; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.490; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.490; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.490; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.491; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.491; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:56692/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.491; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.499; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={distrib=false&getVersions=100&version=2&wt=javabin&qt=/get} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.509; 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-12 06:57:28.510; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1079263 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f13aa7),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.510; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.511; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1079263 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f13aa7),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1079263 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f13aa7),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.511; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.511; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1c77e3e realtime
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.512; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.512; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={softCommit=false&waitSearcher=true&openSearcher=false&commit=true&version=2&wt=javabin&commit_end_point=true} {commit=} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.532; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.533; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:45953 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.535; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:45953/collection1/ and leader is http://127.0.0.1:60890/collection1/
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.536; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:45953
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.536; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.536; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.537; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.539; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.539; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.539; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.540; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.540; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.541; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.541; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.542; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.542; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.546; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.549; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.549; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.550; org.apache.solr.cloud.AbstractFullDistribZkTestBase; Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.550; org.apache.solr.cloud.AbstractDistribZkTestBase; Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.553; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.553; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.556; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.557; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&version=2&qt=/replication&wt=javabin} status=0 QTime=6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.557; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.558; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.558; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.560; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&generation=2&version=2&qt=/replication&wt=javabin} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.561; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.562; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty3/index.20130512095728561
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.562; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@7f3747 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fd0da6) fullCopy=false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.568; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filecontent&generation=2&checksum=true&file=segments_2&wt=filestream&qt=/replication} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.570; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.571; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.571; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.573; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@16c2bb4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a10a7b),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@16c2bb4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a10a7b),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.573; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.574; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.574; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@c1e7dc main
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.576; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@c1e7dc main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.581; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty3/index.20130512095728561 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty3/index.20130512095728561;done=true>>]
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.581; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty3/index.20130512095728561
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.582; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty3/index.20130512095728561
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.582; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.582; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.582; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.582; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-12 06:57:28.584; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:29.051; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:29.052; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core_node_name":"5",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "base_url":"http://127.0.0.1:45953",
[junit4:junit4] 1> "node_name":"127.0.0.1:45953_",
[junit4:junit4] 1> "state":"recovering"}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:29.055; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "core_node_name":"4",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59085",
[junit4:junit4] 1> "node_name":"127.0.0.1:59085_",
[junit4:junit4] 1> "state":"active"}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:29.058; org.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-12 06:57:29.059; org.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-12 06:57:29.058; org.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-12 06:57:29.059; org.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-12 06:57:29.059; org.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-12 06:57:29.059; org.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-12 06:57:29.555; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-05-12 06:57:29.555; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={onlyIfLeader=true&coreNodeName=5&checkLive=true&core=collection1&action=PREPRECOVERY&nodeName=127.0.0.1:45953_&version=2&wt=javabin&state=recovering} status=0 QTime=1002
[junit4:junit4] 1> INFO - 2013-05-12 06:57:29.556; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:30.558; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.557; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:60890/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.557; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:45953 START replicas=[http://127.0.0.1:60890/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-05-12 06:57:31.558; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.558; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.558; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.558; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.559; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.559; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:60890/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.559; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.560; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.569; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={distrib=false&getVersions=100&version=2&wt=javabin&qt=/get} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.573; 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-12 06:57:31.576; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1c6013 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c8ad4a),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.577; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.577; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1c6013 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c8ad4a),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1c6013 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c8ad4a),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.578; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.578; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@e919fe realtime
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.579; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.579; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={softCommit=false&waitSearcher=true&openSearcher=false&commit=true&version=2&wt=javabin&commit_end_point=true} {commit=} 0 6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.580; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.580; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.582; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.582; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&version=2&qt=/replication&wt=javabin} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.583; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.583; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.590; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.592; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&generation=2&version=2&qt=/replication&wt=javabin} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.593; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.594; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty4/index.20130512095731593
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.594; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@18a9719 lockFactory=org.apache.lucene.store.NativeFSLockFactory@676570) fullCopy=false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.596; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filecontent&generation=2&checksum=true&file=segments_2&wt=filestream&qt=/replication} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.598; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.598; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.598; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.599; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@63d17f lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ca013),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@63d17f lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ca013),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.600; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.600; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.601; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1ad0e83 main
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.602; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1ad0e83 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.603; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty4/index.20130512095731593 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty4/index.20130512095731593;done=true>>]
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.603; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty4/index.20130512095731593
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.604; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599/jetty4/index.20130512095731593
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.604; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.604; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.604; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.604; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-12 06:57:31.605; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.065; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.066; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core_node_name":"5",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "base_url":"http://127.0.0.1:45953",
[junit4:junit4] 1> "node_name":"127.0.0.1:45953_",
[junit4:junit4] 1> "state":"active"}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.071; org.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-12 06:57:32.071; org.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-12 06:57:32.071; org.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-12 06:57:32.071; org.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-12 06:57:32.071; org.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-12 06:57:32.071; org.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-12 06:57:32.562; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.563; org.apache.solr.cloud.AbstractDistribZkTestBase; Recoveries finished - collection: collection1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.569; 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-12 06:57:32.570; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@8e2752 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f4a30),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.571; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.571; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@8e2752 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f4a30),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@8e2752 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f4a30),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.572; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.572; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1d3faee main
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.572; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.574; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1d3faee main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.575; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={softCommit=false&waitSearcher=true&commit=true&version=2&wt=javabin} {commit=} 0 6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.594; 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-12 06:57:32.595; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1c6013 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c8ad4a),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1c6013 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c8ad4a),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.595; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.596; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1b914dc main
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.596; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.597; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1b914dc main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.597; org.apache.solr.update.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:45953/collection1/, StdNode: http://127.0.0.1:56692/collection1/, StdNode: http://127.0.0.1:59085/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.604; 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-12 06:57:32.609; 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-12 06:57:32.610; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1079263 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f13aa7),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1079263 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f13aa7),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.610; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.611; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@16c2bb4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a10a7b),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@16c2bb4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a10a7b),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.611; 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-12 06:57:32.611; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@44cf50 main
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.611; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.612; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.612; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@63d17f lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ca013),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@63d17f lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ca013),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.614; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@44cf50 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.613; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@8ea563 main
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.614; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={softCommit=false&waitSearcher=true&commit=true&version=2&expungeDeletes=false&wt=javabin&commit_end_point=true} {commit=} 0 10
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.614; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.615; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@8ea563 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.614; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.616; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@5072be main
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.616; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={softCommit=false&waitSearcher=true&commit=true&version=2&expungeDeletes=false&wt=javabin&commit_end_point=true} {commit=} 0 7
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.617; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.617; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@5072be main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.624; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={softCommit=false&waitSearcher=true&commit=true&version=2&expungeDeletes=false&wt=javabin&commit_end_point=true} {commit=} 0 13
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.626; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={softCommit=false&waitSearcher=true&commit=true&version=2&wt=javabin} {commit=} 0 32
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.627; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.636; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={rows=0&tests=checkShardConsistency&distrib=false&q=*:*&version=2&wt=javabin} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.638; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={rows=0&tests=checkShardConsistency&distrib=false&q=*:*&version=2&wt=javabin} hits=0 status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.640; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={rows=0&tests=checkShardConsistency&distrib=false&q=*:*&version=2&wt=javabin} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:32.642; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={rows=0&tests=checkShardConsistency&distrib=false&q=*:*&version=2&wt=javabin} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.646; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {deleteByQuery=*:* (-1434810428576235520)} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.653; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1434810428580429824&update.from=http://127.0.0.1:60890/collection1/&version=2&wt=javabin} {deleteByQuery=*:* (-1434810428580429824)} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.655; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1434810428583575552&update.from=http://127.0.0.1:56692/collection1/&version=2&wt=javabin} {deleteByQuery=*:* (-1434810428583575552)} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.656; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin} {deleteByQuery=*:* (-1434810428583575552)} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.657; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {deleteByQuery=*:* (-1434810428580429824)} 0 9
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.660; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[0 (1434810428590915584)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.668; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[0 (1434810428597207040)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.669; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[0 (1434810428597207040)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.670; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[0]} 0 8
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.673; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[1 (1434810428604547072)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.686; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[1 (1434810428617129984)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.687; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[1 (1434810428617129984)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.688; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[1]} 0 9
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.691; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[2 (1434810428624470016)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.699; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[2 (1434810428629712896)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.700; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[2 (1434810428629712896)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.700; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[2]} 0 6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.703; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[3 (1434810428637052928)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.710; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[3 (1434810428641247232)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.711; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[3 (1434810428641247232)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.714; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[4 (1434810428647538688)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.719; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[4 (1434810428650684416)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.720; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[4 (1434810428650684416)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.723; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[5 (1434810428658024448)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.731; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[5 (1434810428664315904)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.732; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[5 (1434810428664315904)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.733; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[5]} 0 7
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.739; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[6 (1434810428674801664)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.750; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[6 (1434810428683190272)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.751; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[6 (1434810428683190272)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.754; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[7 (1434810428690530304)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.759; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[7 (1434810428693676032)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.760; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[7 (1434810428693676032)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.767; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[8 (1434810428703113216)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.773; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[8 (1434810428707307520)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.774; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[8 (1434810428707307520)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.777; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[9 (1434810428714647552)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.784; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[9 (1434810428719890432)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.785; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[9 (1434810428719890432)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.786; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[9]} 0 6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.792; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[10 (1434810428730376192)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.799; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[10 (1434810428735619072)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.800; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[10 (1434810428735619072)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.801; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[10]} 0 6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.804; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[11 (1434810428741910528)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.809; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[11 (1434810428745056256)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.810; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[11 (1434810428745056256)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.817; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[12 (1434810428755542016)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.822; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[12 (1434810428758687744)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.823; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[12 (1434810428758687744)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.826; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[13 (1434810428764979200)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.831; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[13 (1434810428769173504)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.832; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[13 (1434810428769173504)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.835; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[14 (1434810428775464960)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.842; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[14 (1434810428780707840)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.843; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[14 (1434810428780707840)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.844; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[14]} 0 7
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.847; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[15 (1434810428788047872)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.852; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[15 (1434810428791193600)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.853; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[15 (1434810428791193600)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.857; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[16 (1434810428797485056)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.864; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[16 (1434810428802727936)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.865; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[16 (1434810428802727936)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.866; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[16]} 0 7
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.869; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[17 (1434810428811116544)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.878; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[17 (1434810428817408000)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.879; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[17 (1434810428817408000)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.880; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[17]} 0 8
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.883; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[18 (1434810428824748032)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.889; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[18 (1434810428827893760)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.890; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[18 (1434810428827893760)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.893; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[19 (1434810428835233792)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.921; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[19 (1434810428839428096)]} 0 23
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.922; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[19 (1434810428839428096)]} 0 27
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.930; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[20 (1434810428875079680)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.937; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[20 (1434810428880322560)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.938; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[20 (1434810428880322560)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.939; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[20]} 0 6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.942; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[21 (1434810428887662592)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.947; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[21 (1434810428890808320)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.948; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[21 (1434810428890808320)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.951; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[22 (1434810428897099776)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.958; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[22 (1434810428902342656)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.959; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[22 (1434810428902342656)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.960; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[22]} 0 6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.963; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[23 (1434810428909682688)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.970; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[23 (1434810428914925568)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.971; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[23 (1434810428914925568)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.972; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[23]} 0 6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.975; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[24 (1434810428921217024)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.983; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[24 (1434810428927508480)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.983; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[24 (1434810428927508480)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.984; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[24]} 0 6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.987; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[25 (1434810428934848512)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.994; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[25 (1434810428939042816)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.995; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[25 (1434810428939042816)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.995; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[25]} 0 6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:34.998; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[26 (1434810428946382848)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.006; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[26 (1434810428952674304)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.007; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[26 (1434810428952674304)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.008; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[26]} 0 7
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.011; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[27 (1434810428958965760)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.016; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[27 (1434810428962111488)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.016; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[27 (1434810428962111488)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.019; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[28 (1434810428968402944)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.026; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[28 (1434810428973645824)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.027; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[28 (1434810428973645824)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.027; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[28]} 0 5
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.030; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[29 (1434810428979937280)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.036; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[29 (1434810428984131584)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.037; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[29 (1434810428984131584)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.039; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[30 (1434810428989374464)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.045; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[30 (1434810428993568768)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.046; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[30 (1434810428993568768)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.047; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[30]} 0 6
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.049; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[31 (1434810428999860224)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.056; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[31 (1434810429004054528)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.057; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[31 (1434810429004054528)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.057; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[31]} 0 5
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.060; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[32 (1434810429011394560)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.065; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[32 (1434810429013491712)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.066; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[32 (1434810429013491712)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.070; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[33 (1434810429020831744)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.074; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[33 (1434810429023977472)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.075; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[33 (1434810429023977472)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.078; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[34 (1434810429030268928)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.084; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[34 (1434810429034463232)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.085; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[34 (1434810429034463232)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.085; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[34]} 0 5
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.088; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[35 (1434810429040754688)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.095; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[35 (1434810429045997568)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.095; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[35 (1434810429045997568)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.096; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[35]} 0 5
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.098; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[36 (1434810429051240448)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.105; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[36 (1434810429056483328)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.106; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[36 (1434810429056483328)]} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.106; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[36]} 0 5
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.109; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[37 (1434810429061726208)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.118; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[37 (1434810429070114816)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.119; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[37 (1434810429070114816)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.120; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[37]} 0 8
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.122; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[38 (1434810429076406272)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.127; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[38 (1434810429078503424)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.127; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[38 (1434810429078503424)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.130; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[39 (1434810429084794880)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.134; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:56692/collection1/} {add=[39 (1434810429086892032)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.135; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[39 (1434810429086892032)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.138; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[40 (1434810429093183488)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.143; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[40 (1434810429096329216)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.144; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[40 (1434810429096329216)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.148; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[41 (1434810429102620672)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 06:57:35.153; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&version=2&wt=javabin&distrib.from=http://127.0.0.1:60890/collection1/} {add=[4
[...truncated too long message...]
2013-05-12 07:00:27.368; org.apache.solr.update.SolrCoreState; Closing SolrCoreState
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.368; org.apache.solr.update.DefaultSolrCoreState; SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.368; org.apache.solr.update.DefaultSolrCoreState; closing IndexWriter with IndexWriterCloser
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.369; org.apache.solr.core.SolrCore; [collection1_shard1_1_replica1] Closing main searcher on request.
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.370; org.apache.solr.core.CachingDirectoryFactory; Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.370; org.apache.solr.core.CachingDirectoryFactory; looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472/collection1_shard1_1_replica1/data/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472/collection1_shard1_1_replica1/data/index;done=false>>]
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.371; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472/collection1_shard1_1_replica1/data/index
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.371; org.apache.solr.core.CachingDirectoryFactory; looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472/collection1_shard1_1_replica1/data [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472/collection1_shard1_1_replica1/data;done=false>>]
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.372; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368341845472/collection1_shard1_1_replica1/data
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.373; org.apache.solr.cloud.Overseer$ClusterStateUpdater; According to ZK I (id=89675650079195148-127.0.0.1:45953_-n_0000000004) am no longer a leader.
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.373; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> WARN - 2013-05-12 07:00:27.374; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 07:00:27.374; org.apache.solr.common.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.396; org.eclipse.jetty.server.handler.ContextHandler; stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.457; org.apache.solr.SolrTestCaseJ4; ###Ending testDistribSearch
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.459; org.apache.solr.cloud.ZkTestServer; connecting to 127.0.0.1:54624 54624
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.461; org.apache.solr.cloud.ChaosMonkey; monkey: stop shard! 43960
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.461; org.apache.solr.SolrTestCaseJ4; ###Ending testDistribSearch
[junit4:junit4] 1> INFO - 2013-05-12 07:00:27.462; org.apache.solr.cloud.ZkTestServer; connecting to 127.0.0.1:54624 54624
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeyShardSplitTest-1368341828599
[junit4:junit4] 2> check const of shard2
[junit4:junit4] 2> client0
[junit4:junit4] 2> PROPS:2:{"shard":"shard2","core":"collection1","collection":"collection1","base_url":"http://127.0.0.1:56692","node_name":"127.0.0.1:56692_","state":"active","leader":"true"}
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:48
[junit4:junit4] 2>
[junit4:junit4] 2> client1
[junit4:junit4] 2> PROPS:4:{"shard":"shard2","core":"collection1","collection":"collection1","base_url":"http://127.0.0.1:59085","node_name":"127.0.0.1:59085_","state":"active"}
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:48
[junit4:junit4] 2>
[junit4:junit4] 2> check const of shard1
[junit4:junit4] 2> client0
[junit4:junit4] 2> PROPS:3:{"shard":"shard1","core":"collection1","collection":"collection1","base_url":"http://127.0.0.1:60890","node_name":"127.0.0.1:60890_","state":"down"}
[junit4:junit4] 2> error contacting client: Server refused connection at: http://127.0.0.1:60890/collection1
[junit4:junit4] 2>
[junit4:junit4] 2> client1
[junit4:junit4] 2> PROPS:5:{"shard":"shard1","core":"collection1","collection":"collection1","base_url":"http://127.0.0.1:45953","node_name":"127.0.0.1:45953_","state":"active","leader":"true"}
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:63
[junit4:junit4] 2>
[junit4:junit4] 2> !!!! WARNING: best effort to remove /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368341828599 FAILED !!!!!
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeyShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=92966F67D126457C -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=en_IN -Dtests.timezone=Europe/Sofia -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR 199s J1 | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:60890 returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([92966F67D126457C:1370E17FA6792540]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:387)
[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-12 07:00:27.476; org.apache.solr.SolrTestCaseJ4; ###deleteCore
[junit4:junit4] 2> 198885 T514 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {_version_=PostingsFormat(name=MockRandom), id=MockVariableIntBlock(baseBlockSize=108)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {}, locale=en_IN, timezone=Europe/Sofia
[junit4:junit4] 2> NOTE: Linux 3.2.0-41-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=2,free=59635600,total=128962560
[junit4:junit4] 2> NOTE: All tests run in this JVM: [DisMaxRequestHandlerTest, FieldAnalysisRequestHandlerTest, TestRTGBase, TestArbitraryIndexDir, PingRequestHandlerTest, HighlighterConfigTest, TestManagedSchema, SolrCmdDistributorTest, MultiTermTest, NoCacheHeaderTest, SimplePostToolTest, CopyFieldTest, DocumentAnalysisRequestHandlerTest, DistanceFunctionTest, TestQuerySenderNoQuery, DefaultValueUpdateProcessorTest, TestPartialUpdateDeduplication, SolrCoreCheckLockOnStartupTest, DirectUpdateHandlerTest, CurrencyFieldXmlFileTest, FileUtilsTest, CollectionsAPIDistributedZkTest, DOMUtilTest, TestDefaultSimilarityFactory, TestNumberUtils, DebugComponentTest, TestCollationField, TestDFRSimilarityFactory, StatsComponentTest, TestFiltering, SpellCheckComponentTest, TestJmxIntegration, OpenExchangeRatesOrgProviderTest, TestBM25SimilarityFactory, HardAutoCommitTest, TestReload, TestAddFieldRealTimeGet, LeaderElectionIntegrationTest, TestAtomicUpdateErrorCases, TestFieldTypeResource, BadIndexSchemaTest, TimeZoneUtilsTest, SortByFunctionTest, BasicDistributedZk2Test, TestRangeQuery, TestFastOutputStream, ConvertedLegacyTest, TestUtils, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J1 in 199.69s, 1 test, 1 error <<< FAILURES!
[...truncated 564 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:377: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:357: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1240: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:884: There were test failures: 294 suites, 1225 tests, 1 error, 16 ignored (7 assumptions)
Total time: 41 minutes 6 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.8.0-ea-b86 -client -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
[JENKINS] Lucene-Solr-trunk-Linux (64bit/jdk1.7.0_21) - Build #
5615 - Still Failing!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/5615/
Java: 64bit/jdk1.7.0_21 -XX:+UseCompressedOops -XX:+UseG1GC
1 tests failed.
REGRESSION: org.apache.solr.request.TestRemoteStreaming.testQtUpdateFails
Error Message:
IOException occured when talking to server at: https://127.0.0.1:50584/solr/collection1
Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:50584/solr/collection1
at __randomizedtesting.SeedInfo.seed([6289A0DF930E9789:368BB43A5F3E12D3]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:435)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:168)
at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:146)
at org.apache.solr.request.TestRemoteStreaming.doBefore(TestRemoteStreaming.java:60)
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$7.evaluate(RandomizedRunner.java:771)
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)
Caused by: org.apache.http.NoHttpResponseException: The target server failed to respond
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:95)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)
at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)
at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)
at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:717)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:522)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
... 44 more
Build Log:
[...truncated 9772 lines...]
[junit4:junit4] Suite: org.apache.solr.request.TestRemoteStreaming
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.659; org.apache.solr.SolrJettyTestBase; Randomized ssl (true) and clientAuth (false)
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.660; org.apache.solr.SolrTestCaseJ4; ####initCore
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.660; org.apache.solr.SolrTestCaseJ4; ####initCore end
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.661; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.666; org.eclipse.jetty.util.ssl.SslContextFactory; Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.685; org.eclipse.jetty.server.AbstractConnector; Started SslSelectChannelConnector@127.0.0.1:50584
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.686; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.687; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.687; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: solr/
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.688; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/solr/solr.xml
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.688; org.apache.solr.core.CoreContainer; New CoreContainer 816046378
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.688; org.apache.solr.core.CoreContainer$Initializer; no solr.xml found. using default old-style solr.xml
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.689; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: 'solr/'
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.689; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: 'solr/'
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.734; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 0
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.734; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.735; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 0
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.735; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.735; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.736; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.736; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.736; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.737; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.737; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.741; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.745; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: solr/collection1
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.746; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: 'solr/collection1/'
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.775; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.814; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.815; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-12 08:35:24.819; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.150; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.156; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.158; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.167; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.170; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.172; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-05-12 08:35:25.173; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-05-12 08:35:25.173; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.173; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-05-12 08:35:25.174; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-05-12 08:35:25.174; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.174; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.175; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at solr/collection1/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/solrtest-TestRemoteStreaming-1368347724660/
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.175; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@ce6e2f2
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.175; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.176; org.apache.solr.core.CachingDirectoryFactory; return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/solrtest-TestRemoteStreaming-1368347724660
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.176; org.apache.solr.core.SolrCore; New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/solrtest-TestRemoteStreaming-1368347724660/index/
[junit4:junit4] 1> WARN - 2013-05-12 08:35:25.176; org.apache.solr.core.SolrCore; [collection1] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/solrtest-TestRemoteStreaming-1368347724660/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.177; org.apache.solr.core.CachingDirectoryFactory; return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/solrtest-TestRemoteStreaming-1368347724660/index
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.178; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=RateLimitedDirectoryWrapper(MockDirWrapper(org.apache.lucene.store.RAMDirectory@57642847 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bbf5d99)),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.178; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.179; org.apache.solr.core.SolrCore; created xml: solr.XMLResponseWriter
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.180; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.180; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.181; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.181; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.182; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.182; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.182; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.182; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.183; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.183; org.apache.solr.core.RequestHandlers; created dismax: solr.SearchHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.184; org.apache.solr.core.RequestHandlers; created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.184; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.184; org.apache.solr.core.RequestHandlers; created defaults: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.184; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.185; org.apache.solr.core.RequestHandlers; created lazy: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.185; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.185; org.apache.solr.core.RequestHandlers; created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.186; org.apache.solr.core.RequestHandlers; created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.186; org.apache.solr.core.RequestHandlers; created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.187; org.apache.solr.core.RequestHandlers; created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.187; org.apache.solr.core.RequestHandlers; created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.187; org.apache.solr.core.RequestHandlers; created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.188; org.apache.solr.core.RequestHandlers; created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.188; org.apache.solr.core.RequestHandlers; created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.188; org.apache.solr.core.RequestHandlers; created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.189; org.apache.solr.core.RequestHandlers; created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.191; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> WARN - 2013-05-12 08:35:25.193; org.apache.solr.core.SolrCore; solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 1> WARN - 2013-05-12 08:35:25.193; org.apache.solr.core.SolrCore; adding ShowFileRequestHandler with hidden files: []
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.194; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@b5e2a8d main
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.195; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.195; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.196; org.apache.solr.handler.component.SpellCheckComponent; Initializing spell checkers
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.309; org.apache.solr.spelling.DirectSolrSpellChecker; init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.328; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@b5e2a8d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.333; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.334; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.334; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.334; org.apache.solr.SolrJettyTestBase; Jetty Assigned Port#50584
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-TestRemoteStreaming-1368347724660
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.341; org.apache.solr.SolrTestCaseJ4; ###Starting testQtUpdateFails
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.341; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.440; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=RateLimitedDirectoryWrapper(MockDirWrapper(org.apache.lucene.store.RAMDirectory@57642847 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bbf5d99)),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.442; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-12 08:35:25.443; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[1234]} 0 4
[junit4:junit4] 1> WARN - 2013-05-12 08:36:47.055; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:36:47.739; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:36:57.280; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:36:57.579; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:02.207; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:03.919; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:05.541; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:07.155; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:08.868; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:10.484; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:12.094; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:13.709; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:15.318; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:17.030; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:18.738; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:20.449; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:22.058; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:23.669; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:25.426; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:27.142; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:31.229; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:33.394; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-12 08:37:42.622; org.apache.solr.cloud.OverseerCollectionProcessor; Overseer cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.675; org.apache.solr.SolrTestCaseJ4; ###Ending testQtUpdateFails
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.675; 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-12 08:38:45.678; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=RateLimitedDirectoryWrapper(MockDirWrapper(org.apache.lucene.store.RAMDirectory@57642847 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bbf5d99)),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=RateLimitedDirectoryWrapper(MockDirWrapper(org.apache.lucene.store.RAMDirectory@57642847 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bbf5d99)),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.678; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.680; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@3d8b5316 main
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.680; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.682; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@3d8b5316 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C1)}
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.683; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestRemoteStreaming -Dtests.method=testQtUpdateFails -Dtests.seed=6289A0DF930E9789 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_LY -Dtests.timezone=America/Phoenix -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR 200s J0 | TestRemoteStreaming.testQtUpdateFails <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:50584/solr/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([6289A0DF930E9789:368BB43A5F3E12D3]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:435)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
[junit4:junit4] > at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:168)
[junit4:junit4] > at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:146)
[junit4:junit4] > at org.apache.solr.request.TestRemoteStreaming.doBefore(TestRemoteStreaming.java:60)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] > Caused by: org.apache.http.NoHttpResponseException: The target server failed to respond
[junit4:junit4] > at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:95)
[junit4:junit4] > at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)
[junit4:junit4] > at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)
[junit4:junit4] > at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)
[junit4:junit4] > at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)
[junit4:junit4] > at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)
[junit4:junit4] > at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)
[junit4:junit4] > at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)
[junit4:junit4] > at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:717)
[junit4:junit4] > at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:522)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
[junit4:junit4] > ... 44 more
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.709; org.apache.solr.SolrTestCaseJ4; ###Starting testNoUrlAccess
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.720; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[1234]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.724; 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-12 08:38:45.726; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=RateLimitedDirectoryWrapper(MockDirWrapper(org.apache.lucene.store.RAMDirectory@57642847 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bbf5d99)),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=RateLimitedDirectoryWrapper(MockDirWrapper(org.apache.lucene.store.RAMDirectory@57642847 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bbf5d99)),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.727; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.728; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@54e9eeb6 main
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.728; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.730; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@54e9eeb6 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)}
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.730; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.734; org.apache.solr.core.SolrCore; [collection1] webapp=/solr path=/select params={q=id:1234&wt=javabin&version=2} hits=1 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.738; org.apache.solr.core.SolrCore; [collection1] webapp=/solr path=/select params={stream.url=https://127.0.0.1:50584/solr/collection1/update?commit%3Dtrue%26stream.body%3D%253Cdelete%253E%253Cquery%253E*%253A*%253C%252Fquery%253E%253C%252Fdelete%253E&q=*:*&wt=javabin&version=2} hits=1 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.742; org.apache.solr.core.SolrCore; [collection1] webapp=/solr path=/select params={q=id:1234&wt=javabin&version=2} hits=1 status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.743; org.apache.solr.SolrTestCaseJ4; ###Ending testNoUrlAccess
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.748; org.apache.solr.SolrTestCaseJ4; ###Starting testStreamUrl
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.752; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[1234]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.756; 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-12 08:38:45.758; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=RateLimitedDirectoryWrapper(MockDirWrapper(org.apache.lucene.store.RAMDirectory@57642847 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bbf5d99)),segFN=segments_3,generation=3}
[junit4:junit4] 1> commit{dir=RateLimitedDirectoryWrapper(MockDirWrapper(org.apache.lucene.store.RAMDirectory@57642847 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bbf5d99)),segFN=segments_4,generation=4}
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.758; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 4
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.759; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@686f2985 main
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.760; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.762; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@686f2985 main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):C1)}
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.762; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.766; org.apache.solr.core.SolrCore; [collection1] webapp=/solr path=/select params={q=id:1234&wt=javabin&version=2} hits=1 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.816; org.apache.solr.core.SolrCore; [collection1] webapp=/solr path=/select params={fl=id&q=*:*&wt=csv} hits=1 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.829; org.apache.solr.core.SolrCore; [collection1] webapp=/solr path=/debug/dump params={stream.url=https://127.0.0.1:50584/solr/collection1/select?q%3D*:*%26fl%3Did%26wt%3Dcsv&wt=xml} status=0 QTime=28
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.833; org.apache.solr.SolrTestCaseJ4; ###Ending testStreamUrl
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.838; org.apache.solr.SolrTestCaseJ4; ###Starting testMakeDeleteAllUrl
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.842; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[1234]} 0 1
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.845; 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-12 08:38:45.847; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=RateLimitedDirectoryWrapper(MockDirWrapper(org.apache.lucene.store.RAMDirectory@57642847 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bbf5d99)),segFN=segments_4,generation=4}
[junit4:junit4] 1> commit{dir=RateLimitedDirectoryWrapper(MockDirWrapper(org.apache.lucene.store.RAMDirectory@57642847 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bbf5d99)),segFN=segments_5,generation=5}
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.848; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 5
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.849; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@31674d7d main
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.849; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.850; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@31674d7d main{StandardDirectoryReader(segments_5:15:nrt _3(5.0):C1)}
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.851; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.854; org.apache.solr.core.SolrCore; [collection1] webapp=/solr path=/select params={q=id:1234&wt=javabin&version=2} hits=1 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.857; org.apache.solr.update.DirectUpdateHandler2; [collection1] REMOVING ALL DOCUMENTS FROM INDEX
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.857; 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-12 08:38:45.858; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=RateLimitedDirectoryWrapper(MockDirWrapper(org.apache.lucene.store.RAMDirectory@57642847 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bbf5d99)),segFN=segments_5,generation=5}
[junit4:junit4] 1> commit{dir=RateLimitedDirectoryWrapper(MockDirWrapper(org.apache.lucene.store.RAMDirectory@57642847 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bbf5d99)),segFN=segments_6,generation=6}
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.858; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 6
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.859; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@249e4264 main
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.859; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.861; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@249e4264 main{StandardDirectoryReader(segments_6:16:nrt)}
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.861; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp=/solr path=/update params={stream.body=<delete><query>*:*</query></delete>&commit=true} {deleteByQuery=*:*,commit=} 0 4
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.865; org.apache.solr.core.SolrCore; [collection1] webapp=/solr path=/select params={q=id:1234&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.866; org.apache.solr.SolrTestCaseJ4; ###Ending testMakeDeleteAllUrl
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.987; org.apache.solr.core.CoreContainer; Shutting down CoreContainer instance=816046378
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.987; org.apache.solr.core.SolrCore; [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@1dbe2c6a
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.997; org.apache.solr.update.DirectUpdateHandler2; closing DirectUpdateHandler2{commits=5,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=4,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.998; org.apache.solr.update.SolrCoreState; Closing SolrCoreState
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.998; org.apache.solr.update.DefaultSolrCoreState; SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 1> INFO - 2013-05-12 08:38:45.998; org.apache.solr.update.DefaultSolrCoreState; closing IndexWriter with IndexWriterCloser
[junit4:junit4] 1> INFO - 2013-05-12 08:38:46.000; org.apache.solr.core.SolrCore; [collection1] Closing main searcher on request.
[junit4:junit4] 1> INFO - 2013-05-12 08:38:46.000; org.apache.solr.core.CachingDirectoryFactory; Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 1> INFO - 2013-05-12 08:38:46.000; org.apache.solr.core.CachingDirectoryFactory; looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/solrtest-TestRemoteStreaming-1368347724660/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/solrtest-TestRemoteStreaming-1368347724660/index;done=false>>]
[junit4:junit4] 1> INFO - 2013-05-12 08:38:46.001; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/solrtest-TestRemoteStreaming-1368347724660/index
[junit4:junit4] 1> INFO - 2013-05-12 08:38:46.001; org.apache.solr.core.CachingDirectoryFactory; looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/solrtest-TestRemoteStreaming-1368347724660 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/solrtest-TestRemoteStreaming-1368347724660;done=false>>]
[junit4:junit4] 1> INFO - 2013-05-12 08:38:46.001; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/solrtest-TestRemoteStreaming-1368347724660
[junit4:junit4] 1> INFO - 2013-05-12 08:38:46.002; org.eclipse.jetty.server.handler.ContextHandler; stopped o.e.j.s.ServletContextHandler{/solr,null}
[junit4:junit4] 1> INFO - 2013-05-12 08:38:46.053; org.apache.solr.SolrTestCaseJ4; ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=FastCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=FAST, chunkSize=31), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=FAST, chunkSize=31)), sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=ar_LY, timezone=America/Phoenix
[junit4:junit4] 2> NOTE: Linux 3.2.0-41-generic amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=8,threads=1,free=198712136,total=520093696
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TermsComponentTest, TestRealTimeGet, TestPHPSerializedResponseWriter, CircularListTest, TestSolrIndexConfig, CoreAdminHandlerTest, SliceStateTest, IndexSchemaTest, BadCopyFieldTest, ZkCLITest, FieldMutatingUpdateProcessorTest, TestFieldResource, TestCoreContainer, TestValueSourceCache, PeerSyncTest, TestSolrCoreProperties, ResponseLogComponentTest, TestBadConfig, TestStressVersions, FastVectorHighlighterTest, TestDocumentBuilder, TestPhraseSuggestions, SuggesterTest, UUIDFieldTest, RAMDirectoryFactoryTest, TestFuzzyAnalyzedSuggestions, QueryEqualityTest, ClusterStateUpdateTest, TestSolrDeletionPolicy2, RecoveryZkTest, TestExtendedDismaxParser, TestLFUCache, TestSolrQueryParser, TestJoin, SolrInfoMBeanTest, QueryResultKeyTest, SimpleFacetsTest, TestSerializedLuceneMatchVersion, QueryElevationComponentTest, TestFieldTypeCollectionResource, TestSchemaResource, PluginInfoTest, ScriptEngineTest, TestDynamicFieldResource, OverseerCollectionProcessorTest, DistributedQueryElevationComponentTest, ZkControllerTest, TestConfig, TestRandomDVFaceting, TestSolrDeletionPolicy1, TestPerFieldSimilarity, MoreLikeThisHandlerTest, TestFunctionQuery, LegacyHTMLStripCharFilterTest, TestFastLRUCache, DirectSolrConnectionTest, QueryParsingTest, TestSearchPerf, DateFieldTest, JsonLoaderTest, SpatialFilterTest, TestPluginEnable, DocValuesTest, TestPropInjectDefaults, StatelessScriptUpdateProcessorFactoryTest, TestManagedSchemaFieldResource, MBeansHandlerTest, PreAnalyzedFieldTest, ChaosMonkeyNothingIsSafeTest, BinaryUpdateRequestHandlerTest, BasicDistributedZkTest, BasicDistributedZk2Test, UnloadDistributedZkTest, SyncSliceTest, OverseerTest, TestReplicationHandler, ZkSolrClientTest, SliceStateUpdateTest, AutoCommitTest, TestFaceting, TestMultiCoreConfBootstrap, HardAutoCommitTest, DistributedTermsComponentTest, SolrCoreTest, BadIndexSchemaTest, ConvertedLegacyTest, TestSort, TestFiltering, ShowFileRequestHandlerTest, SolrIndexSplitterTest, AnalysisAfterCoreReloadTest, SpellCheckCollatorTest, TestFoldingMultitermQuery, SuggesterTSTTest, TestTrie, WordBreakSolrSpellCheckerTest, TestPseudoReturnFields, DirectUpdateHandlerOptimizeTest, TestRemoteStreaming]
[junit4:junit4] Completed on J0 in 201.41s, 4 tests, 1 error <<< FAILURES!
[...truncated 50 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:377: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:357: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1240: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:884: There were test failures: 294 suites, 1225 tests, 1 error, 13 ignored (7 assumptions)
Total time: 39 minutes 50 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0_21 -XX:+UseCompressedOops -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure