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/04/30 20:40:44 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/jdk1.7.0_21) - Build # 5367
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/5367/
Java: 32bit/jdk1.7.0_21 -server -XX:+UseG1GC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Wrong doc count on shard1_0 expected:<312> but was:<311>
Stack Trace:
java.lang.AssertionError: Wrong doc count on shard1_0 expected:<312> but was:<311>
at __randomizedtesting.SeedInfo.seed([1AEE91CBFD77B606:9B081FD38A28D63A]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.apache.solr.cloud.ShardSplitTest.checkDocCountsAndShardStates(ShardSplitTest.java:158)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:134)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9316 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 1> INFO - 2013-04-30 18:25:33.904; org.apache.solr.BaseDistributedSearchTestCase; Setting hostContext system property: /
[junit4:junit4] 1> INFO - 2013-04-30 18:25:33.909; org.apache.solr.SolrTestCaseJ4; ###Starting testDistribSearch
[junit4:junit4] 1> INFO - 2013-04-30 18:25:33.910; org.apache.solr.cloud.ZkTestServer; STARTING ZK TEST SERVER
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 1> INFO - 2013-04-30 18:25:33.910; org.apache.solr.cloud.ZkTestServer$ZKServerMain; Starting server
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.010; org.apache.solr.cloud.ZkTestServer; start zk server on port:33716
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.011; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.190; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@930887 name:ZooKeeperConnection Watcher:127.0.0.1:33716 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.190; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.191; org.apache.solr.common.cloud.SolrZkClient; makePath: /solr
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.196; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.197; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@17b377a name:ZooKeeperConnection Watcher:127.0.0.1:33716/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.198; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.198; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.200; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/shards
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.203; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.205; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/shards
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.207; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.208; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.211; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.212; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.215; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.215; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.218; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.218; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.220; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.221; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.223; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-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-04-30 18:25:34.223; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.226; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.226; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.228; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.229; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.231; org.apache.solr.cloud.AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.231; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.295; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.299; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:43986
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.300; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.300; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.300; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1367346334234
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.301; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1367346334234/solr.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.301; org.apache.solr.core.CoreContainer; New CoreContainer 20323812
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.302; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1367346334234/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.302; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1367346334234/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.368; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.368; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.369; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.369; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.369; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.370; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.370; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.370; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.371; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.371; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.375; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.375; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:33716/solr
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.375; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.376; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.378; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@18fb0d5 name:ZooKeeperConnection Watcher:127.0.0.1:33716 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.378; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.380; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.383; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.384; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1cce943 name:ZooKeeperConnection Watcher:127.0.0.1:33716/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.384; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.386; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.389; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/collection-queue-work
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.391; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.392; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43986_
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.393; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:43986_
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.395; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/election
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.399; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/leader
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.401; org.apache.solr.cloud.Overseer; Overseer (id=89610409339322371-127.0.0.1:43986_-n_0000000000) starting
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.403; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue-work
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.406; org.apache.solr.cloud.OverseerCollectionProcessor; Process current queue of collection creations
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.407; org.apache.solr.common.cloud.SolrZkClient; makePath: /clusterstate.json
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.409; org.apache.solr.common.cloud.SolrZkClient; makePath: /aliases.json
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.410; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.412; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Starting to work on the main queue
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.416; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1367346334234/collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.416; org.apache.solr.cloud.ZkController; Check for collection zkNode:control_collection
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.417; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.417; org.apache.solr.cloud.ZkController; Load collection config from:/collections/control_collection
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.418; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1367346334234/collection1/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.419; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-controljetty-1367346334234/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.419; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-controljetty-1367346334234/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.443; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.472; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.473; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.477; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.785; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.791; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.793; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.805; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.809; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.814; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 18:25:34.815; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 18:25:34.815; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.816; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 18:25:34.816; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 18:25:34.817; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.817; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.817; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1367346334234/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1367346333909/control/data/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.818; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@16a8d4c
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.818; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.819; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1367346333909/control/data
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.819; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1367346333909/control/data/index/
[junit4:junit4] 1> WARN - 2013-04-30 18:25:34.819; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1367346333909/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.820; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1367346333909/control/data/index
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.822; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1b259dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@e9f626),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.822; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.824; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.825; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.826; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.826; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.827; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.827; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.827; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.828; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.828; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.832; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.835; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1ee5eaf main
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.836; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1367346333909/control/data/tlog
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.837; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.837; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.840; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1ee5eaf main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.841; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-30 18:25:34.841; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 18:25:35.916; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:35.917; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:43986_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:43986"}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:35.917; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection control_collection with numShards 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:35.917; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:35.921; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:36.842; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:36.843; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:43986 collection:control_collection shard:shard1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:36.844; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-04-30 18:25:36.850; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:36.852; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:36.852; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-04-30 18:25:36.852; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:43986/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:36.853; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-04-30 18:25:36.853; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:43986/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-04-30 18:25:36.853; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:43986/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:36.853; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.426; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.451; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.460; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:43986/collection1/ and leader is http://127.0.0.1:43986/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.460; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43986
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.460; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.461; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.461; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.464; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.466; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.466; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.467; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.474; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.477; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.479; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1e924f9 name:ZooKeeperConnection Watcher:127.0.0.1:33716/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.479; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.482; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.487; org.apache.solr.cloud.ChaosMonkey; monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.570; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.572; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:58740
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.573; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.574; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.574; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1367346337488
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.574; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1367346337488/solr.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.575; org.apache.solr.core.CoreContainer; New CoreContainer 5231796
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.575; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1367346337488/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.575; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1367346337488/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.620; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.620; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.621; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.621; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.621; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.622; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.622; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.622; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.623; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.623; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.626; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.627; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:33716/solr
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.627; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.628; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.630; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1d77db2 name:ZooKeeperConnection Watcher:127.0.0.1:33716 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.631; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.635; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.638; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.640; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@109ad23 name:ZooKeeperConnection Watcher:127.0.0.1:33716/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.640; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:37.647; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.651; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58740_
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.653; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:58740_
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.656; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.657; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.657; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.657; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.662; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1367346337488/collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.662; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.663; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.663; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.665; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1367346337488/collection1/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.665; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty1-1367346337488/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.666; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty1-1367346337488/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.695; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.724; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.725; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.729; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.958; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.959; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:43986__collection1",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:43986_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:43986"}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.962; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.962; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:38.962; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.054; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.060; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.062; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.077; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.080; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.083; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 18:25:39.084; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 18:25:39.085; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.085; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 18:25:39.086; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 18:25:39.086; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.086; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.087; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1367346337488/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty1/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.087; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@16a8d4c
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.087; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.088; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.088; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty1/index/
[junit4:junit4] 1> WARN - 2013-04-30 18:25:39.088; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.088; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty1/index
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.090; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6bfebd lockFactory=org.apache.lucene.store.NativeFSLockFactory@63650c),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.090; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.091; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.092; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.092; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.093; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.093; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.093; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.093; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.094; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.094; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.096; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.099; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1260e7b main
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.099; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty1/tlog
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.099; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.100; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.104; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1260e7b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.105; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-30 18:25:39.106; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 18:25:40.466; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:40.466; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:58740_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:58740"}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:40.467; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection collection1 with numShards 2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:40.467; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:40.472; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:40.472; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:40.472; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.107; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.108; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:58740 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.114; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.123; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.125; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.126; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.126; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:58740/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.126; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.126; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:58740/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.127; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:58740/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.127; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.977; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.999; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.999; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:41.999; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.034; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:58740/collection1/ and leader is http://127.0.0.1:58740/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.035; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58740
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.035; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.035; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.036; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.038; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.040; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.040; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.041; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.119; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.120; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:34771
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.121; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.122; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.122; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1367346342049
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.122; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1367346342049/solr.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.123; org.apache.solr.core.CoreContainer; New CoreContainer 19263119
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.123; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1367346342049/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.123; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1367346342049/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.164; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.165; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.166; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.166; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.167; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.167; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.168; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.168; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.168; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.169; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.172; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.173; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:33716/solr
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.173; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.174; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.175; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@3701d4 name:ZooKeeperConnection Watcher:127.0.0.1:33716 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.175; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.177; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.181; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.182; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1731f7a name:ZooKeeperConnection Watcher:127.0.0.1:33716/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.182; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:42.186; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.189; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34771_
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.190; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:34771_
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.194; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.195; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.195; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.195; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.195; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.195; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.195; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.203; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1367346342049/collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.203; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.204; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.204; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.206; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1367346342049/collection1/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.206; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty2-1367346342049/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.207; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty2-1367346342049/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.243; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.294; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.296; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.302; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.511; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.512; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:58740__collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:58740_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:58740"}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.515; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.515; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.515; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.515; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.642; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.648; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.650; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.662; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.665; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.667; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 18:25:43.669; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 18:25:43.669; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.669; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 18:25:43.670; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 18:25:43.670; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.671; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.671; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1367346342049/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty2/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.671; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@16a8d4c
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.672; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.672; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.672; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty2/index/
[junit4:junit4] 1> WARN - 2013-04-30 18:25:43.672; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.673; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty2/index
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.674; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1d8f88e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e2b1ae),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.674; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.676; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.676; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.677; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.677; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.678; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.678; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.678; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.678; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.679; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.681; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.683; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1c300c3 main
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.684; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty2/tlog
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.684; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.684; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.688; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1c300c3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.691; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-30 18:25:43.691; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.019; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.020; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:34771_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34771"}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.020; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.020; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.023; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.023; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.023; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.023; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.693; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.693; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:34771 collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.695; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.705; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.709; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.709; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.709; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:34771/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.710; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.710; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:34771/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.710; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:34771/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:45.711; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.529; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.559; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.560; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.560; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.560; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.573; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:34771/collection1/ and leader is http://127.0.0.1:34771/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.573; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34771
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.574; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.574; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.574; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.577; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.579; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.579; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.580; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.656; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.658; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:60064
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.659; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.660; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.661; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1367346346586
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.661; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1367346346586/solr.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.662; org.apache.solr.core.CoreContainer; New CoreContainer 3907263
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.663; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1367346346586/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.664; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1367346346586/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.716; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.717; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.717; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.718; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.718; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.718; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.719; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.719; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.719; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.720; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.723; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.724; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:33716/solr
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.724; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.725; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.726; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@11dccac name:ZooKeeperConnection Watcher:127.0.0.1:33716 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.726; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.728; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.731; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.732; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@55775a name:ZooKeeperConnection Watcher:127.0.0.1:33716/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.733; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:46.736; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.739; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60064_
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.741; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:60064_
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.745; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.746; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.746; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.747; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.747; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.748; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.747; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.749; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.749; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.756; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1367346346586/collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.757; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.758; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.758; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.760; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1367346346586/collection1/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.761; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty3-1367346346586/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.762; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty3-1367346346586/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.807; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.836; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.838; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:47.841; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.067; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.068; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:34771__collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:34771_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34771"}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.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: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.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: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.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: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.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: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.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: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.145; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.167; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.169; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.184; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.187; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.190; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 18:25:48.192; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 18:25:48.192; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.192; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 18:25:48.194; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 18:25:48.194; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.194; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.194; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1367346346586/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty3/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.195; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@16a8d4c
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.195; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.195; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty3
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.196; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty3/index/
[junit4:junit4] 1> WARN - 2013-04-30 18:25:48.196; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.196; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty3/index
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.197; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f915d6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@108f1ac),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.197; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.199; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.199; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.200; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.200; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.201; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.201; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.201; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.201; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.202; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.204; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.206; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@de1565 main
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.206; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty3/tlog
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.207; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.207; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.211; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@de1565 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.213; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-30 18:25:48.214; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 18:25:49.577; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:49.579; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:60064_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:60064"}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:49.579; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:49.580; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:49.584; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:49.584; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:49.584; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:49.584; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:49.584; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.216; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.217; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:60064 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.223; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:60064/collection1/ and leader is http://127.0.0.1:58740/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.223; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60064
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.224; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.224; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.225; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.226; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.226; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.226; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.227; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.228; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.229; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.229; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.230; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.242; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:60064__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.304; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.306; org.eclipse.jetty.server.AbstractConnector; Started SelectChannelConnector@127.0.0.1:40630
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.306; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.307; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.307; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1367346350239
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.307; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1367346350239/solr.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.308; org.apache.solr.core.CoreContainer; New CoreContainer 30033674
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.308; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1367346350239/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.308; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1367346350239/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.350; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.350; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.351; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.351; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.351; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.352; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.352; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.352; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.353; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.353; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.356; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.357; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:33716/solr
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.357; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.358; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.359; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@191bfcc name:ZooKeeperConnection Watcher:127.0.0.1:33716 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.360; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.362; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.365; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.366; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@112a6ee name:ZooKeeperConnection Watcher:127.0.0.1:33716/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.366; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-04-30 18:25:50.369; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.088; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.089; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:60064__collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"recovering",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:60064_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:60064"}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.094; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.095; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.094; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.096; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.094; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.095; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.243; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 127.0.0.1:60064__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.243; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:60064__collection1&state=recovering&nodeName=127.0.0.1:60064_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.373; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40630_
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.375; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:40630_
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.378; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.378; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.379; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.379; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.380; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.379; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.381; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.379; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.380; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.380; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.382; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.382; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.389; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1367346350239/collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.390; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.391; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.391; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.393; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1367346350239/collection1/'
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.394; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty4-1367346350239/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.395; org.apache.solr.core.SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty4-1367346350239/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.433; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.462; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.463; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.467; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.770; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.776; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.778; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.793; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.798; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.801; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 18:25:51.803; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 18:25:51.803; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.804; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 1> WARN - 2013-04-30 18:25:51.805; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4] 1> WARN - 2013-04-30 18:25:51.805; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.805; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.805; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1367346350239/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.806; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@16a8d4c
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.806; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.806; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.807; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4/index/
[junit4:junit4] 1> WARN - 2013-04-30 18:25:51.807; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.807; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4/index
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.808; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73e204 lockFactory=org.apache.lucene.store.NativeFSLockFactory@38c285),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.808; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.810; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.810; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.811; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.811; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.812; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.812; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.812; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.813; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.813; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.815; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.817; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@efc0f0 main
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.817; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4/tlog
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.818; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.818; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.822; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@efc0f0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.825; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-30 18:25:51.825; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.602; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.604; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:40630_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40630"}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.604; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.604; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.610; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.610; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.611; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.610; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.610; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.610; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.828; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.829; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:40630 collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.834; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:40630/collection1/ and leader is http://127.0.0.1:34771/collection1/
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.834; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40630
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.834; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.835; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.836; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.837; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.837; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.837; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.838; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.839; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.839; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.839; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.840; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.848; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.849; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:40630__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.850; org.apache.solr.cloud.AbstractFullDistribZkTestBase; Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.850; org.apache.solr.cloud.AbstractDistribZkTestBase; Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 1> INFO - 2013-04-30 18:25:52.852; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.244; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:58740/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.244; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:60064 START replicas=[http://127.0.0.1:58740/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-04-30 18:25:53.245; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.246; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.246; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.246; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.247; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.247; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:58740/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.248; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.255; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.256; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.258; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6bfebd lockFactory=org.apache.lucene.store.NativeFSLockFactory@63650c),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.259; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.260; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6bfebd lockFactory=org.apache.lucene.store.NativeFSLockFactory@63650c),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6bfebd lockFactory=org.apache.lucene.store.NativeFSLockFactory@63650c),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.261; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.261; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@c52548 realtime
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.262; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.263; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.264; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.264; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.266; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.266; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.267; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.267; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.268; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.269; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.270; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.271; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty3/index.20130430192553270
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.271; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@2cb913 lockFactory=org.apache.lucene.store.NativeFSLockFactory@176b6eb) fullCopy=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.274; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.275; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.276; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.276; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.277; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f915d6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@108f1ac),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f915d6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@108f1ac),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.278; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.278; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.278; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@157e221 main
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.279; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@157e221 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.280; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty3/index.20130430192553270 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty3/index.20130430192553270;done=true>>]
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.280; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty3/index.20130430192553270
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.280; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty3/index.20130430192553270
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.281; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.281; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.281; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.281; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.283; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:53.854; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:54.116; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:54.117; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:40630__collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"recovering",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:40630_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40630"}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:54.121; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:60064__collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:60064_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:60064"}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:54.140; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:54.140; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:54.140; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:54.140; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:54.140; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:54.140; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:54.850; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 127.0.0.1:40630__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:54.850; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:40630__collection1&state=recovering&nodeName=127.0.0.1:40630_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2001
[junit4:junit4] 1> INFO - 2013-04-30 18:25:54.856; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:55.857; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.851; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:34771/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.852; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:40630 START replicas=[http://127.0.0.1:34771/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-04-30 18:25:56.853; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.853; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.853; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.853; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.853; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.853; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:34771/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.854; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.859; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.860; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.863; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.865; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1d8f88e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e2b1ae),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.866; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.867; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1d8f88e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e2b1ae),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1d8f88e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e2b1ae),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.867; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.868; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1e50749 realtime
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.868; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.868; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.869; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.870; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.871; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.872; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.872; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.873; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.873; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.875; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.876; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.877; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4/index.20130430192556876
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.877; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1140823 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5a599b) fullCopy=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.879; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.880; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.881; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.881; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.883; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73e204 lockFactory=org.apache.lucene.store.NativeFSLockFactory@38c285),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73e204 lockFactory=org.apache.lucene.store.NativeFSLockFactory@38c285),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.883; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.883; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.883; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1a49128 main
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.884; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1a49128 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.885; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4/index.20130430192556876 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4/index.20130430192556876;done=true>>]
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.885; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4/index.20130430192556876
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.885; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4/index.20130430192556876
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.885; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.885; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.886; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.886; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 18:25:56.887; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.148; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.149; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:40630__collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:40630_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40630"}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.153; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.153; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.153; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.153; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.153; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.153; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.862; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.863; org.apache.solr.cloud.AbstractDistribZkTestBase; Recoveries finished - collection: collection1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.869; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.871; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1b259dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@e9f626),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.872; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.872; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1b259dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@e9f626),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1b259dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@e9f626),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.872; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.873; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@10e30b7 main
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.873; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.874; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@10e30b7 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.874; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.880; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.881; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6bfebd lockFactory=org.apache.lucene.store.NativeFSLockFactory@63650c),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6bfebd lockFactory=org.apache.lucene.store.NativeFSLockFactory@63650c),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.881; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.881; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1df0dd5 main
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.882; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.882; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1df0dd5 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.883; org.apache.solr.update.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:60064/collection1/, StdNode: http://127.0.0.1:34771/collection1/, StdNode: http://127.0.0.1:40630/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.886; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.887; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1d8f88e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e2b1ae),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1d8f88e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e2b1ae),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.887; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.887; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@a94258 main
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.888; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.888; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@a94258 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.889; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 3
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.891; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.891; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.892; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f915d6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@108f1ac),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f915d6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@108f1ac),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.893; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.893; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73e204 lockFactory=org.apache.lucene.store.NativeFSLockFactory@38c285),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73e204 lockFactory=org.apache.lucene.store.NativeFSLockFactory@38c285),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.894; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.894; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1c88e97 main
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.894; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@ad8885 main
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.895; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.895; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.895; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1c88e97 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.895; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@ad8885 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.896; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.896; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.897; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 17
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.898; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.900; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.902; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.904; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-04-30 18:25:57.906; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.909; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1433766576686891008)} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.916; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1433766576691085312&update.from=http://127.0.0.1:58740/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1433766576691085312)} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.919; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1433766576694231040&update.from=http://127.0.0.1:34771/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1433766576694231040)} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.920; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1433766576694231040)} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.920; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1433766576691085312)} 0 8
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.929; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1433766576705765376)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.938; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1433766576712056832)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.939; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1433766576712056832)]} 0 8
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.943; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1433766576722542592)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.951; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1433766576726736896)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.951; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1433766576726736896)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.956; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1433766576735125504)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.967; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1433766576741416960)]} 0 3
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.968; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[2 (1433766576741416960)]} 0 8
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.969; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2]} 0 11
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.973; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1433766576753999872)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.983; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1433766576760291328)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.984; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[3 (1433766576760291328)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.984; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3]} 0 8
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.989; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1433766576769728512)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.996; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1433766576774971392)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:25:59.997; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1433766576774971392)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.002; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1433766576783360000)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.009; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1433766576787554304)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.009; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1433766576787554304)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.013; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1433766576795942912)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.024; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1433766576802234368)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.025; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[6 (1433766576802234368)]} 0 7
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.026; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6]} 0 10
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.030; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1433766576813768704)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.037; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1433766576817963008)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.038; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1433766576817963008)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.043; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1433766576826351616)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.053; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1433766576833691648)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.053; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1433766576833691648)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.054; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8]} 0 8
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.058; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1433766576843128832)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.066; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1433766576848371712)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.067; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1433766576848371712)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.071; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1433766576856760320)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.079; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1433766576860954624)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.080; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1433766576860954624)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.091; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1433766576877731840)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.100; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1433766576882974720)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.100; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1433766576882974720)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.105; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1433766576891363328)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.139; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1433766576924917760)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.139; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[12 (1433766576924917760)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.140; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12]} 0 8
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.144; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1433766576933306368)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.155; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1433766576940646400)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.156; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[13 (1433766576940646400)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.157; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13]} 0 10
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.162; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1433766576952180736)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.169; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1433766576956375040)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.170; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1433766576956375040)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.174; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1433766576964763648)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.183; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1433766576971055104)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.184; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[15 (1433766576971055104)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.185; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15]} 0 9
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.188; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1433766576979443712)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.198; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1433766576985735168)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.199; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[16 (1433766576985735168)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.199; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16]} 0 8
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.204; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1433766576995172352)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.212; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1433766577001463808)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.213; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[17 (1433766577001463808)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.213; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17]} 0 7
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.217; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1433766577009852416)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.225; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1433766577014046720)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.225; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1433766577014046720)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.229; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1433766577022435328)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.236; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1433766577026629632)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.237; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1433766577026629632)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.240; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1433766577033969664)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.248; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1433766577038163968)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.248; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1433766577038163968)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.253; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1433766577046552576)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.260; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1433766577050746880)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.261; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1433766577050746880)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.265; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1433766577060184064)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.275; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1433766577066475520)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.276; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[22 (1433766577066475520)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.277; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22]} 0 9
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.282; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1433766577078009856)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.292; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1433766577085349888)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.293; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[23 (1433766577085349888)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.294; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23]} 0 9
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.298; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1433766577094787072)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.307; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1433766577100029952)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.308; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[24 (1433766577100029952)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.309; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24]} 0 9
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.313; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1433766577110515712)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.320; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1433766577114710016)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.321; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1433766577114710016)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.324; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1433766577122050048)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.334; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1433766577128341504)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.335; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[26 (1433766577128341504)]} 0 7
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.335; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26]} 0 8
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.340; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1433766577137778688)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.350; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1433766577145118720)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.351; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[27 (1433766577145118720)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.352; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27]} 0 9
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.356; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1433766577155604480)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.363; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1433766577158750208)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.364; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1433766577158750208)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.368; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1433766577168187392)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.378; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1433766577174478848)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.379; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[29 (1433766577174478848)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.380; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29]} 0 9
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.385; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1433766577184964608)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.396; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1433766577192304640)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.397; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[30 (1433766577192304640)]} 0 7
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.397; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30]} 0 9
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.402; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1433766577203838976)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.410; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1433766577208033280)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.411; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1433766577208033280)]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.416; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1433766577218519040)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.426; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1433766577225859072)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.426; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[32 (1433766577225859072)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.427; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32]} 0 8
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.430; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1433766577233199104)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.438; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34771/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1433766577239490560)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.439; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[33 (1433766577239490560)]} 0 4
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.439; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33]} 0 6
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.443; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1433766577246830592)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.449; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1433766577249976320)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.450; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1433766577249976320)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.453; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1433766577257316352)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.460; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1433766577261510656)]} 0 2
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.460; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1433766577261510656)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.463; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1433766577268850688)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.469; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58740/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1433766577270947840)]} 0 1
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.470; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1433766577270947840)]} 0 5
[junit4:junit4] 1> INFO - 2013-04-30 18:26:00.474; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/up
[...truncated too long message...]
"operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:60064__collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:60064_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:60064"}
[junit4:junit4] 1> INFO - 2013-04-30 18:28:12.454; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-04-30 18:28:12.454; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-04-30 18:28:12.494; org.apache.solr.cloud.ChaosMonkey; monkey: stop shard! 40630
[junit4:junit4] 1> INFO - 2013-04-30 18:28:12.495; org.apache.solr.core.CoreContainer; Shutting down CoreContainer instance=30033674
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.497; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.498; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.501; org.apache.solr.core.SolrCore; [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@bf6a4e
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.512; org.apache.solr.update.DirectUpdateHandler2; closing DirectUpdateHandler2{commits=3,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=597,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.513; org.apache.solr.update.SolrCoreState; Closing SolrCoreState
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.514; org.apache.solr.update.DefaultSolrCoreState; SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.515; org.apache.solr.update.DefaultSolrCoreState; closing IndexWriter with IndexWriterCloser
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.517; org.apache.solr.core.SolrCore; [collection1] Closing main searcher on request.
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.518; org.apache.solr.core.CachingDirectoryFactory; Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.519; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4/index;done=false>>]
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.519; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4/index
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.520; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4;done=false>>]
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.521; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1367346333909/jetty4
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.522; org.apache.solr.cloud.Overseer$ClusterStateUpdater; According to ZK I (id=89610409339322380-127.0.0.1:40630_-n_0000000004) am no longer a leader.
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.524; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.526; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (0)
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.546; org.eclipse.jetty.server.handler.ContextHandler; stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.605; org.apache.solr.SolrTestCaseJ4; ###Ending testDistribSearch
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.607; org.apache.solr.cloud.ZkTestServer; connecting to 127.0.0.1:33716 33716
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.709; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@de03c4 name:ZooKeeperConnection Watcher:127.0.0.1:33716/solr got event WatchedEvent state:Disconnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.709; org.apache.solr.common.cloud.ConnectionManager; Client->ZooKeeper status change trigger but we are already closed
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.713; org.apache.solr.cloud.ChaosMonkey; monkey: stop shard! 43986
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.713; org.apache.solr.SolrTestCaseJ4; ###Ending testDistribSearch
[junit4:junit4] 1> INFO - 2013-04-30 18:28:13.714; org.apache.solr.cloud.ZkTestServer; connecting to 127.0.0.1:33716 33716
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-ShardSplitTest-1367346333909
[junit4:junit4] 2> !!!! WARNING: best effort to remove /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-1367346333909 FAILED !!!!!
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=1AEE91CBFD77B606 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=fr_FR -Dtests.timezone=Africa/Ndjamena -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 160s J1 | ShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: Wrong doc count on shard1_0 expected:<312> but was:<311>
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([1AEE91CBFD77B606:9B081FD38A28D63A]:0)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.checkDocCountsAndShardStates(ShardSplitTest.java:158)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:134)
[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-04-30 18:28:13.750; org.apache.solr.SolrTestCaseJ4; ###deleteCore
[junit4:junit4] 2> 159850 T869 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 1> WARN - 2013-04-30 18:28:14.824; org.apache.solr.common.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-04-30 18:28:14.824; 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-04-30 18:28:14.825; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[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=crazy): {}, locale=fr_FR, timezone=Africa/Ndjamena
[junit4:junit4] 2> NOTE: Linux 3.2.0-40-generic i386/Oracle Corporation 1.7.0_21 (32-bit)/cpus=8,threads=3,free=308369824,total=531628032
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestCollationField, TestCSVLoader, ChaosMonkeyShardSplitTest, TestCSVResponseWriter, TestNumberUtils, TestQueryTypes, ClusterStateTest, TestCloudManagedSchema, RequiredFieldsTest, TestUpdate, TestReload, BadCopyFieldTest, TestStressLucene, SolrCoreCheckLockOnStartupTest, ZkSolrClientTest, TestLuceneMatchVersion, DateMathParserTest, TestSolrJ, TestCoreDiscovery, NoCacheHeaderTest, TestStressReorder, StandardRequestHandlerTest, TermVectorComponentDistributedTest, DOMUtilTest, MultiTermTest, ShardSplitTest]
[junit4:junit4] Completed on J1 in 161.13s, 1 test, 1 failure <<< FAILURES!
[...truncated 645 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:384: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:364: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1243: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:887: There were test failures: 294 suites, 1222 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 39 minutes 28 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_21 -server -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure