lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Apache Jenkins Server <jenk...@builds.apache.org>
Subject [JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1683 - Failure
Date Wed, 05 Jun 2013 14:54:24 GMT
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1683/

1 tests failed.
REGRESSION:  org.apache.solr.cloud.ShardSplitTest.testDistribSearch

Error Message:
Server at http://127.0.0.1:16982/kq_ 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:16982/kq_ returned non ok status:500, message:Server Error
	at __randomizedtesting.SeedInfo.seed([1672CDEA881E2C1E:979443F2FF414C22]: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:815)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:616)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at java.lang.Thread.run(Thread.java:679)




Build Log:
[...truncated 9577 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4]   2> 1826875 T4741 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /kq_/
[junit4:junit4]   2> 1826880 T4741 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./solrtest-ShardSplitTest-1370443823108
[junit4:junit4]   2> 1826882 T4741 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 1826883 T4742 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 1826984 T4741 oasc.ZkTestServer.run start zk server on port:31085
[junit4:junit4]   2> 1826985 T4741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1826991 T4748 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@66118c42 name:ZooKeeperConnection Watcher:127.0.0.1:31085 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1826991 T4741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1826992 T4741 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 1826997 T4741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1827012 T4750 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2a4017c9 name:ZooKeeperConnection Watcher:127.0.0.1:31085/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1827013 T4741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1827013 T4741 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 1827019 T4741 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 1827022 T4741 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 1827024 T4741 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 1827027 T4741 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 1827027 T4741 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 1827043 T4741 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 1827044 T4741 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 1827172 T4741 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 1827173 T4741 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 1827176 T4741 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 1827177 T4741 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 1827180 T4741 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 1827180 T4741 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 1827184 T4741 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 1827184 T4741 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 1827187 T4741 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 1827188 T4741 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 1827191 T4741 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 1827192 T4741 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 1827195 T4741 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 1827196 T4741 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 1827494 T4741 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1827499 T4741 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:57328
[junit4:junit4]   2> 1827500 T4741 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1827501 T4741 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1827501 T4741 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370443823426
[junit4:junit4]   2> 1827502 T4741 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370443823426/solr.xml
[junit4:junit4]   2> 1827502 T4741 oasc.CoreContainer.<init> New CoreContainer 775403385
[junit4:junit4]   2> 1827503 T4741 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370443823426/'
[junit4:junit4]   2> 1827504 T4741 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370443823426/'
[junit4:junit4]   2> 1827629 T4741 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 1827629 T4741 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1827630 T4741 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 1827631 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1827631 T4741 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1827631 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1827632 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1827632 T4741 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1827633 T4741 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1827633 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 1827656 T4741 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1827657 T4741 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:31085/solr
[junit4:junit4]   2> 1827657 T4741 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1827658 T4741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1827661 T4761 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@173f7447 name:ZooKeeperConnection Watcher:127.0.0.1:31085 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1827662 T4741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1827664 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1827676 T4741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1827679 T4763 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@52444c1 name:ZooKeeperConnection Watcher:127.0.0.1:31085/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1827679 T4741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1827681 T4741 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 1827685 T4741 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 1827694 T4741 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 1827697 T4741 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57328_kq_
[junit4:junit4]   2> 1827698 T4741 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57328_kq_
[junit4:junit4]   2> 1827701 T4741 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 1827719 T4741 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 1827723 T4741 oasc.Overseer.start Overseer (id=89813406391795715-127.0.0.1:57328_kq_-n_0000000000) starting
[junit4:junit4]   2> 1827736 T4741 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 1827748 T4765 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 1827748 T4741 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 1827751 T4741 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 1827753 T4741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1827756 T4764 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 1827760 T4766 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370443823426/collection1
[junit4:junit4]   2> 1827760 T4766 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 1827761 T4766 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 1827761 T4766 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 1827763 T4766 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370443823426/collection1/'
[junit4:junit4]   2> 1827765 T4766 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-controljetty-1370443823426/collection1/lib/README' to classloader
[junit4:junit4]   2> 1827765 T4766 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-controljetty-1370443823426/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 1827831 T4766 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 1827895 T4766 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1827996 T4766 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1828012 T4766 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 1828633 T4766 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1828637 T4766 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1828640 T4766 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1828646 T4766 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1828670 T4766 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1828670 T4766 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370443823426/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370443823108/control/data/
[junit4:junit4]   2> 1828671 T4766 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@43a4181c
[junit4:junit4]   2> 1828671 T4766 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1828672 T4766 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370443823108/control/data
[junit4:junit4]   2> 1828672 T4766 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370443823108/control/data/index/
[junit4:junit4]   2> 1828672 T4766 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370443823108/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1828673 T4766 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370443823108/control/data/index
[junit4:junit4]   2> 1828678 T4766 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18e42f0e lockFactory=org.apache.lucene.store.NativeFSLockFactory@5eda2600),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1828678 T4766 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1828681 T4766 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1828681 T4766 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1828682 T4766 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1828683 T4766 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1828683 T4766 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1828683 T4766 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1828684 T4766 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1828684 T4766 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1828685 T4766 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1828700 T4766 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1828708 T4766 oass.SolrIndexSearcher.<init> Opening Searcher@6912bbd1 main
[junit4:junit4]   2> 1828709 T4766 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370443823108/control/data/tlog
[junit4:junit4]   2> 1828710 T4766 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1828710 T4766 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1828714 T4767 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6912bbd1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1828715 T4766 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1828716 T4766 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1829259 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1829260 T4764 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"1",
[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:57328_kq_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57328/kq_"}
[junit4:junit4]   2> 1829260 T4764 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 1829261 T4764 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 1829275 T4763 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> 1829719 T4766 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 1829719 T4766 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57328/kq_ collection:control_collection shard:shard1
[junit4:junit4]   2> 1829720 T4766 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 1829812 T4766 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 1829821 T4766 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 1829822 T4766 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 1829822 T4766 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:57328/kq_/collection1/
[junit4:junit4]   2> 1829822 T4766 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 1829823 T4766 oasc.SyncStrategy.syncToMe http://127.0.0.1:57328/kq_/collection1/ has no replicas
[junit4:junit4]   2> 1829823 T4766 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:57328/kq_/collection1/
[junit4:junit4]   2> 1829823 T4766 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 1830779 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1830808 T4763 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> 1830857 T4766 oasc.ZkController.register We are http://127.0.0.1:57328/kq_/collection1/ and leader is http://127.0.0.1:57328/kq_/collection1/
[junit4:junit4]   2> 1830857 T4766 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57328/kq_
[junit4:junit4]   2> 1830857 T4766 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 1830858 T4766 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 1830858 T4766 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1830860 T4766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1830861 T4741 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4]   2> 1830862 T4741 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1830863 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1830880 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 1830882 T4741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1830884 T4770 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3525bd40 name:ZooKeeperConnection Watcher:127.0.0.1:31085/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1830885 T4741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1830886 T4741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1830888 T4741 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 1831183 T4741 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1831188 T4741 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:16982
[junit4:junit4]   2> 1831188 T4741 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1831189 T4741 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1831189 T4741 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370443827116
[junit4:junit4]   2> 1831190 T4741 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370443827116/solr.xml
[junit4:junit4]   2> 1831190 T4741 oasc.CoreContainer.<init> New CoreContainer 933775328
[junit4:junit4]   2> 1831191 T4741 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370443827116/'
[junit4:junit4]   2> 1831192 T4741 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370443827116/'
[junit4:junit4]   2> 1831331 T4741 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 1831332 T4741 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1831333 T4741 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 1831333 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1831334 T4741 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1831334 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1831335 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1831335 T4741 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1831336 T4741 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1831336 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 1831352 T4741 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1831353 T4741 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:31085/solr
[junit4:junit4]   2> 1831354 T4741 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1831355 T4741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1831358 T4781 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@21aed890 name:ZooKeeperConnection Watcher:127.0.0.1:31085 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1831359 T4741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1831375 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1831386 T4741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1831389 T4783 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7216958f name:ZooKeeperConnection Watcher:127.0.0.1:31085/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1831389 T4741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1831401 T4741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1832321 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1832322 T4764 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"1",
[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:57328_kq_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57328/kq_"}
[junit4:junit4]   2> 1832338 T4770 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> 1832338 T4783 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> 1832338 T4763 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> 1832404 T4741 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:16982_kq_
[junit4:junit4]   2> 1832406 T4741 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:16982_kq_
[junit4:junit4]   2> 1832409 T4763 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> 1832409 T4770 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 1832409 T4783 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 1832409 T4770 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> 1832410 T4783 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> 1832410 T4763 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 1832423 T4784 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370443827116/collection1
[junit4:junit4]   2> 1832423 T4784 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 1832424 T4784 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 1832424 T4784 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 1832426 T4784 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370443827116/collection1/'
[junit4:junit4]   2> 1832427 T4784 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty1-1370443827116/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 1832428 T4784 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty1-1370443827116/collection1/lib/README' to classloader
[junit4:junit4]   2> 1832483 T4784 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 1832547 T4784 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1832648 T4784 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1832661 T4784 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 1833261 T4784 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1833265 T4784 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1833268 T4784 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1833274 T4784 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1833298 T4784 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1833298 T4784 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370443827116/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty1/
[junit4:junit4]   2> 1833299 T4784 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@43a4181c
[junit4:junit4]   2> 1833299 T4784 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1833300 T4784 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty1
[junit4:junit4]   2> 1833300 T4784 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty1/index/
[junit4:junit4]   2> 1833300 T4784 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1833301 T4784 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty1/index
[junit4:junit4]   2> 1833304 T4784 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5c328df6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ebfd4c6),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1833305 T4784 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1833309 T4784 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1833309 T4784 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1833310 T4784 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1833310 T4784 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1833311 T4784 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1833311 T4784 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1833312 T4784 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1833312 T4784 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1833313 T4784 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1833323 T4784 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1833331 T4784 oass.SolrIndexSearcher.<init> Opening Searcher@344495bb main
[junit4:junit4]   2> 1833331 T4784 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty1/tlog
[junit4:junit4]   2> 1833333 T4784 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1833333 T4784 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1833337 T4785 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@344495bb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1833339 T4784 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1833339 T4784 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1833844 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1833845 T4764 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"2",
[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:16982_kq_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:16982/kq_"}
[junit4:junit4]   2> 1833845 T4764 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 1833846 T4764 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 1833860 T4783 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> 1833860 T4770 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> 1833860 T4763 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> 1834342 T4784 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 1834342 T4784 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:16982/kq_ collection:collection1 shard:shard1
[junit4:junit4]   2> 1834343 T4784 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 1834361 T4784 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 1834372 T4784 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 1834372 T4784 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 1834372 T4784 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:16982/kq_/collection1/
[junit4:junit4]   2> 1834373 T4784 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 1834373 T4784 oasc.SyncStrategy.syncToMe http://127.0.0.1:16982/kq_/collection1/ has no replicas
[junit4:junit4]   2> 1834373 T4784 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:16982/kq_/collection1/
[junit4:junit4]   2> 1834373 T4784 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 1835364 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1835392 T4763 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> 1835392 T4770 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> 1835392 T4783 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> 1835408 T4784 oasc.ZkController.register We are http://127.0.0.1:16982/kq_/collection1/ and leader is http://127.0.0.1:16982/kq_/collection1/
[junit4:junit4]   2> 1835408 T4784 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:16982/kq_
[junit4:junit4]   2> 1835408 T4784 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 1835408 T4784 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 1835409 T4784 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1835410 T4784 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1835412 T4741 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4]   2> 1835412 T4741 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1835413 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1835711 T4741 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1835714 T4741 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:33413
[junit4:junit4]   2> 1835715 T4741 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1835716 T4741 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1835716 T4741 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370443831657
[junit4:junit4]   2> 1835717 T4741 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370443831657/solr.xml
[junit4:junit4]   2> 1835717 T4741 oasc.CoreContainer.<init> New CoreContainer 1775058555
[junit4:junit4]   2> 1835718 T4741 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370443831657/'
[junit4:junit4]   2> 1835719 T4741 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370443831657/'
[junit4:junit4]   2> 1835846 T4741 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 1835847 T4741 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1835848 T4741 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 1835848 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1835849 T4741 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1835849 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1835850 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1835850 T4741 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1835851 T4741 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1835851 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 1835870 T4741 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1835872 T4741 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:31085/solr
[junit4:junit4]   2> 1835872 T4741 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1835873 T4741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1835876 T4797 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@131c6b77 name:ZooKeeperConnection Watcher:127.0.0.1:31085 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1835882 T4741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1835884 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1835896 T4741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1835899 T4799 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@411b605b name:ZooKeeperConnection Watcher:127.0.0.1:31085/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1835899 T4741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1835903 T4741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1836903 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1836904 T4764 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"2",
[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:16982_kq_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:16982/kq_"}
[junit4:junit4]   2> 1836906 T4741 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33413_kq_
[junit4:junit4]   2> 1836919 T4741 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:33413_kq_
[junit4:junit4]   2> 1836921 T4799 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> 1836921 T4783 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> 1836921 T4770 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> 1836921 T4763 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> 1836925 T4799 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 1836926 T4783 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 1836926 T4770 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 1836926 T4783 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> 1836926 T4763 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> 1836926 T4770 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> 1836928 T4763 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 1836932 T4800 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370443831657/collection1
[junit4:junit4]   2> 1836932 T4800 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 1836933 T4800 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 1836933 T4800 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 1836935 T4800 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370443831657/collection1/'
[junit4:junit4]   2> 1836937 T4800 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty2-1370443831657/collection1/lib/README' to classloader
[junit4:junit4]   2> 1836937 T4800 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty2-1370443831657/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 1836992 T4800 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 1837062 T4800 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1837163 T4800 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1837176 T4800 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 1837787 T4800 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1837791 T4800 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1837792 T4800 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1837797 T4800 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1837815 T4800 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1837815 T4800 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370443831657/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty2/
[junit4:junit4]   2> 1837815 T4800 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@43a4181c
[junit4:junit4]   2> 1837816 T4800 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1837816 T4800 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty2
[junit4:junit4]   2> 1837816 T4800 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty2/index/
[junit4:junit4]   2> 1837817 T4800 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1837817 T4800 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty2/index
[junit4:junit4]   2> 1837820 T4800 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70869715 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a1967d),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1837821 T4800 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1837823 T4800 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1837823 T4800 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1837824 T4800 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1837824 T4800 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1837824 T4800 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1837825 T4800 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1837825 T4800 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1837825 T4800 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1837826 T4800 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1837832 T4800 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1837839 T4800 oass.SolrIndexSearcher.<init> Opening Searcher@5ed61f91 main
[junit4:junit4]   2> 1837839 T4800 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty2/tlog
[junit4:junit4]   2> 1837840 T4800 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1837840 T4800 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1837844 T4801 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5ed61f91 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1837845 T4800 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1837845 T4800 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1838427 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1838428 T4764 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"3",
[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:33413_kq_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:33413/kq_"}
[junit4:junit4]   2> 1838428 T4764 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 1838428 T4764 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4]   2> 1838432 T4799 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> 1838433 T4763 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> 1838433 T4783 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> 1838433 T4770 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> 1838848 T4800 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 1838848 T4800 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:33413/kq_ collection:collection1 shard:shard2
[junit4:junit4]   2> 1838849 T4800 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 1838866 T4800 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 1838878 T4800 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 1838878 T4800 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 1838879 T4800 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:33413/kq_/collection1/
[junit4:junit4]   2> 1838879 T4800 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 1838879 T4800 oasc.SyncStrategy.syncToMe http://127.0.0.1:33413/kq_/collection1/ has no replicas
[junit4:junit4]   2> 1838880 T4800 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:33413/kq_/collection1/
[junit4:junit4]   2> 1838880 T4800 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 1839936 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1839971 T4799 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> 1839971 T4763 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> 1839971 T4783 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> 1839971 T4770 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> 1840017 T4800 oasc.ZkController.register We are http://127.0.0.1:33413/kq_/collection1/ and leader is http://127.0.0.1:33413/kq_/collection1/
[junit4:junit4]   2> 1840017 T4800 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:33413/kq_
[junit4:junit4]   2> 1840017 T4800 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 1840018 T4800 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 1840018 T4800 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1840024 T4800 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1840025 T4741 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4]   2> 1840026 T4741 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1840027 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1840346 T4741 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1840356 T4741 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:18749
[junit4:junit4]   2> 1840357 T4741 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1840358 T4741 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1840359 T4741 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370443836270
[junit4:junit4]   2> 1840359 T4741 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370443836270/solr.xml
[junit4:junit4]   2> 1840360 T4741 oasc.CoreContainer.<init> New CoreContainer 51067620
[junit4:junit4]   2> 1840360 T4741 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370443836270/'
[junit4:junit4]   2> 1840361 T4741 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370443836270/'
[junit4:junit4]   2> 1840494 T4741 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 1840494 T4741 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1840495 T4741 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 1840495 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1840496 T4741 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1840496 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1840497 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1840497 T4741 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1840498 T4741 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1840499 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 1840514 T4741 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1840515 T4741 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:31085/solr
[junit4:junit4]   2> 1840516 T4741 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1840517 T4741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1840520 T4813 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@63e8982d name:ZooKeeperConnection Watcher:127.0.0.1:31085 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1840521 T4741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1840537 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1840547 T4741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1840549 T4815 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2e652d7a name:ZooKeeperConnection Watcher:127.0.0.1:31085/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1840550 T4741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1840561 T4741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1841476 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1841477 T4764 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"3",
[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:33413_kq_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:33413/kq_"}
[junit4:junit4]   2> 1841517 T4799 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> 1841517 T4783 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> 1841517 T4763 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> 1841517 T4815 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> 1841517 T4770 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> 1841564 T4741 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:18749_kq_
[junit4:junit4]   2> 1841566 T4741 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:18749_kq_
[junit4:junit4]   2> 1841569 T4763 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> 1841569 T4815 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> 1841569 T4799 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> 1841569 T4770 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> 1841569 T4783 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1841570 T4783 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> 1841570 T4763 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1841578 T4815 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1841578 T4799 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1841578 T4770 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1841582 T4816 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370443836270/collection1
[junit4:junit4]   2> 1841583 T4816 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 1841583 T4816 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 1841584 T4816 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 1841585 T4816 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370443836270/collection1/'
[junit4:junit4]   2> 1841586 T4816 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty3-1370443836270/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 1841587 T4816 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty3-1370443836270/collection1/lib/README' to classloader
[junit4:junit4]   2> 1841642 T4816 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 1841706 T4816 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1841807 T4816 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1841818 T4816 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 1842441 T4816 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1842445 T4816 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1842448 T4816 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1842453 T4816 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1842475 T4816 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1842475 T4816 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370443836270/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty3/
[junit4:junit4]   2> 1842476 T4816 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@43a4181c
[junit4:junit4]   2> 1842476 T4816 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1842477 T4816 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty3
[junit4:junit4]   2> 1842477 T4816 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty3/index/
[junit4:junit4]   2> 1842477 T4816 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1842478 T4816 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty3/index
[junit4:junit4]   2> 1842482 T4816 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3c2beb97 lockFactory=org.apache.lucene.store.NativeFSLockFactory@39ec6fbc),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1842482 T4816 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1842485 T4816 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1842486 T4816 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1842486 T4816 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1842487 T4816 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1842488 T4816 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1842488 T4816 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1842488 T4816 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1842489 T4816 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1842489 T4816 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1842503 T4816 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1842512 T4816 oass.SolrIndexSearcher.<init> Opening Searcher@ed69115 main
[junit4:junit4]   2> 1842513 T4816 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty3/tlog
[junit4:junit4]   2> 1842514 T4816 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1842514 T4816 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1842519 T4817 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ed69115 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1842521 T4816 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1842521 T4816 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1843025 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1843026 T4764 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"4",
[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:18749_kq_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:18749/kq_"}
[junit4:junit4]   2> 1843026 T4764 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 1843026 T4764 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 1843041 T4770 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> 1843041 T4815 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> 1843041 T4763 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> 1843041 T4783 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> 1843041 T4799 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> 1843560 T4816 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 1843560 T4816 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:18749/kq_ collection:collection1 shard:shard1
[junit4:junit4]   2> 1843563 T4816 oasc.ZkController.register We are http://127.0.0.1:18749/kq_/collection1/ and leader is http://127.0.0.1:16982/kq_/collection1/
[junit4:junit4]   2> 1843564 T4816 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:18749/kq_
[junit4:junit4]   2> 1843564 T4816 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 1843564 T4816 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C2893 name=collection1 org.apache.solr.core.SolrCore@38130f9e url=http://127.0.0.1:18749/kq_/collection1 node=127.0.0.1:18749_kq_ C2893_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:18749_kq_, base_url=http://127.0.0.1:18749/kq_}
[junit4:junit4]   2> 1843565 T4818 C2893 P18749 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 1843565 T4816 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1843566 T4818 C2893 P18749 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 1843567 T4818 C2893 P18749 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 1843567 T4818 C2893 P18749 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1843568 T4741 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4]   2> 1843568 T4741 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1843568 T4818 C2893 P18749 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1843569 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1843597 T4773 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 1843879 T4741 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1843883 T4741 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:29762
[junit4:junit4]   2> 1843883 T4741 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1843884 T4741 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1843885 T4741 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370443839821
[junit4:junit4]   2> 1843885 T4741 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370443839821/solr.xml
[junit4:junit4]   2> 1843885 T4741 oasc.CoreContainer.<init> New CoreContainer 1220156668
[junit4:junit4]   2> 1843886 T4741 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370443839821/'
[junit4:junit4]   2> 1843887 T4741 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370443839821/'
[junit4:junit4]   2> 1844015 T4741 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 1844016 T4741 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1844016 T4741 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 1844017 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1844017 T4741 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1844018 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1844018 T4741 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1844019 T4741 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1844019 T4741 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1844020 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 1844037 T4741 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1844038 T4741 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:31085/solr
[junit4:junit4]   2> 1844039 T4741 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1844040 T4741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1844043 T4830 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@25ff5d81 name:ZooKeeperConnection Watcher:127.0.0.1:31085 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1844044 T4741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1844056 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1844068 T4741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1844071 T4832 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@542eb69 name:ZooKeeperConnection Watcher:127.0.0.1:31085/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1844071 T4741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1844082 T4741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1844545 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1844546 T4764 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"4",
[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:18749_kq_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:18749/kq_"}
[junit4:junit4]   2> 1844565 T4763 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> 1844565 T4770 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> 1844565 T4799 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> 1844565 T4815 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> 1844565 T4832 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> 1844565 T4783 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> 1845085 T4741 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:29762_kq_
[junit4:junit4]   2> 1845092 T4741 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:29762_kq_
[junit4:junit4]   2> 1845098 T4799 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> 1845098 T4815 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> 1845098 T4832 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> 1845098 T4763 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> 1845098 T4770 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> 1845098 T4783 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1845100 T4799 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1845100 T4783 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> 1845101 T4815 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1845101 T4832 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1845101 T4763 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1845102 T4770 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1845106 T4833 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370443839821/collection1
[junit4:junit4]   2> 1845106 T4833 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 1845107 T4833 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 1845107 T4833 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 1845109 T4833 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370443839821/collection1/'
[junit4:junit4]   2> 1845110 T4833 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty4-1370443839821/collection1/lib/README' to classloader
[junit4:junit4]   2> 1845111 T4833 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty4-1370443839821/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 1845164 T4833 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 1845232 T4833 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1845333 T4833 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1845347 T4833 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 1845599 T4773 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4]   2> 1845599 T4773 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:18749_kq_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2002 
[junit4:junit4]   2> 1845955 T4833 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1845959 T4833 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1845962 T4833 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1845967 T4833 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1845991 T4833 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1845991 T4833 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370443839821/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4/
[junit4:junit4]   2> 1845991 T4833 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@43a4181c
[junit4:junit4]   2> 1845992 T4833 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1845993 T4833 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4
[junit4:junit4]   2> 1845993 T4833 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4/index/
[junit4:junit4]   2> 1845993 T4833 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1845994 T4833 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4/index
[junit4:junit4]   2> 1845998 T4833 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f623076 lockFactory=org.apache.lucene.store.NativeFSLockFactory@edb0921),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1845999 T4833 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1846002 T4833 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1846002 T4833 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1846003 T4833 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1846003 T4833 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1846004 T4833 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1846004 T4833 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1846005 T4833 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1846005 T4833 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1846006 T4833 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1846020 T4833 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1846029 T4833 oass.SolrIndexSearcher.<init> Opening Searcher@38390719 main
[junit4:junit4]   2> 1846029 T4833 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4/tlog
[junit4:junit4]   2> 1846031 T4833 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1846031 T4833 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1846036 T4834 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@38390719 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1846038 T4833 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1846038 T4833 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1846108 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1846109 T4764 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"5",
[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:29762_kq_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:29762/kq_"}
[junit4:junit4]   2> 1846109 T4764 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 1846110 T4764 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4]   2> 1846114 T4763 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> 1846114 T4815 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> 1846114 T4770 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> 1846114 T4799 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> 1846114 T4832 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> 1846114 T4783 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> 1847067 T4833 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 1847067 T4833 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:29762/kq_ collection:collection1 shard:shard2
[junit4:junit4]   2> 1847070 T4833 oasc.ZkController.register We are http://127.0.0.1:29762/kq_/collection1/ and leader is http://127.0.0.1:33413/kq_/collection1/
[junit4:junit4]   2> 1847071 T4833 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:29762/kq_
[junit4:junit4]   2> 1847071 T4833 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 1847072 T4833 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C2894 name=collection1 org.apache.solr.core.SolrCore@44186d60 url=http://127.0.0.1:29762/kq_/collection1 node=127.0.0.1:29762_kq_ C2894_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:29762_kq_, base_url=http://127.0.0.1:29762/kq_}
[junit4:junit4]   2> 1847072 T4835 C2894 P29762 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 1847073 T4833 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1847074 T4835 C2894 P29762 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 1847074 T4835 C2894 P29762 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 1847075 T4835 C2894 P29762 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1847075 T4741 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4]   2> 1847076 T4741 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1847076 T4835 C2894 P29762 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1847076 T4741 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1847099 T4741 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1847100 T4789 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 1847100 T4741 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4]   2> 1847101 T4741 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4]   2> 1847102 T4741 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> ASYNC  NEW_CORE C2895 name=collection1 org.apache.solr.core.SolrCore@38130f9e url=http://127.0.0.1:18749/kq_/collection1 node=127.0.0.1:18749_kq_ C2895_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:18749_kq_, base_url=http://127.0.0.1:18749/kq_}
[junit4:junit4]   2> 1847601 T4818 C2895 P18749 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:16982/kq_/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 1847601 T4818 C2895 P18749 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18749/kq_ START replicas=[http://127.0.0.1:16982/kq_/collection1/] nUpdates=100
[junit4:junit4]   2> 1847602 T4818 C2895 P18749 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 1847602 T4818 C2895 P18749 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 1847602 T4818 C2895 P18749 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 1847603 T4818 C2895 P18749 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 1847603 T4818 C2895 P18749 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 1847603 T4818 C2895 P18749 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:16982/kq_/collection1/. core=collection1
[junit4:junit4]   2> 1847603 T4818 C2895 P18749 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C2896 name=collection1 org.apache.solr.core.SolrCore@4417ff34 url=http://127.0.0.1:16982/kq_/collection1 node=127.0.0.1:16982_kq_ C2896_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:16982_kq_, base_url=http://127.0.0.1:16982/kq_, leader=true}
[junit4:junit4]   2> 1847614 T4774 C2896 P16982 oasc.SolrCore.execute [collection1] webapp=/kq_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=2 
[junit4:junit4]   2> 1847618 T4775 C2896 P16982 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 1847618 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1847619 T4764 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"5",
[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:29762_kq_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:29762/kq_"}
[junit4:junit4]   2> 1847620 T4775 C2896 P16982 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5c328df6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ebfd4c6),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1847621 T4775 C2896 P16982 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1847621 T4775 C2896 P16982 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5c328df6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ebfd4c6),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5c328df6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ebfd4c6),segFN=segments_2,generation=2}
[junit4:junit4]   2> 1847622 T4775 C2896 P16982 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 1847622 T4775 C2896 P16982 oass.SolrIndexSearcher.<init> Opening Searcher@180647d1 realtime
[junit4:junit4]   2> 1847623 T4775 C2896 P16982 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1847623 T4775 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4]   2> 1847624 T4818 C2895 P18749 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 1847624 T4818 C2895 P18749 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 1847626 T4783 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> 1847626 T4770 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> 1847627 T4776 C2896 P16982 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 1847626 T4763 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> 1847626 T4799 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> 1847627 T4776 C2896 P16982 oasc.SolrCore.execute [collection1] webapp=/kq_ path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   2> 1847626 T4832 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> 1847626 T4815 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> 1847629 T4818 C2895 P18749 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 1847629 T4818 C2895 P18749 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 1847629 T4818 C2895 P18749 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 1847631 T4776 C2896 P16982 oasc.SolrCore.execute [collection1] webapp=/kq_ path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0 
[junit4:junit4]   2> 1847632 T4818 C2895 P18749 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 1847632 T4818 C2895 P18749 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty3/index.20130605145043859
[junit4:junit4]   2> 1847633 T4818 C2895 P18749 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@548a22 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1305cfbb) fullCopy=false
[junit4:junit4]   2> 1847635 T4776 C2896 P16982 oasc.SolrCore.execute [collection1] webapp=/kq_ path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 1847636 T4818 C2895 P18749 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 1847637 T4818 C2895 P18749 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 1847637 T4818 C2895 P18749 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 1847640 T4818 C2895 P18749 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3c2beb97 lockFactory=org.apache.lucene.store.NativeFSLockFactory@39ec6fbc),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3c2beb97 lockFactory=org.apache.lucene.store.NativeFSLockFactory@39ec6fbc),segFN=segments_2,generation=2}
[junit4:junit4]   2> 1847640 T4818 C2895 P18749 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 1847640 T4818 C2895 P18749 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 1847641 T4818 C2895 P18749 oass.SolrIndexSearcher.<init> Opening Searcher@44866545 main
[junit4:junit4]   2> 1847642 T4817 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@44866545 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1847642 T4818 C2895 P18749 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty3/index.20130605145043859 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty3/index.20130605145043859;done=true>>]
[junit4:junit4]   2> 1847643 T4818 C2895 P18749 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty3/index.20130605145043859
[junit4:junit4]   2> 1847643 T4818 C2895 P18749 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty3/index.20130605145043859
[junit4:junit4]   2> 1847643 T4818 C2895 P18749 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 1847643 T4818 C2895 P18749 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 1847644 T4818 C2895 P18749 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 1847644 T4818 C2895 P18749 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1847646 T4818 C2895 P18749 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 1848101 T4789 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4]   2> 1848101 T4789 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:29762_kq_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001 
[junit4:junit4]   2> 1848103 T4741 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1849106 T4741 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1849138 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1849139 T4764 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"4",
[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:18749_kq_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:18749/kq_"}
[junit4:junit4]   2> 1849157 T4799 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> 1849158 T4832 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> 1849157 T4770 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> 1849157 T4763 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> 1849157 T4783 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> 1849157 T4815 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>  C2894_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:29762_kq_, base_url=http://127.0.0.1:29762/kq_}
[junit4:junit4]   2> 1850103 T4835 C2894 P29762 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:33413/kq_/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 1850103 T4835 C2894 P29762 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:29762/kq_ START replicas=[http://127.0.0.1:33413/kq_/collection1/] nUpdates=100
[junit4:junit4]   2> 1850104 T4835 C2894 P29762 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 1850104 T4835 C2894 P29762 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 1850104 T4835 C2894 P29762 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 1850104 T4835 C2894 P29762 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 1850105 T4835 C2894 P29762 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 1850105 T4835 C2894 P29762 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:33413/kq_/collection1/. core=collection1
[junit4:junit4]   2> 1850105 T4835 C2894 P29762 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1850110 T4741 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> ASYNC  NEW_CORE C2897 name=collection1 org.apache.solr.core.SolrCore@44b14e5f url=http://127.0.0.1:33413/kq_/collection1 node=127.0.0.1:33413_kq_ C2897_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:33413_kq_, base_url=http://127.0.0.1:33413/kq_, leader=true}
[junit4:junit4]   2> 1850114 T4790 C2897 P33413 oasc.SolrCore.execute [collection1] webapp=/kq_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1 
[junit4:junit4]   2> 1850118 T4791 C2897 P33413 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 1850120 T4791 C2897 P33413 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70869715 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a1967d),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1850121 T4791 C2897 P33413 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1850121 T4791 C2897 P33413 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70869715 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a1967d),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70869715 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a1967d),segFN=segments_2,generation=2}
[junit4:junit4]   2> 1850122 T4791 C2897 P33413 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 1850122 T4791 C2897 P33413 oass.SolrIndexSearcher.<init> Opening Searcher@5d164a01 realtime
[junit4:junit4]   2> 1850123 T4791 C2897 P33413 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1850123 T4791 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4]   2> 1850124 T4835 C2894 P29762 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 1850124 T4835 C2894 P29762 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 1850125 T4792 C2897 P33413 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 1850126 T4792 C2897 P33413 oasc.SolrCore.execute [collection1] webapp=/kq_ path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   2> 1850126 T4835 C2894 P29762 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 1850127 T4835 C2894 P29762 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 1850127 T4835 C2894 P29762 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 1850129 T4792 C2897 P33413 oasc.SolrCore.execute [collection1] webapp=/kq_ path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0 
[junit4:junit4]   2> 1850130 T4835 C2894 P29762 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 1850131 T4835 C2894 P29762 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4/index.20130605145046357
[junit4:junit4]   2> 1850131 T4835 C2894 P29762 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@886f410 lockFactory=org.apache.lucene.store.NativeFSLockFactory@64411510) fullCopy=false
[junit4:junit4]   2> 1850134 T4792 C2897 P33413 oasc.SolrCore.execute [collection1] webapp=/kq_ path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 1850135 T4835 C2894 P29762 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 1850136 T4835 C2894 P29762 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 1850136 T4835 C2894 P29762 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 1850138 T4835 C2894 P29762 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f623076 lockFactory=org.apache.lucene.store.NativeFSLockFactory@edb0921),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f623076 lockFactory=org.apache.lucene.store.NativeFSLockFactory@edb0921),segFN=segments_2,generation=2}
[junit4:junit4]   2> 1850138 T4835 C2894 P29762 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 1850138 T4835 C2894 P29762 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 1850139 T4835 C2894 P29762 oass.SolrIndexSearcher.<init> Opening Searcher@1317002 main
[junit4:junit4]   2> 1850140 T4834 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1317002 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1850140 T4835 C2894 P29762 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4/index.20130605145046357 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4/index.20130605145046357;done=true>>]
[junit4:junit4]   2> 1850141 T4835 C2894 P29762 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4/index.20130605145046357
[junit4:junit4]   2> 1850141 T4835 C2894 P29762 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4/index.20130605145046357
[junit4:junit4]   2> 1850141 T4835 C2894 P29762 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 1850141 T4835 C2894 P29762 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 1850141 T4835 C2894 P29762 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 1850142 T4835 C2894 P29762 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1850151 T4835 C2894 P29762 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 1850662 T4764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1850663 T4764 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"5",
[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:29762_kq_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:29762/kq_"}
[junit4:junit4]   2> 1850680 T4763 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> 1850681 T4770 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> 1850680 T4799 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> 1850680 T4815 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> 1850680 T4783 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> 1850680 T4832 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> 1851112 T4741 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1851114 T4741 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4]   2> ASYNC  NEW_CORE C2898 name=collection1 org.apache.solr.core.SolrCore@472c1ab0 url=http://127.0.0.1:57328/kq_/collection1 node=127.0.0.1:57328_kq_ C2898_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:57328_kq_, base_url=http://127.0.0.1:57328/kq_, leader=true}
[junit4:junit4]   2> 1851123 T4753 C2898 P57328 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 1851127 T4753 C2898 P57328 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18e42f0e lockFactory=org.apache.lucene.store.NativeFSLockFactory@5eda2600),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1851127 T4753 C2898 P57328 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1851129 T4753 C2898 P57328 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18e42f0e lockFactory=org.apache.lucene.store.NativeFSLockFactory@5eda2600),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18e42f0e lockFactory=org.apache.lucene.store.NativeFSLockFactory@5eda2600),segFN=segments_2,generation=2}
[junit4:junit4]   2> 1851129 T4753 C2898 P57328 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 1851130 T4753 C2898 P57328 oass.SolrIndexSearcher.<init> Opening Searcher@127cd3fc main
[junit4:junit4]   2> 1851130 T4753 C2898 P57328 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1851131 T4767 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@127cd3fc main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1851132 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4]   2> 1851142 T4777 C2896 P16982 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 1851144 T4777 C2896 P16982 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5c328df6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ebfd4c6),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5c328df6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ebfd4c6),segFN=segments_3,generation=3}
[junit4:junit4]   2> 1851144 T4777 C2896 P16982 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 1851145 T4777 C2896 P16982 oass.SolrIndexSearcher.<init> Opening Searcher@63b34c11 main
[junit4:junit4]   2> 1851145 T4777 C2896 P16982 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1851146 T4785 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@63b34c11 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1851147 T4777 C2896 P16982 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:18749/kq_/collection1/, StdNode: http://127.0.0.1:33413/kq_/collection1/, StdNode: http://127.0.0.1:29762/kq_/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4]   2> 1851150 T4793 C2897 P33413 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 1851151 T4793 C2897 P33413 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70869715 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a1967d),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70869715 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a1967d),segFN=segments_3,generation=3}
[junit4:junit4]   2> 1851152 T4793 C2897 P33413 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 1851152 T4793 C2897 P33413 oass.SolrIndexSearcher.<init> Opening Searcher@3644fce1 main
[junit4:junit4]   2> 1851153 T4793 C2897 P33413 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1851154 T4801 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3644fce1 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1851154 T4793 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4]   2>  C2895_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:18749_kq_, base_url=http://127.0.0.1:18749/kq_}
[junit4:junit4]   2> 1851159 T4805 C2895 P18749 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2>  C2894_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:29762_kq_, base_url=http://127.0.0.1:29762/kq_}
[junit4:junit4]   2> 1851159 T4822 C2894 P29762 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 1851160 T4805 C2895 P18749 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3c2beb97 lockFactory=org.apache.lucene.store.NativeFSLockFactory@39ec6fbc),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3c2beb97 lockFactory=org.apache.lucene.store.NativeFSLockFactory@39ec6fbc),segFN=segments_3,generation=3}
[junit4:junit4]   2> 1851160 T4822 C2894 P29762 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f623076 lockFactory=org.apache.lucene.store.NativeFSLockFactory@edb0921),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f623076 lockFactory=org.apache.lucene.store.NativeFSLockFactory@edb0921),segFN=segments_3,generation=3}
[junit4:junit4]   2> 1851161 T4805 C2895 P18749 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 1851161 T4822 C2894 P29762 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 1851162 T4805 C2895 P18749 oass.SolrIndexSearcher.<init> Opening Searcher@3a652917 main
[junit4:junit4]   2> 1851162 T4822 C2894 P29762 oass.SolrIndexSearcher.<init> Opening Searcher@357345ce main
[junit4:junit4]   2> 1851163 T4805 C2895 P18749 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1851163 T4822 C2894 P29762 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1851164 T4834 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@357345ce main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1851163 T4817 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3a652917 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1851164 T4822 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4]   2> 1851165 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4]   2> 1851165 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 23
[junit4:junit4]   2> 1851166 T4741 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1851169 T4778 C2896 P16982 oasc.SolrCore.execute [collection1] webapp=/kq_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0 
[junit4:junit4]   2> 1851171 T4806 C2895 P18749 oasc.SolrCore.execute [collection1] webapp=/kq_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0 
[junit4:junit4]   2> 1851173 T4794 C2897 P33413 oasc.SolrCore.execute [collection1] webapp=/kq_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1 
[junit4:junit4]   2> 1851174 T4823 C2894 P29762 oasc.SolrCore.execute [collection1] webapp=/kq_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0 
[junit4:junit4]   2> 1853180 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437014529833697280)} 0 2
[junit4:junit4]   2> 1853190 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={update.distrib=FROMLEADER&_version_=-1437014529837891584&update.from=http://127.0.0.1:33413/kq_/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437014529837891584)} 0 2
[junit4:junit4]   2> 1853193 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={update.distrib=FROMLEADER&_version_=-1437014529844183040&update.from=http://127.0.0.1:16982/kq_/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437014529844183040)} 0 1
[junit4:junit4]   2> 1853194 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1437014529844183040)} 0 6
[junit4:junit4]   2> 1853195 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437014529837891584)} 0 13
[junit4:junit4]   2> 1853199 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[a!0 (1437014529854668800)]} 0 1
[junit4:junit4]   2> 1853208 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1437014529860960256)]} 0 1
[junit4:junit4]   2> 1853208 T4793 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!0 (1437014529860960256)]} 0 4
[junit4:junit4]   2> 1853209 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[a!0]} 0 7
[junit4:junit4]   2> 1853213 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[b!1 (1437014529869348864)]} 0 1
[junit4:junit4]   2> 1853222 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1437014529875640320)]} 0 1
[junit4:junit4]   2> 1853222 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!1 (1437014529875640320)]} 0 4
[junit4:junit4]   2> 1853223 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[b!1]} 0 7
[junit4:junit4]   2> 1853226 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[c!2 (1437014529884028928)]} 0 0
[junit4:junit4]   2> 1853233 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1437014529887174656)]} 0 1
[junit4:junit4]   2> 1853233 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[c!2 (1437014529887174656)]} 0 4
[junit4:junit4]   2> 1853236 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[d!3 (1437014529894514688)]} 0 0
[junit4:junit4]   2> 1853242 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1437014529897660416)]} 0 0
[junit4:junit4]   2> 1853243 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[d!3 (1437014529897660416)]} 0 4
[junit4:junit4]   2> 1853246 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[e!4 (1437014529905000448)]} 0 0
[junit4:junit4]   2> 1853254 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1437014529910243328)]} 0 0
[junit4:junit4]   2> 1853255 T4793 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!4 (1437014529910243328)]} 0 4
[junit4:junit4]   2> 1853256 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[e!4]} 0 7
[junit4:junit4]   2> 1853259 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[f!5 (1437014529918631936)]} 0 0
[junit4:junit4]   2> 1853267 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1437014529923874816)]} 0 0
[junit4:junit4]   2> 1853268 T4793 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1437014529923874816)]} 0 4
[junit4:junit4]   2> 1853269 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[f!5]} 0 7
[junit4:junit4]   2> 1853272 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[g!6 (1437014529932263424)]} 0 0
[junit4:junit4]   2> 1853280 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1437014529937506304)]} 0 0
[junit4:junit4]   2> 1853281 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!6 (1437014529937506304)]} 0 4
[junit4:junit4]   2> 1853282 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[g!6]} 0 7
[junit4:junit4]   2> 1853286 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[h!7 (1437014529945894912)]} 0 1
[junit4:junit4]   2> 1853291 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1437014529949040640)]} 0 0
[junit4:junit4]   2> 1853292 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[h!7 (1437014529949040640)]} 0 4
[junit4:junit4]   2> 1853295 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[i!8 (1437014529956380672)]} 0 0
[junit4:junit4]   2> 1853301 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1437014529959526400)]} 0 0
[junit4:junit4]   2> 1853302 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[i!8 (1437014529959526400)]} 0 4
[junit4:junit4]   2> 1853305 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[j!9 (1437014529966866432)]} 0 0
[junit4:junit4]   2> 1853313 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1437014529972109312)]} 0 0
[junit4:junit4]   2> 1853314 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!9 (1437014529972109312)]} 0 4
[junit4:junit4]   2> 1853315 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[j!9]} 0 7
[junit4:junit4]   2> 1853318 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[k!10 (1437014529980497920)]} 0 0
[junit4:junit4]   2> 1853323 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1437014529983643648)]} 0 0
[junit4:junit4]   2> 1853324 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[k!10 (1437014529983643648)]} 0 3
[junit4:junit4]   2> 1853327 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[l!11 (1437014529989935104)]} 0 0
[junit4:junit4]   2> 1853336 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1437014529995177984)]} 0 1
[junit4:junit4]   2> 1853337 T4793 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!11 (1437014529995177984)]} 0 5
[junit4:junit4]   2> 1853337 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[l!11]} 0 7
[junit4:junit4]   2> 1853340 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[m!12 (1437014530003566592)]} 0 0
[junit4:junit4]   2> 1853346 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1437014530006712320)]} 0 0
[junit4:junit4]   2> 1853347 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[m!12 (1437014530006712320)]} 0 4
[junit4:junit4]   2> 1853350 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[n!13 (1437014530014052352)]} 0 0
[junit4:junit4]   2> 1853356 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1437014530017198080)]} 0 0
[junit4:junit4]   2> 1853357 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[n!13 (1437014530017198080)]} 0 4
[junit4:junit4]   2> 1853360 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[o!14 (1437014530024538112)]} 0 0
[junit4:junit4]   2> 1853368 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1437014530028732416)]} 0 1
[junit4:junit4]   2> 1853368 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[o!14 (1437014530028732416)]} 0 4
[junit4:junit4]   2> 1853372 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[p!15 (1437014530036072448)]} 0 1
[junit4:junit4]   2> 1853378 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1437014530040266752)]} 0 0
[junit4:junit4]   2> 1853379 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[p!15 (1437014530040266752)]} 0 4
[junit4:junit4]   2> 1853382 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[q!16 (1437014530047606784)]} 0 0
[junit4:junit4]   2> 1853390 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1437014530052849664)]} 0 0
[junit4:junit4]   2> 1853391 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1437014530052849664)]} 0 4
[junit4:junit4]   2> 1853392 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[q!16]} 0 7
[junit4:junit4]   2> 1853395 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[r!17 (1437014530061238272)]} 0 0
[junit4:junit4]   2> 1853400 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1437014530064384000)]} 0 0
[junit4:junit4]   2> 1853401 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[r!17 (1437014530064384000)]} 0 3
[junit4:junit4]   2> 1853405 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[s!18 (1437014530070675456)]} 0 1
[junit4:junit4]   2> 1853411 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1437014530073821184)]} 0 1
[junit4:junit4]   2> 1853412 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[s!18 (1437014530073821184)]} 0 5
[junit4:junit4]   2> 1853414 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[t!19 (1437014530081161216)]} 0 0
[junit4:junit4]   2> 1853423 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1437014530086404096)]} 0 1
[junit4:junit4]   2> 1853423 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!19 (1437014530086404096)]} 0 4
[junit4:junit4]   2> 1853424 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[t!19]} 0 7
[junit4:junit4]   2> 1853428 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[u!20 (1437014530094792704)]} 0 1
[junit4:junit4]   2> 1853435 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1437014530100035584)]} 0 0
[junit4:junit4]   2> 1853436 T4793 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!20 (1437014530100035584)]} 0 4
[junit4:junit4]   2> 1853437 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[u!20]} 0 7
[junit4:junit4]   2> 1853440 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[v!21 (1437014530108424192)]} 0 0
[junit4:junit4]   2> 1853447 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1437014530111569920)]} 0 1
[junit4:junit4]   2> 1853448 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[v!21 (1437014530111569920)]} 0 5
[junit4:junit4]   2> 1853450 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[w!22 (1437014530118909952)]} 0 0
[junit4:junit4]   2> 1853456 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1437014530122055680)]} 0 0
[junit4:junit4]   2> 1853457 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[w!22 (1437014530122055680)]} 0 4
[junit4:junit4]   2> 1853460 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[x!23 (1437014530129395712)]} 0 0
[junit4:junit4]   2> 1853468 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1437014530134638592)]} 0 0
[junit4:junit4]   2> 1853469 T4793 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!23 (1437014530134638592)]} 0 4
[junit4:junit4]   2> 1853470 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[x!23]} 0 7
[junit4:junit4]   2> 1853474 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[y!24 (1437014530143027200)]} 0 1
[junit4:junit4]   2> 1853481 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1437014530147221504)]} 0 1
[junit4:junit4]   2> 1853481 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[y!24 (1437014530147221504)]} 0 4
[junit4:junit4]   2> 1853485 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[z!25 (1437014530154561536)]} 0 1
[junit4:junit4]   2> 1853492 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1437014530159804416)]} 0 0
[junit4:junit4]   2> 1853493 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!25 (1437014530159804416)]} 0 4
[junit4:junit4]   2> 1853494 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[z!25]} 0 7
[junit4:junit4]   2> 1853498 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[a!26 (1437014530168193024)]} 0 1
[junit4:junit4]   2> 1853504 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1437014530172387328)]} 0 1
[junit4:junit4]   2> 1853504 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[a!26 (1437014530172387328)]} 0 3
[junit4:junit4]   2> 1853507 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[b!27 (1437014530178678784)]} 0 0
[junit4:junit4]   2> 1853515 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1437014530183921664)]} 0 0
[junit4:junit4]   2> 1853516 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!27 (1437014530183921664)]} 0 4
[junit4:junit4]   2> 1853517 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[b!27]} 0 7
[junit4:junit4]   2> 1853519 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[c!28 (1437014530191261696)]} 0 0
[junit4:junit4]   2> 1853527 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1437014530196504576)]} 0 0
[junit4:junit4]   2> 1853528 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!28 (1437014530196504576)]} 0 4
[junit4:junit4]   2> 1853529 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[c!28]} 0 7
[junit4:junit4]   2> 1853533 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[d!29 (1437014530204893184)]} 0 0
[junit4:junit4]   2> 1853541 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1437014530210136064)]} 0 1
[junit4:junit4]   2> 1853542 T4793 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1437014530210136064)]} 0 5
[junit4:junit4]   2> 1853542 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[d!29]} 0 7
[junit4:junit4]   2> 1853546 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[e!30 (1437014530218524672)]} 0 1
[junit4:junit4]   2> 1853552 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1437014530221670400)]} 0 1
[junit4:junit4]   2> 1853553 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[e!30 (1437014530221670400)]} 0 5
[junit4:junit4]   2> 1853557 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[f!31 (1437014530230059008)]} 0 1
[junit4:junit4]   2> 1853564 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1437014530235301888)]} 0 0
[junit4:junit4]   2> 1853565 T4793 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1437014530235301888)]} 0 4
[junit4:junit4]   2> 1853566 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[f!31]} 0 7
[junit4:junit4]   2> 1853568 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[g!32 (1437014530242641920)]} 0 0
[junit4:junit4]   2> 1853574 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1437014530245787648)]} 0 1
[junit4:junit4]   2> 1853575 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[g!32 (1437014530245787648)]} 0 4
[junit4:junit4]   2> 1853578 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[h!33 (1437014530252079104)]} 0 1
[junit4:junit4]   2> 1853583 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1437014530255224832)]} 0 0
[junit4:junit4]   2> 1853584 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[h!33 (1437014530255224832)]} 0 4
[junit4:junit4]   2> 1853588 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[i!34 (1437014530262564864)]} 0 1
[junit4:junit4]   2> 1853594 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1437014530266759168)]} 0 0
[junit4:junit4]   2> 1853595 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[i!34 (1437014530266759168)]} 0 4
[junit4:junit4]   2> 1853599 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[j!35 (1437014530274099200)]} 0 1
[junit4:junit4]   2> 1853606 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1437014530278293504)]} 0 1
[junit4:junit4]   2> 1853606 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[j!35 (1437014530278293504)]} 0 4
[junit4:junit4]   2> 1853609 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[k!36 (1437014530285633536)]} 0 0
[junit4:junit4]   2> 1853618 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1437014530290876416)]} 0 1
[junit4:junit4]   2> 1853619 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[k!36 (1437014530290876416)]} 0 5
[junit4:junit4]   2> 1853623 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[l!37 (1437014530299265024)]} 0 1
[junit4:junit4]   2> 1853630 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1437014530304507904)]} 0 0
[junit4:junit4]   2> 1853631 T4793 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1437014530304507904)]} 0 4
[junit4:junit4]   2> 1853632 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[l!37]} 0 7
[junit4:junit4]   2> 1853635 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[m!38 (1437014530312896512)]} 0 0
[junit4:junit4]   2> 1853642 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1437014530316042240)]} 0 1
[junit4:junit4]   2> 1853642 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[m!38 (1437014530316042240)]} 0 4
[junit4:junit4]   2> 1853645 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[n!39 (1437014530323382272)]} 0 0
[junit4:junit4]   2> 1853652 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1437014530328625152)]} 0 0
[junit4:junit4]   2> 1853653 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!39 (1437014530328625152)]} 0 3
[junit4:junit4]   2> 1853654 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[n!39]} 0 6
[junit4:junit4]   2> 1853656 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[o!40 (1437014530334916608)]} 0 0
[junit4:junit4]   2> 1853662 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1437014530338062336)]} 0 0
[junit4:junit4]   2> 1853663 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[o!40 (1437014530338062336)]} 0 4
[junit4:junit4]   2> 1853667 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[p!41 (1437014530345402368)]} 0 1
[junit4:junit4]   2> 1853676 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1437014530351693824)]} 0 1
[junit4:junit4]   2> 1853676 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!41 (1437014530351693824)]} 0 4
[junit4:junit4]   2> 1853677 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[p!41]} 0 8
[junit4:junit4]   2> 1853681 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[q!42 (1437014530360082432)]} 0 1
[junit4:junit4]   2> 1853686 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1437014530363228160)]} 0 0
[junit4:junit4]   2> 1853687 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[q!42 (1437014530363228160)]} 0 4
[junit4:junit4]   2> 1853690 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[r!43 (1437014530370568192)]} 0 0
[junit4:junit4]   2> 1853697 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1437014530373713920)]} 0 1
[junit4:junit4]   2> 1853698 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[r!43 (1437014530373713920)]} 0 5
[junit4:junit4]   2> 1853700 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[s!44 (1437014530381053952)]} 0 0
[junit4:junit4]   2> 1853706 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1437014530384199680)]} 0 0
[junit4:junit4]   2> 1853707 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[s!44 (1437014530384199680)]} 0 4
[junit4:junit4]   2> 1853710 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[t!45 (1437014530391539712)]} 0 0
[junit4:junit4]   2> 1853717 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1437014530394685440)]} 0 0
[junit4:junit4]   2> 1853718 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[t!45 (1437014530394685440)]} 0 5
[junit4:junit4]   2> 1853722 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[u!46 (1437014530403074048)]} 0 1
[junit4:junit4]   2> 1853727 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1437014530406219776)]} 0 0
[junit4:junit4]   2> 1853728 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[u!46 (1437014530406219776)]} 0 4
[junit4:junit4]   2> 1853732 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[v!47 (1437014530413559808)]} 0 1
[junit4:junit4]   2> 1853738 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1437014530418802688)]} 0 0
[junit4:junit4]   2> 1853739 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!47 (1437014530418802688)]} 0 3
[junit4:junit4]   2> 1853740 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[v!47]} 0 6
[junit4:junit4]   2> 1853743 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[w!48 (1437014530426142720)]} 0 0
[junit4:junit4]   2> 1853751 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1437014530431385600)]} 0 0
[junit4:junit4]   2> 1853752 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!48 (1437014530431385600)]} 0 4
[junit4:junit4]   2> 1853753 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[w!48]} 0 7
[junit4:junit4]   2> 1853756 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[x!49 (1437014530439774208)]} 0 0
[junit4:junit4]   2> 1853761 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1437014530442919936)]} 0 0
[junit4:junit4]   2> 1853762 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[x!49 (1437014530442919936)]} 0 3
[junit4:junit4]   2> 1853765 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[y!50 (1437014530449211392)]} 0 0
[junit4:junit4]   2> 1853772 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1437014530454454272)]} 0 0
[junit4:junit4]   2> 1853773 T4793 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!50 (1437014530454454272)]} 0 3
[junit4:junit4]   2> 1853774 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[y!50]} 0 6
[junit4:junit4]   2> 1853776 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[z!51 (1437014530460745728)]} 0 0
[junit4:junit4]   2> 1853783 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1437014530465988608)]} 0 0
[junit4:junit4]   2> 1853784 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!51 (1437014530465988608)]} 0 3
[junit4:junit4]   2> 1853785 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[z!51]} 0 6
[junit4:junit4]   2> 1853787 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[a!52 (1437014530472280064)]} 0 0
[junit4:junit4]   2> 1853792 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1437014530475425792)]} 0 0
[junit4:junit4]   2> 1853793 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[a!52 (1437014530475425792)]} 0 3
[junit4:junit4]   2> 1853796 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[b!53 (1437014530481717248)]} 0 0
[junit4:junit4]   2> 1853805 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1437014530488008704)]} 0 0
[junit4:junit4]   2> 1853806 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!53 (1437014530488008704)]} 0 4
[junit4:junit4]   2> 1853807 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[b!53]} 0 8
[junit4:junit4]   2> 1853811 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[c!54 (1437014530496397312)]} 0 1
[junit4:junit4]   2> 1853817 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1437014530500591616)]} 0 0
[junit4:junit4]   2> 1853818 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[c!54 (1437014530500591616)]} 0 4
[junit4:junit4]   2> 1853821 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[d!55 (1437014530507931648)]} 0 0
[junit4:junit4]   2> 1853828 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1437014530511077376)]} 0 1
[junit4:junit4]   2> 1853828 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[d!55 (1437014530511077376)]} 0 4
[junit4:junit4]   2> 1853833 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[e!56 (1437014530519465984)]} 0 1
[junit4:junit4]   2> 1853838 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1437014530523660288)]} 0 0
[junit4:junit4]   2> 1853839 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[e!56 (1437014530523660288)]} 0 3
[junit4:junit4]   2> 1853842 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[f!57 (1437014530529951744)]} 0 0
[junit4:junit4]   2> 1853848 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1437014530533097472)]} 0 0
[junit4:junit4]   2> 1853850 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[f!57 (1437014530533097472)]} 0 5
[junit4:junit4]   2> 1853852 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[g!58 (1437014530540437504)]} 0 0
[junit4:junit4]   2> 1853859 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1437014530543583232)]} 0 1
[junit4:junit4]   2> 1853859 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[g!58 (1437014530543583232)]} 0 4
[junit4:junit4]   2> 1853862 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[h!59 (1437014530550923264)]} 0 0
[junit4:junit4]   2> 1853867 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1437014530554068992)]} 0 0
[junit4:junit4]   2> 1853868 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[h!59 (1437014530554068992)]} 0 3
[junit4:junit4]   2> 1853871 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[i!60 (1437014530560360448)]} 0 0
[junit4:junit4]   2> 1853880 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1437014530563506176)]} 0 1
[junit4:junit4]   2> 1853881 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[i!60 (1437014530563506176)]} 0 7
[junit4:junit4]   2> 1853883 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[j!61 (1437014530572943360)]} 0 0
[junit4:junit4]   2> 1853888 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1437014530576089088)]} 0 0
[junit4:junit4]   2> 1853889 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[j!61 (1437014530576089088)]} 0 3
[junit4:junit4]   2> 1853892 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[k!62 (1437014530582380544)]} 0 0
[junit4:junit4]   2> 1853898 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!62 (1437014530585526272)]} 0 0
[junit4:junit4]   2> 1853899 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[k!62 (1437014530585526272)]} 0 4
[junit4:junit4]   2> 1853902 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[l!63 (1437014530592866304)]} 0 0
[junit4:junit4]   2> 1853911 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!63 (1437014530598109184)]} 0 1
[junit4:junit4]   2> 1853911 T4793 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!63 (1437014530598109184)]} 0 4
[junit4:junit4]   2> 1853912 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[l!63]} 0 7
[junit4:junit4]   2> 1853916 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[m!64 (1437014530606497792)]} 0 1
[junit4:junit4]   2> 1853921 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!64 (1437014530609643520)]} 0 0
[junit4:junit4]   2> 1853922 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[m!64 (1437014530609643520)]} 0 4
[junit4:junit4]   2> 1853926 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[n!65 (1437014530616983552)]} 0 1
[junit4:junit4]   2> 1853933 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!65 (1437014530622226432)]} 0 0
[junit4:junit4]   2> 1853934 T4779 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!65 (1437014530622226432)]} 0 4
[junit4:junit4]   2> 1853935 T4795 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[n!65]} 0 7
[junit4:junit4]   2> 1853937 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[o!66 (1437014530629566464)]} 0 0
[junit4:junit4]   2> 1853944 T4824 C2894 P29762 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:33413/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!66 (1437014530634809344)]} 0 0
[junit4:junit4]   2> 1853945 T4793 C2897 P33413 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!66 (1437014530634809344)]} 0 3
[junit4:junit4]   2> 1853946 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[o!66]} 0 6
[junit4:junit4]   2> 1853950 T4753 C2898 P57328 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={wt=javabin&version=2} {add=[p!67 (1437014530642149376)]} 0 1
[junit4:junit4]   2> 1853955 T4805 C2895 P18749 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params={distrib.from=http://127.0.0.1:16982/kq_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!67 (1437014530645295104)]} 0 0
[junit4:junit4]   2> 1853956 T4777 C2896 P16982 oasup.LogUpdateProcessor.finish [collection1] webapp=/kq_ path=/update params

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

 MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4]   2> 2052798 T4832 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4/index;done=false>>]
