lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Policeman Jenkins Server <jenk...@thetaphi.de>
Subject [JENKINS] Lucene-Solr-trunk-MacOSX (64bit/jdk1.7.0) - Build # 573 - Failure!
Date Tue, 18 Jun 2013 14:49:37 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-MacOSX/573/
Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseParallelGC

2 tests failed.
REGRESSION:  org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.testDistribSearch

Error Message:
shard3 is not consistent.  Got 36 from http://127.0.0.1:50578/collection1lastClient and got 34 from http://127.0.0.1:50612/collection1

Stack Trace:
java.lang.AssertionError: shard3 is not consistent.  Got 36 from http://127.0.0.1:50578/collection1lastClient and got 34 from http://127.0.0.1:50612/collection1
	at __randomizedtesting.SeedInfo.seed([DD25AAB11FD4D6C2:5CC324A9688BB6FE]:0)
	at org.junit.Assert.fail(Assert.java:93)
	at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
	at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
	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)


REGRESSION:  org.apache.solr.cloud.ShardSplitTest.testDistribSearch

Error Message:
Server at http://127.0.0.1:50193/lpjh/um returned non ok status:500, message:Server Error

Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:50193/lpjh/um returned non ok status:500, message:Server Error
	at __randomizedtesting.SeedInfo.seed([DD25AAB11FD4D6C2:5CC324A9688BB6FE]:0)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
	at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
	at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:150)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
	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 9489 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4]   2> 1582225 T3686 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /lpjh/um
[junit4:junit4]   2> 1582234 T3686 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./solrtest-ShardSplitTest-1371564945960
[junit4:junit4]   2> 1582237 T3686 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 1582238 T3687 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 1582339 T3686 oasc.ZkTestServer.run start zk server on port:50186
[junit4:junit4]   2> 1582347 T3686 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1582351 T3693 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@63a40854 name:ZooKeeperConnection Watcher:127.0.0.1:50186 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1582352 T3686 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1582353 T3686 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 1582372 T3686 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1582387 T3695 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3c53f765 name:ZooKeeperConnection Watcher:127.0.0.1:50186/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1582388 T3686 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1582389 T3686 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 1582400 T3686 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 1582409 T3686 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 1582421 T3686 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 1582432 T3686 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 1582433 T3686 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 1582454 T3686 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 1582456 T3686 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 1582469 T3686 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 1582471 T3686 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 1582482 T3686 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 1582485 T3686 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 1582497 T3686 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 1582499 T3686 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 1582509 T3686 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 1582511 T3686 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 1582532 T3686 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 1582534 T3686 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 1582545 T3686 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 1582547 T3686 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 1582559 T3686 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 1582560 T3686 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 1583385 T3686 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1583413 T3686 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50189
[junit4:junit4]   2> 1583415 T3686 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1583416 T3686 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1583417 T3686 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371564946299
[junit4:junit4]   2> 1583418 T3686 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371564946299/solr.xml
[junit4:junit4]   2> 1583419 T3686 oasc.CoreContainer.<init> New CoreContainer 1799868854
[junit4:junit4]   2> 1583420 T3686 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371564946299/'
[junit4:junit4]   2> 1583422 T3686 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371564946299/'
[junit4:junit4]   2> 1583744 T3686 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 1583745 T3686 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1583746 T3686 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 1583748 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1583748 T3686 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1583749 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1583749 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1583750 T3686 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1583750 T3686 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1583751 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 1583777 T3686 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1583778 T3686 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50186/solr
[junit4:junit4]   2> 1583778 T3686 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1583783 T3686 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1583797 T3706 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3e264181 name:ZooKeeperConnection Watcher:127.0.0.1:50186 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1583799 T3686 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1583807 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1583844 T3686 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1583853 T3708 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@40613bf8 name:ZooKeeperConnection Watcher:127.0.0.1:50186/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1583854 T3686 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1583862 T3686 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 1583885 T3686 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 1583898 T3686 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 1583906 T3686 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50189_lpjh%2Fum
[junit4:junit4]   2> 1583911 T3686 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50189_lpjh%2Fum
[junit4:junit4]   2> 1583928 T3686 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 1583958 T3686 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 1583975 T3686 oasc.Overseer.start Overseer (id=89886880299220995-127.0.0.1:50189_lpjh%2Fum-n_0000000000) starting
[junit4:junit4]   2> 1583993 T3686 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 1584010 T3710 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 1584016 T3686 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 1584032 T3686 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 1584042 T3686 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1584059 T3709 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 1584073 T3711 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1584073 T3711 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1585580 T3709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1585582 T3709 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50189_lpjh%2Fum",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50189/lpjh/um"}
[junit4:junit4]   2> 1585582 T3709 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 1585582 T3709 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 1585595 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 1586083 T3711 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371564946299/collection1
[junit4:junit4]   2> 1586088 T3711 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 1586091 T3711 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 1586091 T3711 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 1586097 T3711 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371564946299/collection1/'
[junit4:junit4]   2> 1586099 T3711 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1371564946299/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 1586100 T3711 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1371564946299/collection1/lib/README' to classloader
[junit4:junit4]   2> 1586221 T3711 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1586398 T3711 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1586403 T3711 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1586414 T3711 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 1587779 T3711 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1587786 T3711 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1587789 T3711 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1587802 T3711 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1587909 T3711 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1587910 T3711 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371564946299/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371564945959/control/data/
[junit4:junit4]   2> 1587911 T3711 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4e17aa0d
[junit4:junit4]   2> 1587912 T3711 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1587913 T3711 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371564945959/control/data
[junit4:junit4]   2> 1587914 T3711 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371564945959/control/data/index/
[junit4:junit4]   2> 1587914 T3711 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371564945959/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1587915 T3711 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371564945959/control/data/index
[junit4:junit4]   2> 1587924 T3711 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@bc0c015 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f555b4e),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1587925 T3711 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1587932 T3711 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1587933 T3711 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1587934 T3711 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1587935 T3711 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1587937 T3711 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1587937 T3711 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1587938 T3711 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1587939 T3711 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1587940 T3711 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1587974 T3711 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1587987 T3711 oass.SolrIndexSearcher.<init> Opening Searcher@6742076 main
[junit4:junit4]   2> 1587988 T3711 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371564945959/control/data/tlog
[junit4:junit4]   2> 1587990 T3711 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1587991 T3711 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1587996 T3712 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6742076 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1587998 T3711 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 1587999 T3711 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50189/lpjh/um collection:control_collection shard:shard1
[junit4:junit4]   2> 1588002 T3711 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 1588027 T3711 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 1588036 T3711 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 1588037 T3711 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 1588037 T3711 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50189/lpjh/um/collection1/
[junit4:junit4]   2> 1588038 T3711 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 1588038 T3711 oasc.SyncStrategy.syncToMe http://127.0.0.1:50189/lpjh/um/collection1/ has no replicas
[junit4:junit4]   2> 1588039 T3711 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50189/lpjh/um/collection1/
[junit4:junit4]   2> 1588039 T3711 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 1588625 T3709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1588666 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 1588701 T3711 oasc.ZkController.register We are http://127.0.0.1:50189/lpjh/um/collection1/ and leader is http://127.0.0.1:50189/lpjh/um/collection1/
[junit4:junit4]   2> 1588701 T3711 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50189/lpjh/um
[junit4:junit4]   2> 1588702 T3711 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 1588702 T3711 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 1588702 T3711 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1588707 T3711 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1588711 T3686 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 1588712 T3686 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1588713 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1588746 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 1588758 T3686 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1588769 T3715 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@144ab841 name:ZooKeeperConnection Watcher:127.0.0.1:50186/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1588770 T3686 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1588775 T3686 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1588789 T3686 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 1589704 T3686 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1589718 T3686 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50193
[junit4:junit4]   2> 1589720 T3686 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1589722 T3686 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1589729 T3686 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371564952513
[junit4:junit4]   2> 1589737 T3686 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371564952513/solr.xml
[junit4:junit4]   2> 1589739 T3686 oasc.CoreContainer.<init> New CoreContainer 955678596
[junit4:junit4]   2> 1589740 T3686 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371564952513/'
[junit4:junit4]   2> 1589741 T3686 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371564952513/'
[junit4:junit4]   2> 1589998 T3686 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 1590000 T3686 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1590001 T3686 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 1590002 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1590003 T3686 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1590004 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1590004 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1590005 T3686 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1590006 T3686 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1590008 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 1590053 T3686 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1590054 T3686 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50186/solr
[junit4:junit4]   2> 1590054 T3686 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1590058 T3686 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1590066 T3726 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7392d781 name:ZooKeeperConnection Watcher:127.0.0.1:50186 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1590067 T3686 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1590079 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1590127 T3686 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1590137 T3728 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3a64666 name:ZooKeeperConnection Watcher:127.0.0.1:50186/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1590137 T3686 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1590163 T3686 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1590184 T3709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1590187 T3709 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:50189_lpjh%2Fum_collection1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50189_lpjh%2Fum",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50189/lpjh/um"}
[junit4:junit4]   2> 1590204 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 1590211 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 1590213 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 1591182 T3686 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50193_lpjh%2Fum
[junit4:junit4]   2> 1591187 T3686 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50193_lpjh%2Fum
[junit4:junit4]   2> 1591196 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 1591202 T3708 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 1591205 T3715 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 1591206 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 1591216 T3728 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 1591216 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 1591241 T3729 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1591241 T3729 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1591732 T3709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1591734 T3709 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50193_lpjh%2Fum",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50193/lpjh/um"}
[junit4:junit4]   2> 1591734 T3709 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 1591736 T3709 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 1591749 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 1591754 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 1591757 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 1592246 T3729 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371564952513/collection1
[junit4:junit4]   2> 1592247 T3729 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 1592249 T3729 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 1592250 T3729 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 1592262 T3729 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371564952513/collection1/'
[junit4:junit4]   2> 1592264 T3729 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1371564952513/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 1592264 T3729 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1371564952513/collection1/lib/README' to classloader
[junit4:junit4]   2> 1592392 T3729 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1592525 T3729 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1592530 T3729 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1592540 T3729 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 1593620 T3729 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1593630 T3729 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1593637 T3729 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1593648 T3729 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1593753 T3729 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1593754 T3729 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371564952513/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty1/
[junit4:junit4]   2> 1593754 T3729 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4e17aa0d
[junit4:junit4]   2> 1593755 T3729 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1593756 T3729 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty1
[junit4:junit4]   2> 1593757 T3729 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty1/index/
[junit4:junit4]   2> 1593757 T3729 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1593759 T3729 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty1/index
[junit4:junit4]   2> 1593766 T3729 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@50544a26 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3720dece),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1593767 T3729 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1593775 T3729 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1593776 T3729 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1593777 T3729 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1593779 T3729 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1593782 T3729 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1593785 T3729 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1593790 T3729 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1593791 T3729 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1593795 T3729 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1593815 T3729 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1593829 T3729 oass.SolrIndexSearcher.<init> Opening Searcher@3b3fbaa1 main
[junit4:junit4]   2> 1593830 T3729 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty1/tlog
[junit4:junit4]   2> 1593832 T3729 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1593833 T3729 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1593841 T3730 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3b3fbaa1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1593845 T3729 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 1593845 T3729 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50193/lpjh/um collection:collection1 shard:shard1
[junit4:junit4]   2> 1593847 T3729 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 1593884 T3729 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 1593895 T3729 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 1593896 T3729 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 1593896 T3729 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50193/lpjh/um/collection1/
[junit4:junit4]   2> 1593897 T3729 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 1593897 T3729 oasc.SyncStrategy.syncToMe http://127.0.0.1:50193/lpjh/um/collection1/ has no replicas
[junit4:junit4]   2> 1593898 T3729 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50193/lpjh/um/collection1/
[junit4:junit4]   2> 1593898 T3729 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 1594796 T3709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1594817 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 1594820 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 1594821 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 1594870 T3729 oasc.ZkController.register We are http://127.0.0.1:50193/lpjh/um/collection1/ and leader is http://127.0.0.1:50193/lpjh/um/collection1/
[junit4:junit4]   2> 1594871 T3729 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50193/lpjh/um
[junit4:junit4]   2> 1594871 T3729 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 1594872 T3729 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 1594872 T3729 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1594880 T3729 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1594885 T3686 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 1594886 T3686 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1594887 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1596197 T3686 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1596211 T3686 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50196
[junit4:junit4]   2> 1596213 T3686 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1596215 T3686 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1596216 T3686 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371564958657
[junit4:junit4]   2> 1596217 T3686 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371564958657/solr.xml
[junit4:junit4]   2> 1596218 T3686 oasc.CoreContainer.<init> New CoreContainer 1338813427
[junit4:junit4]   2> 1596220 T3686 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371564958657/'
[junit4:junit4]   2> 1596232 T3686 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371564958657/'
[junit4:junit4]   2> 1596420 T3709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1596423 T3709 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:50193_lpjh%2Fum_collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50193_lpjh%2Fum",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50193/lpjh/um"}
[junit4:junit4]   2> 1596503 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 1596515 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 1596515 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 1596611 T3686 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 1596617 T3686 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1596619 T3686 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 1596620 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1596621 T3686 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1596622 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1596623 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1596624 T3686 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1596625 T3686 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1596626 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 1596670 T3686 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1596672 T3686 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50186/solr
[junit4:junit4]   2> 1596673 T3686 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1596677 T3686 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1596686 T3742 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@40a5d609 name:ZooKeeperConnection Watcher:127.0.0.1:50186 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1596688 T3686 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1596701 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1596746 T3686 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1596755 T3744 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6288d09c name:ZooKeeperConnection Watcher:127.0.0.1:50186/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1596756 T3686 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1596778 T3686 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1597795 T3686 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50196_lpjh%2Fum
[junit4:junit4]   2> 1597802 T3686 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50196_lpjh%2Fum
[junit4:junit4]   2> 1597810 T3728 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 1597811 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1597816 T3715 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 1597817 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1597818 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 1597824 T3744 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 1597845 T3745 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1597847 T3745 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1597847 T3708 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 1598036 T3709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1598038 T3709 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50196_lpjh%2Fum",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50196/lpjh/um"}
[junit4:junit4]   2> 1598039 T3709 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 1598039 T3709 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4]   2> 1598078 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1598082 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1598087 T3744 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1598094 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1598851 T3745 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371564958657/collection1
[junit4:junit4]   2> 1598852 T3745 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 1598864 T3745 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 1598865 T3745 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 1598869 T3745 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371564958657/collection1/'
[junit4:junit4]   2> 1598891 T3745 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1371564958657/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 1598892 T3745 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1371564958657/collection1/lib/README' to classloader
[junit4:junit4]   2> 1599014 T3745 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1599166 T3745 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1599201 T3745 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1599229 T3745 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 1600757 T3745 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1600771 T3745 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1600774 T3745 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1600791 T3745 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1600880 T3745 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1600881 T3745 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371564958657/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty2/
[junit4:junit4]   2> 1600882 T3745 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4e17aa0d
[junit4:junit4]   2> 1600883 T3745 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1600884 T3745 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty2
[junit4:junit4]   2> 1600886 T3745 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty2/index/
[junit4:junit4]   2> 1600887 T3745 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1600889 T3745 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty2/index
[junit4:junit4]   2> 1600898 T3745 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a5c909d lockFactory=org.apache.lucene.store.NativeFSLockFactory@15f43cb1),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1600904 T3745 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1600912 T3745 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1600913 T3745 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1600914 T3745 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1600915 T3745 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1600915 T3745 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1600916 T3745 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1600916 T3745 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1600917 T3745 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1600918 T3745 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1600941 T3745 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1600952 T3745 oass.SolrIndexSearcher.<init> Opening Searcher@2e98e1ad main
[junit4:junit4]   2> 1600953 T3745 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty2/tlog
[junit4:junit4]   2> 1600955 T3745 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1600956 T3745 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1600963 T3745 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 1600964 T3745 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50196/lpjh/um collection:collection1 shard:shard2
[junit4:junit4]   2> 1600968 T3746 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2e98e1ad main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1600969 T3745 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 1601012 T3745 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 1601024 T3745 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 1601024 T3745 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 1601025 T3745 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50196/lpjh/um/collection1/
[junit4:junit4]   2> 1601025 T3745 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 1601025 T3745 oasc.SyncStrategy.syncToMe http://127.0.0.1:50196/lpjh/um/collection1/ has no replicas
[junit4:junit4]   2> 1601026 T3745 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50196/lpjh/um/collection1/
[junit4:junit4]   2> 1601026 T3745 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 1601159 T3709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1601210 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1601211 T3744 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1601218 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1601224 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1601250 T3745 oasc.ZkController.register We are http://127.0.0.1:50196/lpjh/um/collection1/ and leader is http://127.0.0.1:50196/lpjh/um/collection1/
[junit4:junit4]   2> 1601253 T3745 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50196/lpjh/um
[junit4:junit4]   2> 1601254 T3745 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 1601254 T3745 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 1601254 T3745 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1601259 T3745 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1601268 T3686 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 1601269 T3686 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1601270 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1602109 T3686 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1602125 T3686 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50199
[junit4:junit4]   2> 1602129 T3686 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1602130 T3686 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1602131 T3686 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371564965034
[junit4:junit4]   2> 1602132 T3686 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371564965034/solr.xml
[junit4:junit4]   2> 1602133 T3686 oasc.CoreContainer.<init> New CoreContainer 678572177
[junit4:junit4]   2> 1602134 T3686 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371564965034/'
[junit4:junit4]   2> 1602135 T3686 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371564965034/'
[junit4:junit4]   2> 1602374 T3686 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 1602374 T3686 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1602375 T3686 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 1602375 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1602376 T3686 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1602380 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1602381 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1602381 T3686 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1602382 T3686 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1602382 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 1602409 T3686 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1602410 T3686 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50186/solr
[junit4:junit4]   2> 1602411 T3686 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1602418 T3686 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1602571 T3758 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@64d39852 name:ZooKeeperConnection Watcher:127.0.0.1:50186 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1602575 T3686 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1602581 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1602613 T3686 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1602621 T3760 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@142efae3 name:ZooKeeperConnection Watcher:127.0.0.1:50186/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1602622 T3686 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1602645 T3686 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1602763 T3709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1602766 T3709 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:50196_lpjh%2Fum_collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50196_lpjh%2Fum",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50196/lpjh/um"}
[junit4:junit4]   2> 1602786 T3744 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1602786 T3760 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1602787 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1602788 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1602789 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1603667 T3686 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50199_lpjh%2Fum
[junit4:junit4]   2> 1603671 T3686 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50199_lpjh%2Fum
[junit4:junit4]   2> 1603692 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 1603702 T3760 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1603703 T3760 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1603706 T3744 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1603707 T3744 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1603707 T3728 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1603708 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1603715 T3715 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1603717 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1603726 T3708 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1603747 T3761 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1603750 T3761 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1604318 T3709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1604320 T3709 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50199_lpjh%2Fum",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50199/lpjh/um"}
[junit4:junit4]   2> 1604320 T3709 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 1604321 T3709 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 1604339 T3760 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1604341 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1604341 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1604340 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1604343 T3744 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1604760 T3761 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371564965034/collection1
[junit4:junit4]   2> 1604760 T3761 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 1604762 T3761 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 1604763 T3761 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 1604768 T3761 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371564965034/collection1/'
[junit4:junit4]   2> 1604775 T3761 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1371564965034/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 1604782 T3761 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1371564965034/collection1/lib/README' to classloader
[junit4:junit4]   2> 1604902 T3761 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1605021 T3761 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1605025 T3761 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1605032 T3761 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 1606474 T3761 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1606479 T3761 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1606481 T3761 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1606496 T3761 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1606609 T3761 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1606610 T3761 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371564965034/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty3/
[junit4:junit4]   2> 1606611 T3761 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4e17aa0d
[junit4:junit4]   2> 1606612 T3761 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1606617 T3761 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty3
[junit4:junit4]   2> 1606618 T3761 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty3/index/
[junit4:junit4]   2> 1606619 T3761 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1606621 T3761 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty3/index
[junit4:junit4]   2> 1606629 T3761 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@65239252 lockFactory=org.apache.lucene.store.NativeFSLockFactory@467feeae),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1606629 T3761 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1606636 T3761 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1606637 T3761 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1606639 T3761 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1606640 T3761 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1606641 T3761 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1606641 T3761 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1606642 T3761 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1606643 T3761 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1606643 T3761 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1606677 T3761 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1606694 T3761 oass.SolrIndexSearcher.<init> Opening Searcher@14a40b74 main
[junit4:junit4]   2> 1606695 T3761 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty3/tlog
[junit4:junit4]   2> 1606698 T3761 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1606698 T3761 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1606716 T3762 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@14a40b74 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1606722 T3761 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 1606722 T3761 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50199/lpjh/um collection:collection1 shard:shard1
[junit4:junit4]   2> 1606738 T3761 oasc.ZkController.register We are http://127.0.0.1:50199/lpjh/um/collection1/ and leader is http://127.0.0.1:50193/lpjh/um/collection1/
[junit4:junit4]   2> 1606738 T3761 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50199/lpjh/um
[junit4:junit4]   2> 1606739 T3761 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 1606739 T3761 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> 1606741 T3761 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> ASYNC  NEW_CORE C837 name=collection1 org.apache.solr.core.SolrCore@3f9c5009 url=http://127.0.0.1:50199/lpjh/um/collection1 node=127.0.0.1:50199_lpjh%2Fum C837_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:50199_lpjh%2Fum, base_url=http://127.0.0.1:50199/lpjh/um}
[junit4:junit4]   2> 1606744 T3763 C837 P50199 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 1606758 T3686 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 1606760 T3686 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1606761 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1606761 T3763 C837 P50199 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 1606766 T3763 C837 P50199 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 1606767 T3763 C837 P50199 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1606813 T3763 C837 P50199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1606875 T3719 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:50199_lpjh%2Fum_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 1607423 T3709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1607441 T3709 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:50199_lpjh%2Fum_collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50199_lpjh%2Fum",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50199/lpjh/um"}
[junit4:junit4]   2> 1607476 T3760 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1607476 T3744 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1607477 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1607477 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1607478 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1607883 T3719 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:50199_lpjh%2Fum_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4]   2> 1607889 T3719 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:50199_lpjh%252Fum_collection1&state=recovering&nodeName=127.0.0.1:50199_lpjh%252Fum&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1014 
[junit4:junit4]   2> 1608093 T3686 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1608117 T3686 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50203
[junit4:junit4]   2> 1608119 T3686 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1608120 T3686 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1608121 T3686 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371564970563
[junit4:junit4]   2> 1608121 T3686 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371564970563/solr.xml
[junit4:junit4]   2> 1608122 T3686 oasc.CoreContainer.<init> New CoreContainer 384092695
[junit4:junit4]   2> 1608122 T3686 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371564970563/'
[junit4:junit4]   2> 1608123 T3686 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371564970563/'
[junit4:junit4]   2> 1608358 T3686 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 1608359 T3686 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1608359 T3686 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 1608360 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1608360 T3686 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1608361 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1608362 T3686 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1608362 T3686 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1608362 T3686 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1608363 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 1608388 T3686 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1608389 T3686 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50186/solr
[junit4:junit4]   2> 1608390 T3686 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1608393 T3686 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1608404 T3775 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@64a78717 name:ZooKeeperConnection Watcher:127.0.0.1:50186 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1608408 T3686 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1608413 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1608437 T3686 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1608444 T3777 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9a4c5c9 name:ZooKeeperConnection Watcher:127.0.0.1:50186/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1608444 T3686 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1608458 T3686 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1609482 T3686 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50203_lpjh%2Fum
[junit4:junit4]   2> 1609485 T3686 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50203_lpjh%2Fum
[junit4:junit4]   2> 1609492 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 1609493 T3715 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1609493 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1609494 T3777 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1609494 T3728 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1609495 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1609495 T3760 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1609496 T3760 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1609497 T3744 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1609497 T3744 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1609502 T3708 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1609555 T3778 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1609555 T3778 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2>  C837_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:50199_lpjh%2Fum, base_url=http://127.0.0.1:50199/lpjh/um}
[junit4:junit4]   2> 1609894 T3763 C837 P50199 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50193/lpjh/um/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 1609895 T3763 C837 P50199 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50199/lpjh/um START replicas=[http://127.0.0.1:50193/lpjh/um/collection1/] nUpdates=100
[junit4:junit4]   2> 1609896 T3763 C837 P50199 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 1609898 T3763 C837 P50199 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 1609898 T3763 C837 P50199 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 1609898 T3763 C837 P50199 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 1609899 T3763 C837 P50199 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 1609900 T3763 C837 P50199 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50193/lpjh/um/collection1/. core=collection1
[junit4:junit4]   2> 1609900 T3763 C837 P50199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C838 name=collection1 org.apache.solr.core.SolrCore@191f1340 url=http://127.0.0.1:50193/lpjh/um/collection1 node=127.0.0.1:50193_lpjh%2Fum C838_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50193_lpjh%2Fum, base_url=http://127.0.0.1:50193/lpjh/um, leader=true}
[junit4:junit4]   2> 1609935 T3721 C838 P50193 oasc.SolrCore.execute [collection1] webapp=/lpjh/um path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=3 
[junit4:junit4]   2> 1609937 T3719 C838 P50193 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 1609941 T3719 C838 P50193 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@50544a26 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3720dece),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1609942 T3719 C838 P50193 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1609943 T3719 C838 P50193 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@50544a26 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3720dece),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@50544a26 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3720dece),segFN=segments_2,generation=2}
[junit4:junit4]   2> 1609943 T3719 C838 P50193 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 1609950 T3719 C838 P50193 oass.SolrIndexSearcher.<init> Opening Searcher@8356427 realtime
[junit4:junit4]   2> 1609952 T3719 C838 P50193 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1609953 T3719 C838 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 16
[junit4:junit4]   2> 1609954 T3763 C837 P50199 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 1609955 T3763 C837 P50199 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 1609965 T3724 C838 P50193 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 1609965 T3724 C838 P50193 oasc.SolrCore.execute [collection1] webapp=/lpjh/um path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2 
[junit4:junit4]   2> 1609967 T3763 C837 P50199 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 1609967 T3763 C837 P50199 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 1609967 T3763 C837 P50199 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 1609970 T3720 C838 P50193 oasc.SolrCore.execute [collection1] webapp=/lpjh/um path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0 
[junit4:junit4]   2> 1609972 T3763 C837 P50199 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 1609974 T3763 C837 P50199 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty3/index.20130618091613696
[junit4:junit4]   2> 1609974 T3763 C837 P50199 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f47e386 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d3ab23f) fullCopy=false
[junit4:junit4]   2> 1609978 T3721 C838 P50193 oasc.SolrCore.execute [collection1] webapp=/lpjh/um path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1 
[junit4:junit4]   2> 1609981 T3763 C837 P50199 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 1609982 T3763 C837 P50199 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 1609983 T3763 C837 P50199 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 1609985 T3763 C837 P50199 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@65239252 lockFactory=org.apache.lucene.store.NativeFSLockFactory@467feeae),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@65239252 lockFactory=org.apache.lucene.store.NativeFSLockFactory@467feeae),segFN=segments_2,generation=2}
[junit4:junit4]   2> 1609986 T3763 C837 P50199 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 1609987 T3763 C837 P50199 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 1609988 T3763 C837 P50199 oass.SolrIndexSearcher.<init> Opening Searcher@158cc461 main
[junit4:junit4]   2> 1609989 T3762 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@158cc461 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1609990 T3763 C837 P50199 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty3/index.20130618091613696 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty3/index.20130618091613696;done=true>>]
[junit4:junit4]   2> 1609990 T3763 C837 P50199 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty3/index.20130618091613696
[junit4:junit4]   2> 1609991 T3763 C837 P50199 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty3/index.20130618091613696
[junit4:junit4]   2> 1609991 T3763 C837 P50199 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 1609991 T3763 C837 P50199 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 1609991 T3763 C837 P50199 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 1609992 T3763 C837 P50199 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1609994 T3763 C837 P50199 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 1610506 T3709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1610509 T3709 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50203_lpjh%2Fum",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50203/lpjh/um"}
[junit4:junit4]   2> 1610509 T3709 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 1610510 T3709 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4]   2> 1610520 T3709 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:50199_lpjh%2Fum_collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50199_lpjh%2Fum",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50199/lpjh/um"}
[junit4:junit4]   2> 1610533 T3777 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1610533 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1610534 T3744 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1610536 T3760 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1610543 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1610543 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1610560 T3778 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371564970563/collection1
[junit4:junit4]   2> 1610560 T3778 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 1610562 T3778 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 1610562 T3778 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 1610566 T3778 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371564970563/collection1/'
[junit4:junit4]   2> 1610568 T3778 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1371564970563/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 1610569 T3778 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1371564970563/collection1/lib/README' to classloader
[junit4:junit4]   2> 1610657 T3778 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1610767 T3778 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1610773 T3778 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1610784 T3778 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 1611777 T3778 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1611782 T3778 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1611785 T3778 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1611795 T3778 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1611897 T3778 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1611898 T3778 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371564970563/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty4/
[junit4:junit4]   2> 1611898 T3778 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4e17aa0d
[junit4:junit4]   2> 1611899 T3778 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1611900 T3778 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty4
[junit4:junit4]   2> 1611900 T3778 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty4/index/
[junit4:junit4]   2> 1611900 T3778 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1611902 T3778 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty4/index
[junit4:junit4]   2> 1611907 T3778 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2f66aa18 lockFactory=org.apache.lucene.store.NativeFSLockFactory@634752b3),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1611908 T3778 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1611913 T3778 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1611913 T3778 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1611914 T3778 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1611916 T3778 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1611917 T3778 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1611917 T3778 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1611918 T3778 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1611919 T3778 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1611920 T3778 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1611944 T3778 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1611957 T3778 oass.SolrIndexSearcher.<init> Opening Searcher@1cb397c5 main
[junit4:junit4]   2> 1611958 T3778 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty4/tlog
[junit4:junit4]   2> 1611959 T3778 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1611960 T3778 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1611967 T3778 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 1611967 T3778 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50203/lpjh/um collection:collection1 shard:shard2
[junit4:junit4]   2> 1611968 T3781 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1cb397c5 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1611975 T3778 oasc.ZkController.register We are http://127.0.0.1:50203/lpjh/um/collection1/ and leader is http://127.0.0.1:50196/lpjh/um/collection1/
[junit4:junit4]   2> 1611976 T3778 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50203/lpjh/um
[junit4:junit4]   2> 1611976 T3778 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 1611976 T3778 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C839 name=collection1 org.apache.solr.core.SolrCore@3c6b4edb url=http://127.0.0.1:50203/lpjh/um/collection1 node=127.0.0.1:50203_lpjh%2Fum C839_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:50203_lpjh%2Fum, base_url=http://127.0.0.1:50203/lpjh/um}
[junit4:junit4]   2> 1611977 T3782 C839 P50203 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 1611980 T3782 C839 P50203 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 1611980 T3782 C839 P50203 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 1611980 T3782 C839 P50203 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1611983 T3778 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1611984 T3782 C839 P50203 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1612009 T3686 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 1612010 T3686 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1612010 T3686 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1612023 T3739 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:50203_lpjh%2Fum_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 1612038 T3686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1612041 T3686 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4]   2> 1612042 T3686 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4]   2> 1612044 T3686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1612073 T3709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1612076 T3709 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:50203_lpjh%2Fum_collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50203_lpjh%2Fum",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50203/lpjh/um"}
[junit4:junit4]   2> 1612090 T3760 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1612090 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1612090 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1612092 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1612092 T3744 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1612093 T3777 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1613027 T3739 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:50203_lpjh%2Fum_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4]   2> 1613028 T3739 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:50203_lpjh%252Fum_collection1&state=recovering&nodeName=127.0.0.1:50203_lpjh%252Fum&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1005 
[junit4:junit4]   2> 1613049 T3686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1614054 T3686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C839_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:50203_lpjh%2Fum, base_url=http://127.0.0.1:50203/lpjh/um}
[junit4:junit4]   2> 1615034 T3782 C839 P50203 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50196/lpjh/um/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 1615035 T3782 C839 P50203 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50203/lpjh/um START replicas=[http://127.0.0.1:50196/lpjh/um/collection1/] nUpdates=100
[junit4:junit4]   2> 1615036 T3782 C839 P50203 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 1615036 T3782 C839 P50203 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 1615036 T3782 C839 P50203 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 1615037 T3782 C839 P50203 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 1615037 T3782 C839 P50203 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 1615037 T3782 C839 P50203 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50196/lpjh/um/collection1/. core=collection1
[junit4:junit4]   2> 1615037 T3782 C839 P50203 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C840 name=collection1 org.apache.solr.core.SolrCore@7970dbe4 url=http://127.0.0.1:50196/lpjh/um/collection1 node=127.0.0.1:50196_lpjh%2Fum C840_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50196_lpjh%2Fum, base_url=http://127.0.0.1:50196/lpjh/um, leader=true}
[junit4:junit4]   2> 1615061 T3736 C840 P50196 oasc.SolrCore.execute [collection1] webapp=/lpjh/um path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1 
[junit4:junit4]   2> 1615064 T3686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1615069 T3737 C840 P50196 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 1615072 T3737 C840 P50196 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a5c909d lockFactory=org.apache.lucene.store.NativeFSLockFactory@15f43cb1),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1615073 T3737 C840 P50196 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1615074 T3737 C840 P50196 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a5c909d lockFactory=org.apache.lucene.store.NativeFSLockFactory@15f43cb1),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a5c909d lockFactory=org.apache.lucene.store.NativeFSLockFactory@15f43cb1),segFN=segments_2,generation=2}
[junit4:junit4]   2> 1615074 T3737 C840 P50196 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 1615075 T3737 C840 P50196 oass.SolrIndexSearcher.<init> Opening Searcher@1509b155 realtime
[junit4:junit4]   2> 1615075 T3737 C840 P50196 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1615076 T3737 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4]   2> 1615077 T3782 C839 P50203 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 1615078 T3782 C839 P50203 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 1615083 T3740 C840 P50196 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 1615084 T3740 C840 P50196 oasc.SolrCore.execute [collection1] webapp=/lpjh/um path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2 
[junit4:junit4]   2> 1615085 T3782 C839 P50203 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 1615085 T3782 C839 P50203 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 1615085 T3782 C839 P50203 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 1615088 T3735 C840 P50196 oasc.SolrCore.execute [collection1] webapp=/lpjh/um path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0 
[junit4:junit4]   2> 1615089 T3782 C839 P50203 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 1615091 T3782 C839 P50203 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty4/index.20130618091618814
[junit4:junit4]   2> 1615091 T3782 C839 P50203 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@742b1776 lockFactory=org.apache.lucene.store.NativeFSLockFactory@496b2f19) fullCopy=false
[junit4:junit4]   2> 1615094 T3739 C840 P50196 oasc.SolrCore.execute [collection1] webapp=/lpjh/um path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 1615096 T3782 C839 P50203 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 1615097 T3782 C839 P50203 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 1615098 T3782 C839 P50203 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 1615100 T3782 C839 P50203 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2f66aa18 lockFactory=org.apache.lucene.store.NativeFSLockFactory@634752b3),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2f66aa18 lockFactory=org.apache.lucene.store.NativeFSLockFactory@634752b3),segFN=segments_2,generation=2}
[junit4:junit4]   2> 1615100 T3782 C839 P50203 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 1615101 T3782 C839 P50203 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 1615102 T3782 C839 P50203 oass.SolrIndexSearcher.<init> Opening Searcher@46ffc119 main
[junit4:junit4]   2> 1615104 T3781 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@46ffc119 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1615104 T3782 C839 P50203 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty4/index.20130618091618814 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty4/index.20130618091618814;done=true>>]
[junit4:junit4]   2> 1615105 T3782 C839 P50203 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty4/index.20130618091618814
[junit4:junit4]   2> 1615105 T3782 C839 P50203 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1371564945959/jetty4/index.20130618091618814
[junit4:junit4]   2> 1615105 T3782 C839 P50203 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 1615106 T3782 C839 P50203 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 1615106 T3782 C839 P50203 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 1615106 T3782 C839 P50203 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1615114 T3782 C839 P50203 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 1615122 T3709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1615124 T3709 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:50203_lpjh%2Fum_collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50203_lpjh%2Fum",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50203/lpjh/um"}
[junit4:junit4]   2> 1615135 T3760 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1615138 T3777 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1615138 T3715 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1615139 T3708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1615140 T3728 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1615141 T3744 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1616068 T3686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1616070 T3686 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4]   2> ASYNC  NEW_CORE C841 name=collection1 org.apache.solr.core.SolrCore@d6cfa68 url=http://127.0.0.1:50189/lpjh/um/collection1 node=127.0.0.1:50189_lpjh%2Fum C841_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:50189_lpjh%2Fum, base_url=http://127.0.0.1:50189/lpjh/um, leader=true}
[junit4:junit4]   2> 1616090 T3701 C841 P50189 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 1616093 T3701 C841 P50189 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@bc0c015 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f555b4e),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1616094 T3701 C841 P50189 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1616095 T3701 C841 P50189 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@bc0c015 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f555b4e),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@bc0c015 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f555b4e),segFN=segments_2,generation=2}
[junit4:junit4]   2> 1616096 T3701 C841 P50189 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 1616097 T3701 C841 P50189 oass.SolrIndexSearcher.<init> Opening Searcher@54f93adc main
[junit4:junit4]   2> 1616097 T3701 C841 P50189 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1616098 T3712 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@54f93adc main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1616099 T3701 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4]   2>  C839_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50203_lpjh%2Fum, base_url=http://127.0.0.1:50203/lpjh/um}
[junit4:junit4]   2> 1616132 T3773 C839 P50203 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:50193/lpjh/um/collection1/, StdNode: http://127.0.0.1:50199/lpjh/um/collection1/, StdNode: http://127.0.0.1:50196/lpjh/um/collection1/, StdNode: http://127.0.0.1:50203/lpjh/um/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4]   2> 1616151 T3768 C839 P50203 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> ASYNC  NEW_CORE C842 name=collection1 org.apache.solr.core.SolrCore@191f1340 url=http://127.0.0.1:50193/lpjh/um/collection1 node=127.0.0.1:50193_lpjh%2Fum C842_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50193_lpjh%2Fum, base_url=http://127.0.0.1:50193/lpjh/um, leader=true}
[junit4:junit4]   2> 1616155 T3723 C842 P50193 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 1616153 T3738 C840 P50196 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 1616158 T3768 C839 P50203 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2f66aa18 lockFactory=org.apache.lucene.store.NativeFSLockFactory@634752b3),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2f66aa18 lockFactory=org.apache.lucene.store.NativeFSLockFactory@634752b3),segFN=segments_3,generation=3}
[junit4:junit4]   2> 1616159 T3768 C839 P50203 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 1616162 T3768 C839 P50203 oass.SolrIndexSearcher.<init> Opening Searcher@34b27842 main
[junit4:junit4]   2> 1616162 T3768 C839 P50203 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1616164 T3781 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@34b27842 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1616164 T3768 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4]   2> 1616166 T3723 C842 P50193 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@50544a26 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3720dece),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@50544a26 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3720dece),segFN=segments_3,generation=3}
[junit4:junit4]   2> 1616167 T3723 C842 P50193 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 1616167 T3723 C842 P50193 oass.SolrIndexSearcher.<init> Opening Searcher@3aec044e main
[junit4:junit4]   2> 1616168 T3723 C842 P50193 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1616170 T3730 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3aec044e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1616170 T3723 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 15
[junit4:junit4]   2> 1616172 T3738 C840 P50196 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a5c909d lockFactory=org.apache.lucene.store.NativeFSLockFactory@15f43cb1),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a5c909d lockFactory=org.apache.lucene.store.NativeFSLockFactory@15f43cb1),segFN=segments_3,generation=3}
[junit4:junit4]   2> 1616172 T3738 C840 P50196 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 1616173 T3738 C840 P50196 oass.SolrIndexSearcher.<init> Opening Searcher@721dd7b0 main
[junit4:junit4]   2> 1616176 T3738 C840 P50196 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> ASYNC  NEW_CORE C843 name=collection1 org.apache.solr.core.SolrCore@3f9c5009 url=http://127.0.0.1:50199/lpjh/um/collection1 node=127.0.0.1:50199_lpjh%2Fum C843_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50199_lpjh%2Fum, base_url=http://127.0.0.1:50199/lpjh/um}
[junit4:junit4]   2> 1616174 T3755 C843 P50199 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 1616178 T3746 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@721dd7b0 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1616178 T3738 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 26
[junit4:junit4]   2> 1616180 T3755 C843 P50199 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@65239252 lockFactory=org.apache.lucene.store.NativeFSLockFactory@467feeae),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@65239252 lockFactory=org.apache.lucene.store.NativeFSLockFactory@467feeae),segFN=segments_3,generation=3}
[junit4:junit4]   2> 1616181 T3755 C843 P50199 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 1616182 T3755 C843 P50199 oass.SolrIndexSearcher.<init> Opening Searcher@78190521 main
[junit4:junit4]   2> 1616182 T3755 C843 P50199 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1616183 T3762 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@78190521 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1616184 T3755 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 16
[junit4:junit4]   2> 1616186 T3773 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 54
[junit4:junit4]   2> 1616188 T3686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1616193 T3724 C842 P50193 oasc.SolrCore.execute [collection1] webapp=/lpjh/um path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0 
[junit4:junit4]   2> 1616198 T3751 C843 P50199 oasc.SolrCore.execute [collection1] webapp=/lpjh/um path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1 
[junit4:junit4]   2> 1616201 T3740 C840 P50196 oasc.SolrCore.execute [collection1] webapp=/lpjh/um path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0 
[junit4:junit4]   2> 1616206 T3771 C839 P50203 oasc.SolrCore.execute [collection1] webapp=/lpjh/um path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0 
[junit4:junit4]   2> 1618214 T3700 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438190122498523136)} 0 3
[junit4:junit4]   2> 1618237 T3752 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={update.distrib=FROMLEADER&_version_=-1438190122512154624&update.from=http://127.0.0.1:50193/lpjh/um/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438190122512154624)} 0 2
[junit4:junit4]   2> 1618241 T3724 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438190122512154624)} 0 16
[junit4:junit4]   2> 1618243 T3769 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={update.distrib=FROMLEADER&_version_=-1438190122507960320&update.from=http://127.0.0.1:50196/lpjh/um/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438190122507960320)} 0 4
[junit4:junit4]   2> 1618245 T3740 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438190122507960320)} 0 25
[junit4:junit4]   2> 1618246 T3771 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 29
[junit4:junit4]   2> 1618252 T3701 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[a!0 (1438190122538369024)]} 0 2
[junit4:junit4]   2> 1618265 T3768 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1438190122548854784)]} 0 1
[junit4:junit4]   2> 1618267 T3735 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!0 (1438190122548854784)]} 0 7
[junit4:junit4]   2> 1618268 T3721 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[a!0]} 0 12
[junit4:junit4]   2> 1618273 T3702 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[b!1 (1438190122562486272)]} 0 0
[junit4:junit4]   2> 1618293 T3753 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1438190122571923456)]} 0 3
[junit4:junit4]   2> 1618295 T3722 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[b!1 (1438190122571923456)]} 0 14
[junit4:junit4]   2> 1618300 T3703 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[c!2 (1438190122589749248)]} 0 1
[junit4:junit4]   2> 1618319 T3754 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1438190122600235008)]} 0 1
[junit4:junit4]   2> 1618322 T3719 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[c!2 (1438190122600235008)]} 0 13
[junit4:junit4]   2> 1618327 T3704 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[d!3 (1438190122619109376)]} 0 0
[junit4:junit4]   2> 1618335 T3773 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1438190122624352256)]} 0 0
[junit4:junit4]   2> 1618337 T3739 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[d!3 (1438190122624352256)]} 0 5
[junit4:junit4]   2> 1618341 T3699 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[e!4 (1438190122632740864)]} 0 1
[junit4:junit4]   2> 1618351 T3772 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1438190122640080896)]} 0 1
[junit4:junit4]   2> 1618352 T3736 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50203/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!4 (1438190122640080896)]} 0 5
[junit4:junit4]   2> 1618353 T3770 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[e!4]} 0 9
[junit4:junit4]   2> 1618359 T3700 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[f!5 (1438190122651615232)]} 0 1
[junit4:junit4]   2> 1618372 T3771 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1438190122663149568)]} 0 1
[junit4:junit4]   2> 1618373 T3737 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50203/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1438190122663149568)]} 0 4
[junit4:junit4]   2> 1618377 T3769 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[f!5]} 0 15
[junit4:junit4]   2> 1618383 T3701 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[g!6 (1438190122676781056)]} 0 1
[junit4:junit4]   2> 1618397 T3750 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1438190122689363968)]} 0 1
[junit4:junit4]   2> 1618398 T3723 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50199/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!6 (1438190122689363968)]} 0 4
[junit4:junit4]   2> 1618399 T3755 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[g!6]} 0 10
[junit4:junit4]   2> 1618402 T3702 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[h!7 (1438190122697752576)]} 0 0
[junit4:junit4]   2> 1618407 T3751 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1438190122700898304)]} 0 0
[junit4:junit4]   2> 1618408 T3724 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[h!7 (1438190122700898304)]} 0 3
[junit4:junit4]   2> 1618416 T3703 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[i!8 (1438190122712432640)]} 0 1
[junit4:junit4]   2> 1618421 T3752 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1438190122714529792)]} 0 1
[junit4:junit4]   2> 1618422 T3720 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[i!8 (1438190122714529792)]} 0 4
[junit4:junit4]   2> 1618435 T3704 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[j!9 (1438190122731307008)]} 0 1
[junit4:junit4]   2> 1618446 T3754 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1438190122739695616)]} 0 1
[junit4:junit4]   2> 1618448 T3721 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50199/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!9 (1438190122739695616)]} 0 6
[junit4:junit4]   2> 1618450 T3753 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[j!9]} 0 12
[junit4:junit4]   2> 1618457 T3699 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[k!10 (1438190122754375680)]} 0 1
[junit4:junit4]   2> 1618466 T3750 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1438190122760667136)]} 0 1
[junit4:junit4]   2> 1618468 T3722 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[k!10 (1438190122760667136)]} 0 6
[junit4:junit4]   2> 1618472 T3700 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[l!11 (1438190122770104320)]} 0 1
[junit4:junit4]   2> 1618480 T3768 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1438190122775347200)]} 0 1
[junit4:junit4]   2> 1618482 T3738 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[l!11 (1438190122775347200)]} 0 6
[junit4:junit4]   2> 1618486 T3701 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[m!12 (1438190122785832960)]} 0 0
[junit4:junit4]   2> 1618495 T3773 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1438190122791075840)]} 0 1
[junit4:junit4]   2> 1618497 T3740 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[m!12 (1438190122791075840)]} 0 6
[junit4:junit4]   2> 1618502 T3702 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[n!13 (1438190122802610176)]} 0 1
[junit4:junit4]   2> 1618517 T3751 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1438190122814144512)]} 0 1
[junit4:junit4]   2> 1618519 T3719 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50199/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!13 (1438190122814144512)]} 0 8
[junit4:junit4]   2> 1618521 T3755 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[n!13]} 0 13
[junit4:junit4]   2> 1618526 T3703 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[o!14 (1438190122827776000)]} 0 1
[junit4:junit4]   2> 1618549 T3770 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1438190122847698944)]} 0 1
[junit4:junit4]   2> 1618552 T3735 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50203/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!14 (1438190122847698944)]} 0 7
[junit4:junit4]   2> 1618554 T3772 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[o!14]} 0 16
[junit4:junit4]   2> 1618558 T3699 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[p!15 (1438190122861330432)]} 0 1
[junit4:junit4]   2> 1618572 T3752 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1438190122867621888)]} 0 0
[junit4:junit4]   2> 1618575 T3723 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[p!15 (1438190122867621888)]} 0 11
[junit4:junit4]   2> 1618580 T3700 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[q!16 (1438190122884399104)]} 0 0
[junit4:junit4]   2> 1618593 T3754 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1438190122892787712)]} 0 1
[junit4:junit4]   2> 1618595 T3724 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50203/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1438190122892787712)]} 0 7
[junit4:junit4]   2> 1618597 T3771 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[q!16]} 0 12
[junit4:junit4]   2> 1618608 T3701 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[r!17 (1438190122912710656)]} 0 1
[junit4:junit4]   2> 1618627 T3769 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1438190122929487872)]} 0 1
[junit4:junit4]   2> 1618629 T3739 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[r!17 (1438190122929487872)]} 0 7
[junit4:junit4]   2> 1618635 T3702 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[s!18 (1438190122941022208)]} 0 1
[junit4:junit4]   2> 1618644 T3753 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1438190122947313664)]} 0 1
[junit4:junit4]   2> 1618646 T3720 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[s!18 (1438190122947313664)]} 0 7
[junit4:junit4]   2> 1618652 T3704 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[t!19 (1438190122958848000)]} 0 1
[junit4:junit4]   2> 1618660 T3751 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1438190122964090880)]} 0 0
[junit4:junit4]   2> 1618668 T3722 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[t!19 (1438190122964090880)]} 0 12
[junit4:junit4]   2> 1618676 T3703 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[u!20 (1438190122985062400)]} 0 0
[junit4:junit4]   2> 1618689 T3773 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1438190122993451008)]} 0 1
[junit4:junit4]   2> 1618691 T3737 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50199/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!20 (1438190122993451008)]} 0 7
[junit4:junit4]   2> 1618692 T3755 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[u!20]} 0 12
[junit4:junit4]   2> 1618697 T3699 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[v!21 (1438190123007082496)]} 0 0
[junit4:junit4]   2> 1618707 T3752 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1438190123014422528)]} 0 0
[junit4:junit4]   2> 1618708 T3719 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!21 (1438190123014422528)]} 0 4
[junit4:junit4]   2> 1618709 T3738 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[v!21]} 0 9
[junit4:junit4]   2> 1618713 T3700 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[w!22 (1438190123022811136)]} 0 1
[junit4:junit4]   2> 1618720 T3753 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1438190123029102592)]} 0 0
[junit4:junit4]   2> 1618721 T3723 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50199/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!22 (1438190123029102592)]} 0 4
[junit4:junit4]   2> 1618722 T3754 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[w!22]} 0 7
[junit4:junit4]   2> 1618726 T3701 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[x!23 (1438190123036442624)]} 0 1
[junit4:junit4]   2> 1618732 T3770 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1438190123040636928)]} 0 1
[junit4:junit4]   2> 1618733 T3740 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[x!23 (1438190123040636928)]} 0 4
[junit4:junit4]   2> 1618736 T3702 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[y!24 (1438190123047976960)]} 0 0
[junit4:junit4]   2> 1618745 T3772 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1438190123054268416)]} 0 0
[junit4:junit4]   2> 1618746 T3735 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50199/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!24 (1438190123054268416)]} 0 5
[junit4:junit4]   2> 1618748 T3750 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[y!24]} 0 9
[junit4:junit4]   2> 1618752 T3704 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[z!25 (1438190123063705600)]} 0 1
[junit4:junit4]   2> 1618760 T3751 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1438190123069997056)]} 0 0
[junit4:junit4]   2> 1618762 T3724 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!25 (1438190123069997056)]} 0 5
[junit4:junit4]   2> 1618764 T3736 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[z!25]} 0 9
[junit4:junit4]   2> 1618768 T3703 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[a!26 (1438190123080482816)]} 0 1
[junit4:junit4]   2> 1618777 T3771 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1438190123087822848)]} 0 0
[junit4:junit4]   2> 1618779 T3739 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50199/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!26 (1438190123087822848)]} 0 5
[junit4:junit4]   2> 1618780 T3755 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[a!26]} 0 9
[junit4:junit4]   2> 1618784 T3699 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[b!27 (1438190123098308608)]} 0 0
[junit4:junit4]   2> 1618793 T3753 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1438190123104600064)]} 0 0
[junit4:junit4]   2> 1618795 T3721 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50199/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!27 (1438190123104600064)]} 0 5
[junit4:junit4]   2> 1618796 T3752 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[b!27]} 0 9
[junit4:junit4]   2> 1618800 T3700 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[c!28 (1438190123114037248)]} 0 1
[junit4:junit4]   2> 1618817 T3750 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1438190123129765888)]} 0 0
[junit4:junit4]   2> 1618819 T3720 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50199/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!28 (1438190123129765888)]} 0 5
[junit4:junit4]   2> 1618820 T3754 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[c!28]} 0 17
[junit4:junit4]   2> 1618824 T3701 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[d!29 (1438190123139203072)]} 0 1
[junit4:junit4]   2> 1618832 T3769 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1438190123145494528)]} 0 0
[junit4:junit4]   2> 1618833 T3737 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50203/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1438190123145494528)]} 0 4
[junit4:junit4]   2> 1618836 T3768 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[d!29]} 0 9
[junit4:junit4]   2> 1618847 T3702 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[e!30 (1438190123164368896)]} 0 0
[junit4:junit4]   2> 1618855 T3773 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1438190123169611776)]} 0 1
[junit4:junit4]   2> 1618856 T3738 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[e!30 (1438190123169611776)]} 0 5
[junit4:junit4]   2> 1618862 T3704 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[f!31 (1438190123179048960)]} 0 1
[junit4:junit4]   2> 1618876 T3770 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1438190123189534720)]} 0 1
[junit4:junit4]   2> 1618878 T3740 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1438190123189534720)]} 0 7
[junit4:junit4]   2> 1618880 T3722 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[f!31]} 0 12
[junit4:junit4]   2> 1618885 T3703 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[g!32 (1438190123204214784)]} 0 1
[junit4:junit4]   2> 1618897 T3751 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1438190123212603392)]} 0 1
[junit4:junit4]   2> 1618899 T3719 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50203/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!32 (1438190123212603392)]} 0 7
[junit4:junit4]   2> 1618901 T3772 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[g!32]} 0 12
[junit4:junit4]   2> 1618906 T3699 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[h!33 (1438190123225186304)]} 0 1
[junit4:junit4]   2> 1618914 T3755 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1438190123230429184)]} 0 0
[junit4:junit4]   2> 1618917 T3723 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[h!33 (1438190123230429184)]} 0 7
[junit4:junit4]   2> 1618922 T3700 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[i!34 (1438190123243012096)]} 0 1
[junit4:junit4]   2> 1618939 T3753 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1438190123251400704)]} 0 1
[junit4:junit4]   2> 1618941 T3724 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!34 (1438190123251400704)]} 0 11
[junit4:junit4]   2> 1618942 T3735 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[i!34]} 0 16
[junit4:junit4]   2> 1618947 T3701 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[j!35 (1438190123269226496)]} 0 0
[junit4:junit4]   2> 1618964 T3750 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1438190123278663680)]} 0 1
[junit4:junit4]   2> 1618966 T3721 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50199/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!35 (1438190123278663680)]} 0 10
[junit4:junit4]   2> 1618967 T3752 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[j!35]} 0 16
[junit4:junit4]   2> 1618972 T3704 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[k!36 (1438190123294392320)]} 0 1
[junit4:junit4]   2> 1618982 T3751 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1438190123302780928)]} 0 1
[junit4:junit4]   2> 1618983 T3720 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50199/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!36 (1438190123302780928)]} 0 5
[junit4:junit4]   2> 1618984 T3754 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[k!36]} 0 8
[junit4:junit4]   2> 1618988 T3703 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[l!37 (1438190123312218112)]} 0 0
[junit4:junit4]   2> 1618998 T3771 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1438190123318509568)]} 0 1
[junit4:junit4]   2> 1618999 T3736 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1438190123318509568)]} 0 5
[junit4:junit4]   2> 1619000 T3722 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[l!37]} 0 9
[junit4:junit4]   2> 1619004 T3699 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[m!38 (1438190123328995328)]} 0 0
[junit4:junit4]   2> 1619011 T3769 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1438190123333189632)]} 0 1
[junit4:junit4]   2> 1619012 T3739 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[m!38 (1438190123333189632)]} 0 4
[junit4:junit4]   2> 1619016 T3700 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[n!39 (1438190123341578240)]} 0 0
[junit4:junit4]   2> 1619027 T3755 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1438190123348918272)]} 0 1
[junit4:junit4]   2> 1619028 T3719 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50203/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!39 (1438190123348918272)]} 0 5
[junit4:junit4]   2> 1619029 T3768 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[n!39]} 0 9
[junit4:junit4]   2> 1619033 T3702 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[o!40 (1438190123359404032)]} 0 0
[junit4:junit4]   2> 1619048 T3772 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1438190123370938368)]} 0 1
[junit4:junit4]   2> 1619049 T3737 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50203/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!40 (1438190123370938368)]} 0 5
[junit4:junit4]   2> 1619050 T3770 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[o!40]} 0 9
[junit4:junit4]   2> 1619055 T3701 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[p!41 (1438190123381424128)]} 0 1
[junit4:junit4]   2> 1619061 T3753 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1438190123385618432)]} 0 0
[junit4:junit4]   2> 1619063 T3723 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[p!41 (1438190123385618432)]} 0 5
[junit4:junit4]   2> 1619069 T3704 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[q!42 (1438190123396104192)]} 0 1
[junit4:junit4]   2> 1619085 T3751 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1438190123409735680)]} 0 1
[junit4:junit4]   2> 1619088 T3721 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50199/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!42 (1438190123409735680)]} 0 7
[junit4:junit4]   2> 1619090 T3752 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[q!42]} 0 13
[junit4:junit4]   2> 1619093 T3703 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[r!43 (1438190123422318592)]} 0 0
[junit4:junit4]   2> 1619100 T3771 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1438190123426512896)]} 0 1
[junit4:junit4]   2> 1619101 T3740 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[r!43 (1438190123426512896)]} 0 4
[junit4:junit4]   2> 1619105 T3699 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[s!44 (1438190123434901504)]} 0 0
[junit4:junit4]   2> 1619118 T3754 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1438190123441192960)]} 0 2
[junit4:junit4]   2> 1619122 T3720 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!44 (1438190123441192960)]} 0 11
[junit4:junit4]   2> 1619123 T3735 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[s!44]} 0 14
[junit4:junit4]   2> 1619126 T3700 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[t!45 (1438190123456921600)]} 0 0
[junit4:junit4]   2> 1619135 T3750 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1438190123463213056)]} 0 0
[junit4:junit4]   2> 1619137 T3722 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50199/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!45 (1438190123463213056)]} 0 5
[junit4:junit4]   2> 1619138 T3755 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[t!45]} 0 9
[junit4:junit4]   2> 1619142 T3702 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[u!46 (1438190123473698816)]} 0 0
[junit4:junit4]   2> 1619153 T3768 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1438190123482087424)]} 0 1
[junit4:junit4]   2> 1619154 T3736 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50203/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!46 (1438190123482087424)]} 0 5
[junit4:junit4]   2> 1619156 T3769 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[u!46]} 0 9
[junit4:junit4]   2> 1619176 T3701 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[v!47 (1438190123509350400)]} 0 0
[junit4:junit4]   2> 1619188 T3753 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1438190123518787584)]} 0 1
[junit4:junit4]   2> 1619189 T3719 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[v!47 (1438190123518787584)]} 0 5
[junit4:junit4]   2> 1619199 T3704 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[w!48 (1438190123532419072)]} 0 1
[junit4:junit4]   2> 1619211 T3751 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1438190123539759104)]} 0 2
[junit4:junit4]   2> 1619213 T3724 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[w!48 (1438190123539759104)]} 0 9
[junit4:junit4]   2> 1619219 T3703 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[x!49 (1438190123553390592)]} 0 1
[junit4:junit4]   2> 1619229 T3773 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1438190123559682048)]} 0 1
[junit4:junit4]   2> 1619232 T3739 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[x!49 (1438190123559682048)]} 0 8
[junit4:junit4]   2> 1619237 T3699 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[y!50 (1438190123573313536)]} 0 0
[junit4:junit4]   2> 1619251 T3770 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1438190123582750720)]} 0 1
[junit4:junit4]   2> 1619253 T3738 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50203/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!50 (1438190123582750720)]} 0 7
[junit4:junit4]   2> 1619256 T3772 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[y!50]} 0 14
[junit4:junit4]   2> 1619261 T3700 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[z!51 (1438190123597430784)]} 0 1
[junit4:junit4]   2> 1619278 T3752 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1438190123607916544)]} 0 1
[junit4:junit4]   2> 1619280 T3723 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[z!51 (1438190123607916544)]} 0 11
[junit4:junit4]   2> 1619289 T3702 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[a!52 (1438190123627839488)]} 0 1
[junit4:junit4]   2> 1619303 T3771 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1438190123637276672)]} 0 1
[junit4:junit4]   2> 1619305 T3737 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!52 (1438190123637276672)]} 0 7
[junit4:junit4]   2> 1619308 T3721 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[a!52]} 0 15
[junit4:junit4]   2> 1619313 T3701 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[b!53 (1438190123653005312)]} 0 1
[junit4:junit4]   2> 1619325 T3754 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1438190123662442496)]} 0 0
[junit4:junit4]   2> 1619327 T3720 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!53 (1438190123662442496)]} 0 5
[junit4:junit4]   2> 1619334 T3740 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[b!53]} 0 15
[junit4:junit4]   2> 1619339 T3704 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[c!54 (1438190123679219712)]} 0 1
[junit4:junit4]   2> 1619361 T3755 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50193/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1438190123697045504)]} 0 1
[junit4:junit4]   2> 1619362 T3722 C842 P50193 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50199/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!54 (1438190123697045504)]} 0 8
[junit4:junit4]   2> 1619363 T3750 C843 P50199 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[c!54]} 0 19
[junit4:junit4]   2> 1619368 T3703 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[d!55 (1438190123710676992)]} 0 0
[junit4:junit4]   2> 1619375 T3768 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1438190123714871296)]} 0 0
[junit4:junit4]   2> 1619377 T3735 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[d!55 (1438190123714871296)]} 0 5
[junit4:junit4]   2> 1619381 T3700 C841 P50189 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={wt=javabin&version=2} {add=[e!56 (1438190123724308480)]} 0 1
[junit4:junit4]   2> 1619390 T3773 C839 P50203 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50196/lpjh/um/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1438190123730599936)]} 0 0
[junit4:junit4]   2> 1619392 T3736 C840 P50196 oasup.LogUpdateProcessor.finish [collection1] webapp=/lpjh/um path=/update params={distrib.from=http://127.0.0.1:50203/lpjh/um/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!56 (1438190123730599936)]} 0 5
[junit4:junit4]   2> 1619394 T3769 C83

[...truncated too long message...]

118_STATE=coll:collection1 core:collection1 props:{shard=shard3, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:50612_, base_url=http://127.0.0.1:50612, leader=true}
[junit4:junit4]   2> 2257627 T4695 C1118 P50612 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371565450651/jetty12/index,segFN=segments_q,generation=26}
[junit4:junit4]   2> 		commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371565450651/jetty12/index,segFN=segments_r,generation=27}
[junit4:junit4]   2> 2257628 T4695 C1118 P50612 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 27
[junit4:junit4]   2> 2257633 T4695 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 2257635 T4695 oasc.CachingDirectoryFactory.close Closing StandardDirectoryFactory - 2 directories currently being tracked
[junit4:junit4]   2> 2257635 T4695 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371565450651/jetty12 [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371565450651/jetty12;done=false>>]
[junit4:junit4]   2> 2257636 T4695 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371565450651/jetty12
[junit4:junit4]   2> 2257637 T4695 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371565450651/jetty12/index [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371565450651/jetty12/index;done=false>>]
[junit4:junit4]   2> 2257638 T4695 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371565450651/jetty12/index
[junit4:junit4]   2> 2257640 T5218 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89886913374584860-127.0.0.1:50612_-n_0000000012) am no longer a leader.
[junit4:junit4]   2> 2257646 T4935 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 2257647 T4935 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 2257647 T4935 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 2257662 T4695 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4]   2> 2257854 T4695 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4]   2> 2257858 T4695 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:50551 50551
[junit4:junit4]   1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4]   1> safe stop:
[junit4:junit4]   1> safe stop:
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=ChaosMonkeySafeLeaderTest -Dtests.method=testDistribSearch -Dtests.seed=DD25AAB11FD4D6C2 -Dtests.slow=true -Dtests.locale=el_CY -Dtests.timezone=Atlantic/Reykjavik -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] FAILURE  171s | ChaosMonkeySafeLeaderTest.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: java.lang.AssertionError: shard3 is not consistent.  Got 36 from http://127.0.0.1:50578/collection1lastClient and got 34 from http://127.0.0.1:50612/collection1
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([DD25AAB11FD4D6C2:5CC324A9688BB6FE]:0)
[junit4:junit4]    > 	at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
[junit4:junit4]    > 	at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
[junit4:junit4]    > 	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4]    > 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 2257969 T4695 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 171059 T4694 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4]   2> NOTE: test params are: codec=Lucene41, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=el_CY, timezone=Atlantic/Reykjavik
[junit4:junit4]   2> NOTE: Mac OS X 10.8.4 x86_64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=2,threads=3,free=204740688,total=356122624
[junit4:junit4]   2> NOTE: All tests run in this JVM: [HighlighterConfigTest, TestCoreContainer, SolrPluginUtilsTest, DistributedSpellCheckComponentTest, OpenCloseCoreStressTest, TestSurroundQueryParser, QueryParsingTest, SynonymTokenizerTest, CollectionsAPIDistributedZkTest, CoreContainerCoreInitFailuresTest, TestSystemIdResolver, TestSchemaNameResource, ShowFileRequestHandlerTest, JSONWriterTest, TestIndexSearcher, LegacyHTMLStripCharFilterTest, CSVRequestHandlerTest, ScriptEngineTest, TestSolrIndexConfig, TestLRUCache, TestLazyCores, TestRemoteStreaming, SolrInfoMBeanTest, TestFieldResource, BasicDistributedZk2Test, TestNumberUtils, TestPhraseSuggestions, RequestHandlersTest, QueryElevationComponentTest, TestCSVLoader, PluginInfoTest, TestXIncludeConfig, TestQueryTypes, SolrCoreCheckLockOnStartupTest, TestSolrQueryParser, TestCSVResponseWriter, CurrencyFieldOpenExchangeTest, DistributedQueryElevationComponentTest, TestZkChroot, SpellPossibilityIteratorTest, SortByFunctionTest, TestSolrDeletionPolicy1, SyncSliceTest, ResponseLogComponentTest, RegexBoostProcessorTest, DirectSolrConnectionTest, TestStressLucene, TestJmxIntegration, ZkCLITest, PathHierarchyTokenizerFactoryTest, TestReplicationHandler, ZkNodePropsTest, ShardRoutingTest, SolrCoreTest, TestPostingsSolrHighlighter, TestCopyFieldCollectionResource, BinaryUpdateRequestHandlerTest, IndexSchemaTest, SimplePostToolTest, SOLR749Test, SpellCheckComponentTest, FileUtilsTest, CoreAdminHandlerTest, TestIndexingPerformance, DocValuesMultiTest, TestWriterPerf, TestFunctionQuery, PolyFieldTest, ZkControllerTest, ClusterStateUpdateTest, TestShardHandlerFactory, TestReload, PreAnalyzedFieldTest, FileBasedSpellCheckerTest, TestDistributedSearch, TestSweetSpotSimilarityFactory, IndexBasedSpellCheckerTest, TestFiltering, TestCollationField, TestDynamicFieldResource, MoreLikeThisHandlerTest, SuggesterTest, ResourceLoaderTest, DirectUpdateHandlerOptimizeTest, CachingDirectoryFactoryTest, TestRandomFaceting, ClusterStateTest, TestFieldTypeResource, SuggesterWFSTTest, TestDefaultSearchFieldResource, OpenExchangeRatesOrgProviderTest, LeaderElectionTest, TestFieldCollectionResource, TestAnalyzedSuggestions, JsonLoaderTest, TestPseudoReturnFields, UpdateParamsTest, TestReversedWildcardFilterFactory, TestDistributedGrouping, TestConfig, SolrTestCaseJ4Test, UnloadDistributedZkTest, AlternateDirectoryTest, DirectUpdateHandlerTest, ShardSplitTest, TestAddFieldRealTimeGet, IndexReaderFactoryTest, TestOmitPositions, RAMDirectoryFactoryTest, TestJmxMonitoredMap, LukeRequestHandlerTest, LeaderElectionIntegrationTest, DocumentAnalysisRequestHandlerTest, TestLuceneMatchVersion, TestValueSourceCache, QueryResultKeyTest, HardAutoCommitTest, SolrRequestParserTest, TestSolrQueryParserDefaultOperatorResource, URLClassifyProcessorTest, MultiTermTest, LoggingHandlerTest, DateFieldTest, CopyFieldTest, MBeansHandlerTest, DefaultValueUpdateProcessorTest, TermsComponentTest, ChaosMonkeyNothingIsSafeTest, SpellCheckCollatorTest, PingRequestHandlerTest, SpellingQueryConverterTest, TestMergePolicyConfig, SystemInfoHandlerTest, SampleTest, TestSolr4Spatial, ZkSolrClientTest, TestSchemaResource, TestGroupingSearch, BadComponentTest, TestSearchPerf, BadCopyFieldTest, TestCloudManagedSchemaAddField, BasicDistributedZkTest, ChaosMonkeySafeLeaderTest]
[junit4:junit4] Completed in 171.61s, 1 test, 1 failure <<< FAILURES!

[...truncated 450 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:386: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:366: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build.xml:181: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/common-build.xml:437: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:1243: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:887: There were test failures: 297 suites, 1250 tests, 1 error, 1 failure, 18 ignored (6 assumptions)

Total time: 101 minutes 30 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message