[junit4:junit4]   2> 2052798 T4832 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4/index
[junit4:junit4]   2> 2052799 T4832 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4;done=false>>]
[junit4:junit4]   2> 2052799 T4832 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1370443823108/jetty4
[junit4:junit4]   2> 2052799 T4832 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 2052799 T4832 oasc.LeaderElector$1.process WARN  org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election/89813406391795724-5-n_0000000001
[junit4:junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4]   2> 	at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:152)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:149)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:149)
[junit4:junit4]   2> 	at org.apache.solr.cloud.ElectionContext.cancelElection(ElectionContext.java:63)
[junit4:junit4]   2> 	at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:260)
[junit4:junit4]   2> 	at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4]   2> 	at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[junit4:junit4]   2> 	at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4]   2> 	at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4]   2> 	at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4]   2> 	at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4]   2> 
[junit4:junit4]   2> 2052800 T4832 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> 2052800 T4832 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 2052800 T4832 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 2052801 T4832 oasc.LeaderElector$1.process WARN  org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4]   2> 	at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4]   2> 	at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4]   2> 	at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4]   2> 	at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4]   2> 	at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4]   2> 	at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4]   2> 
[junit4:junit4]   2> NOTE: test params are: codec=Lucene40, sim=DefaultSimilarity, locale=uk_UA, timezone=Etc/Universal
[junit4:junit4]   2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=3,free=224935600,total=419495936
[junit4:junit4]   2> NOTE: All tests run in this JVM: [TestAddFieldRealTimeGet, TestStressReorder, StatsComponentTest, TestCoreDiscovery, ZkNodePropsTest, TestFieldTypeResource, URLClassifyProcessorTest, LeaderElectionIntegrationTest, TestElisionMultitermQuery, TestFiltering, FileUtilsTest, SolrPluginUtilsTest, HighlighterConfigTest, UniqFieldsUpdateProcessorFactoryTest, TestAnalyzedSuggestions, ZkSolrClientTest, SolrCmdDistributorTest, TestUpdate, TestDFRSimilarityFactory, SolrCoreCheckLockOnStartupTest, DateMathParserTest, NotRequiredUniqueKeyTest, TestDynamicFieldResource, DirectUpdateHandlerTest, OpenCloseCoreStressTest, TestOmitPositions, TestSolrXMLSerializer, TestLMJelinekMercerSimilarityFactory, TestSchemaNameResource, MultiTermTest, SpellCheckComponentTest, ConvertedLegacyTest, CurrencyFieldOpenExchangeTest, SpellPossibilityIteratorTest, BadIndexSchemaTest, DefaultValueUpdateProcessorTest, TestFieldResource, TestRandomFaceting, TestJmxMonitoredMap, TestRTGBase, TestFastOutputStream, TestSolrQueryParserResource, TestPostingsSolrHighlighter, JSONWriterTest, TestMultiCoreConfBootstrap, DocValuesMultiTest, TestQueryTypes, TestJmxIntegration, TestDefaultSearchFieldResource, SuggesterWFSTTest, CurrencyFieldXmlFileTest, TestArbitraryIndexDir, TestFoldingMultitermQuery, TestIndexSearcher, DisMaxRequestHandlerTest, PathHierarchyTokenizerFactoryTest, TestMergePolicyConfig, DirectSolrSpellCheckerTest, SpellCheckCollatorTest, FullSolrCloudDistribCmdsTest, TestComponentsName, IndexReaderFactoryTest, XmlUpdateRequestHandlerTest, OpenExchangeRatesOrgProviderTest, HardAutoCommitTest, TestReload, TestDefaultSimilarityFactory, DebugComponentTest, TestUtils, SortByFunctionTest, ChaosMonkeySafeLeaderTest, BasicDistributedZk2Test, UnloadDistributedZkTest, CollectionsAPIDistributedZkTest, ShardRoutingTest, BasicZkTest, ClusterStateUpdateTest, LeaderElectionTest, TestZkChroot, ShardRoutingCustomTest, TestDistributedSearch, TestDistributedGrouping, TestRecovery, TestHashPartitioner, TermVectorComponentDistributedTest, ZkControllerTest, TestRealTimeGet, TestStressVersions, TestRangeQuery, SimpleFacetsTest, TestSolr4Spatial, TestGroupingSearch, TestFunctionQuery, TestLazyCores, HighlighterTest, ShowFileRequestHandlerTest, SimplePostToolTest, SignatureUpdateProcessorFactoryTest, TestExtendedDismaxParser, SuggesterFSTTest, CoreAdminHandlerTest, SolrRequestParserTest, DocValuesTest, SuggesterTSTTest, SuggesterTest, TestStressLucene, SpatialFilterTest, TestCSVLoader, NoCacheHeaderTest, FieldMutatingUpdateProcessorTest, TestWordDelimiterFilterFactory, DirectUpdateHandlerOptimizeTest, TestSolrDeletionPolicy1, IndexBasedSpellCheckerTest, TestQueryUtils, TestReversedWildcardFilterFactory, PrimitiveFieldTypeTest, DocumentBuilderTest, TestIndexingPerformance, RequiredFieldsTest, FastVectorHighlighterTest, LoggingHandlerTest, IndexSchemaTest, ReturnFieldsTest, MBeansHandlerTest, BinaryUpdateRequestHandlerTest, PingRequestHandlerTest, CoreContainerCoreInitFailuresTest, TestLFUCache, TestQuerySenderListener, UpdateParamsTest, CopyFieldTest, SolrIndexConfigTest, SampleTest, TestBinaryField, NumericFieldsTest, MinimalSchemaTest, OutputWriterTest, ExternalFileFieldSortTest, TestLuceneMatchVersion, TestPhraseSuggestions, TestCharFilters, TestCodecSupport, SynonymTokenizerTest, TestXIncludeConfig, EchoParamsTest, TestNumberUtils, TestBM25SimilarityFactory, LegacyHTMLStripCharFilterTest, TestPluginEnable, TimeZoneUtilsTest, ResourceLoaderTest, ChaosMonkeyNothingIsSafeTest, PreAnalyzedFieldTest, TestSystemIdResolver, PrimUtilsTest, TestSuggestSpellingConverter, DateFieldTest, DOMUtilTest, ClusterStateTest, TestSolrJ, TestDocumentBuilder, UUIDFieldTest, CircularListTest, TestCollationKeyRangeQueries, ShardSplitTest]
[junit4:junit4] Completed on J1 in 226.33s, 1 test, 1 error <<< FAILURES!

[...truncated 10 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:386: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:366: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:887: There were test failures: 297 suites, 1244 tests, 1 error, 13 ignored (7 assumptions)

Total time: 54 minutes 11 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message