You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/06/04 21:56:05 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java7 - Build # 1307 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java7/1307/
1 tests failed.
FAILED: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:24465 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:24465 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([F44971097932BC2D:75AFFF110E6DDC11]: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:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9457 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 405558 T1280 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 405565 T1280 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./solrtest-ShardSplitTest-1370374390189
[junit4:junit4] 2> 405567 T1280 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 405568 T1281 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 405669 T1280 oasc.ZkTestServer.run start zk server on port:55300
[junit4:junit4] 2> 405670 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 405675 T1287 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4d6e30b name:ZooKeeperConnection Watcher:127.0.0.1:55300 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 405675 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 405675 T1280 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 405688 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 405690 T1289 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ebdad6e name:ZooKeeperConnection Watcher:127.0.0.1:55300/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 405691 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 405691 T1280 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 405696 T1280 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 405705 T1280 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 405708 T1280 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 405712 T1280 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 405713 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 405725 T1280 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 405726 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 405832 T1280 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 405833 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 405837 T1280 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 405838 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 405841 T1280 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 405842 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 405846 T1280 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 405847 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 405850 T1280 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 405851 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 405855 T1280 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 405856 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 405860 T1280 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 405860 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 406130 T1280 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 406135 T1280 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:42992
[junit4:junit4] 2> 406136 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 406137 T1280 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 406137 T1280 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370374390487
[junit4:junit4] 2> 406138 T1280 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370374390487/solr.xml
[junit4:junit4] 2> 406138 T1280 oasc.CoreContainer.<init> New CoreContainer 770270277
[junit4:junit4] 2> 406139 T1280 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370374390487/'
[junit4:junit4] 2> 406139 T1280 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370374390487/'
[junit4:junit4] 2> 406268 T1280 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 406269 T1280 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 406270 T1280 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 406270 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 406271 T1280 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 406271 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 406272 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 406272 T1280 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 406273 T1280 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 406273 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 406291 T1280 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 406292 T1280 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55300/solr
[junit4:junit4] 2> 406293 T1280 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 406294 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 406333 T1300 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11f4466d name:ZooKeeperConnection Watcher:127.0.0.1:55300 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 406333 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 406336 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 406349 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 406351 T1302 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6bac9911 name:ZooKeeperConnection Watcher:127.0.0.1:55300/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 406352 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 406354 T1280 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 406364 T1280 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 406369 T1280 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 406371 T1280 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42992_
[junit4:junit4] 2> 406373 T1280 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42992_
[junit4:junit4] 2> 406383 T1280 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 406396 T1280 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 406405 T1280 oasc.Overseer.start Overseer (id=89808856035885059-127.0.0.1:42992_-n_0000000000) starting
[junit4:junit4] 2> 406415 T1280 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 406426 T1304 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 406427 T1280 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 406430 T1280 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 406433 T1280 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 406436 T1303 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 406440 T1305 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370374390487/collection1
[junit4:junit4] 2> 406440 T1305 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 406441 T1305 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 406442 T1305 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 406443 T1305 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370374390487/collection1/'
[junit4:junit4] 2> 406445 T1305 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1370374390487/collection1/lib/README' to classloader
[junit4:junit4] 2> 406445 T1305 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1370374390487/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 406498 T1305 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 406558 T1305 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 406661 T1305 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 406667 T1305 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 407251 T1305 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 407255 T1305 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 407257 T1305 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 407263 T1305 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 407294 T1305 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 407294 T1305 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370374390487/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370374390188/control/data/
[junit4:junit4] 2> 407295 T1305 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@17d260f6
[junit4:junit4] 2> 407295 T1305 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 407296 T1305 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370374390188/control/data
[junit4:junit4] 2> 407296 T1305 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370374390188/control/data/index/
[junit4:junit4] 2> 407296 T1305 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370374390188/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 407297 T1305 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370374390188/control/data/index
[junit4:junit4] 2> 407302 T1305 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@355e7536 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65bf0fcb),segFN=segments_1,generation=1}
[junit4:junit4] 2> 407302 T1305 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 407305 T1305 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 407305 T1305 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 407306 T1305 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 407307 T1305 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 407307 T1305 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 407307 T1305 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 407308 T1305 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 407308 T1305 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 407309 T1305 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 407325 T1305 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 407333 T1305 oass.SolrIndexSearcher.<init> Opening Searcher@29f01668 main
[junit4:junit4] 2> 407333 T1305 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370374390188/control/data/tlog
[junit4:junit4] 2> 407335 T1305 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 407335 T1305 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 407338 T1306 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@29f01668 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 407340 T1305 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 407340 T1305 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 407941 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 407942 T1303 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:42992_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42992"}
[junit4:junit4] 2> 407942 T1303 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 407943 T1303 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 407958 T1302 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> 408344 T1305 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 408344 T1305 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42992 collection:control_collection shard:shard1
[junit4:junit4] 2> 408345 T1305 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 408363 T1305 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 408374 T1305 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 408375 T1305 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 408375 T1305 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:42992/collection1/
[junit4:junit4] 2> 408375 T1305 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 408376 T1305 oasc.SyncStrategy.syncToMe http://127.0.0.1:42992/collection1/ has no replicas
[junit4:junit4] 2> 408376 T1305 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:42992/collection1/
[junit4:junit4] 2> 408376 T1305 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 409464 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 409483 T1302 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> 409510 T1305 oasc.ZkController.register We are http://127.0.0.1:42992/collection1/ and leader is http://127.0.0.1:42992/collection1/
[junit4:junit4] 2> 409510 T1305 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42992
[junit4:junit4] 2> 409510 T1305 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 409510 T1305 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 409511 T1305 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 409513 T1305 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 409514 T1280 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 409515 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 409516 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 409531 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 409534 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 409536 T1309 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6903c2ba name:ZooKeeperConnection Watcher:127.0.0.1:55300/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 409536 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 409539 T1280 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 409542 T1280 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 409810 T1280 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 409814 T1280 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:24465
[junit4:junit4] 2> 409814 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 409815 T1280 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 409815 T1280 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370374394164
[junit4:junit4] 2> 409816 T1280 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370374394164/solr.xml
[junit4:junit4] 2> 409817 T1280 oasc.CoreContainer.<init> New CoreContainer 1160651991
[junit4:junit4] 2> 409817 T1280 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370374394164/'
[junit4:junit4] 2> 409818 T1280 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370374394164/'
[junit4:junit4] 2> 409948 T1280 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 409949 T1280 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 409949 T1280 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 409950 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 409950 T1280 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 409951 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 409951 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 409952 T1280 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 409953 T1280 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 409953 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 409969 T1280 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 409970 T1280 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55300/solr
[junit4:junit4] 2> 409970 T1280 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 409972 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 409975 T1320 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d6d9f3d name:ZooKeeperConnection Watcher:127.0.0.1:55300 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 409975 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 409993 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 410004 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 410006 T1322 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@48932da2 name:ZooKeeperConnection Watcher:127.0.0.1:55300/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 410006 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 410016 T1280 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 410992 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 410993 T1303 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:42992_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42992"}
[junit4:junit4] 2> 411011 T1302 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> 411011 T1322 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> 411011 T1309 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> 411021 T1280 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:24465_
[junit4:junit4] 2> 411023 T1280 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:24465_
[junit4:junit4] 2> 411026 T1309 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> 411026 T1322 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> 411026 T1302 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> 411028 T1309 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 411028 T1322 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 411034 T1302 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 411039 T1323 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370374394164/collection1
[junit4:junit4] 2> 411039 T1323 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 411040 T1323 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 411040 T1323 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 411042 T1323 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370374394164/collection1/'
[junit4:junit4] 2> 411044 T1323 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1370374394164/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 411044 T1323 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1370374394164/collection1/lib/README' to classloader
[junit4:junit4] 2> 411097 T1323 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 411158 T1323 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 411260 T1323 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 411266 T1323 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 411848 T1323 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 411852 T1323 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 411855 T1323 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 411860 T1323 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 411891 T1323 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 411891 T1323 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370374394164/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty1/
[junit4:junit4] 2> 411892 T1323 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@17d260f6
[junit4:junit4] 2> 411892 T1323 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 411893 T1323 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty1
[junit4:junit4] 2> 411893 T1323 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty1/index/
[junit4:junit4] 2> 411894 T1323 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 411895 T1323 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty1/index
[junit4:junit4] 2> 411898 T1323 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@742b1274 lockFactory=org.apache.lucene.store.NativeFSLockFactory@719b949e),segFN=segments_1,generation=1}
[junit4:junit4] 2> 411899 T1323 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 411902 T1323 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 411902 T1323 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 411903 T1323 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 411904 T1323 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 411904 T1323 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 411905 T1323 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 411905 T1323 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 411906 T1323 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 411906 T1323 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 411923 T1323 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 411930 T1323 oass.SolrIndexSearcher.<init> Opening Searcher@4a80f58c main
[junit4:junit4] 2> 411931 T1323 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty1/tlog
[junit4:junit4] 2> 411932 T1323 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 411932 T1323 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 411937 T1324 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4a80f58c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 411939 T1323 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 411939 T1323 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 412518 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 412519 T1303 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:24465_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:24465"}
[junit4:junit4] 2> 412519 T1303 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 412520 T1303 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 412555 T1302 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> 412555 T1322 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> 412555 T1309 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> 412942 T1323 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 412942 T1323 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:24465 collection:collection1 shard:shard1
[junit4:junit4] 2> 412943 T1323 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 413047 T1323 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 413050 T1323 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 413051 T1323 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 413051 T1323 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:24465/collection1/
[junit4:junit4] 2> 413051 T1323 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 413052 T1323 oasc.SyncStrategy.syncToMe http://127.0.0.1:24465/collection1/ has no replicas
[junit4:junit4] 2> 413052 T1323 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:24465/collection1/
[junit4:junit4] 2> 413052 T1323 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 414109 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 414131 T1302 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> 414131 T1322 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> 414131 T1309 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> 414170 T1323 oasc.ZkController.register We are http://127.0.0.1:24465/collection1/ and leader is http://127.0.0.1:24465/collection1/
[junit4:junit4] 2> 414170 T1323 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:24465
[junit4:junit4] 2> 414170 T1323 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 414170 T1323 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 414171 T1323 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 414173 T1323 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 414174 T1280 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 414175 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 414175 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 414453 T1280 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 414457 T1280 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:21410
[junit4:junit4] 2> 414458 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 414458 T1280 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 414459 T1280 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370374398813
[junit4:junit4] 2> 414459 T1280 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370374398813/solr.xml
[junit4:junit4] 2> 414460 T1280 oasc.CoreContainer.<init> New CoreContainer 253287704
[junit4:junit4] 2> 414460 T1280 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370374398813/'
[junit4:junit4] 2> 414461 T1280 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370374398813/'
[junit4:junit4] 2> 414589 T1280 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 414590 T1280 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 414590 T1280 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 414591 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 414591 T1280 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 414592 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 414592 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 414593 T1280 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 414594 T1280 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 414594 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 414612 T1280 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 414612 T1280 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55300/solr
[junit4:junit4] 2> 414613 T1280 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 414614 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 414617 T1336 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3bd45c13 name:ZooKeeperConnection Watcher:127.0.0.1:55300 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 414618 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 414632 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 414645 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 414647 T1338 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b95b269 name:ZooKeeperConnection Watcher:127.0.0.1:55300/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 414647 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 414659 T1280 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 415644 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 415645 T1303 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:24465_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:24465"}
[junit4:junit4] 2> 415658 T1338 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> 415659 T1322 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> 415659 T1309 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> 415659 T1302 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> 415663 T1280 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:21410_
[junit4:junit4] 2> 415665 T1280 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:21410_
[junit4:junit4] 2> 415668 T1338 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> 415668 T1322 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> 415668 T1309 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> 415668 T1302 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> 415670 T1338 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 415670 T1322 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 415671 T1309 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 415676 T1302 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 415681 T1339 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370374398813/collection1
[junit4:junit4] 2> 415682 T1339 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 415683 T1339 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 415683 T1339 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 415685 T1339 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370374398813/collection1/'
[junit4:junit4] 2> 415686 T1339 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1370374398813/collection1/lib/README' to classloader
[junit4:junit4] 2> 415687 T1339 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1370374398813/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 415753 T1339 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 415814 T1339 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 415915 T1339 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 415921 T1339 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 416487 T1339 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 416492 T1339 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 416494 T1339 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 416500 T1339 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 416530 T1339 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 416530 T1339 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370374398813/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty2/
[junit4:junit4] 2> 416530 T1339 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@17d260f6
[junit4:junit4] 2> 416531 T1339 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 416532 T1339 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty2
[junit4:junit4] 2> 416532 T1339 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty2/index/
[junit4:junit4] 2> 416532 T1339 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 416533 T1339 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty2/index
[junit4:junit4] 2> 416537 T1339 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2c04f395 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44a07682),segFN=segments_1,generation=1}
[junit4:junit4] 2> 416537 T1339 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 416541 T1339 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 416541 T1339 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 416542 T1339 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 416542 T1339 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 416543 T1339 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 416543 T1339 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 416544 T1339 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 416544 T1339 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 416545 T1339 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 416561 T1339 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 416569 T1339 oass.SolrIndexSearcher.<init> Opening Searcher@22aca7d3 main
[junit4:junit4] 2> 416569 T1339 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty2/tlog
[junit4:junit4] 2> 416570 T1339 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 416571 T1339 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 416575 T1340 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@22aca7d3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 416577 T1339 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 416577 T1339 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 417166 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 417167 T1303 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:21410_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:21410"}
[junit4:junit4] 2> 417167 T1303 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 417167 T1303 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 417173 T1338 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> 417173 T1322 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> 417173 T1302 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> 417173 T1309 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> 417581 T1339 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 417581 T1339 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:21410 collection:collection1 shard:shard2
[junit4:junit4] 2> 417582 T1339 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 417657 T1339 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 417682 T1339 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 417682 T1339 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 417682 T1339 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:21410/collection1/
[junit4:junit4] 2> 417683 T1339 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 417683 T1339 oasc.SyncStrategy.syncToMe http://127.0.0.1:21410/collection1/ has no replicas
[junit4:junit4] 2> 417683 T1339 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:21410/collection1/
[junit4:junit4] 2> 417683 T1339 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 418688 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 418711 T1338 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> 418711 T1309 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> 418711 T1322 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> 418711 T1302 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> 418759 T1339 oasc.ZkController.register We are http://127.0.0.1:21410/collection1/ and leader is http://127.0.0.1:21410/collection1/
[junit4:junit4] 2> 418759 T1339 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:21410
[junit4:junit4] 2> 418759 T1339 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 418759 T1339 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 418760 T1339 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 418762 T1339 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 418763 T1280 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 418764 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 418764 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 419042 T1280 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 419046 T1280 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:61947
[junit4:junit4] 2> 419046 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 419047 T1280 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 419048 T1280 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370374403402
[junit4:junit4] 2> 419048 T1280 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370374403402/solr.xml
[junit4:junit4] 2> 419049 T1280 oasc.CoreContainer.<init> New CoreContainer 944426854
[junit4:junit4] 2> 419049 T1280 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370374403402/'
[junit4:junit4] 2> 419050 T1280 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370374403402/'
[junit4:junit4] 2> 419192 T1280 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 419193 T1280 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 419194 T1280 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 419194 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 419195 T1280 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 419195 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 419196 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 419196 T1280 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 419197 T1280 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 419197 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 419213 T1280 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 419214 T1280 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55300/solr
[junit4:junit4] 2> 419214 T1280 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 419216 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 419219 T1352 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@88c2abf name:ZooKeeperConnection Watcher:127.0.0.1:55300 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 419220 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 419239 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 419250 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 419253 T1354 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3888f686 name:ZooKeeperConnection Watcher:127.0.0.1:55300/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 419253 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 419263 T1280 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 420227 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 420228 T1303 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:21410_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:21410"}
[junit4:junit4] 2> 420244 T1338 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> 420244 T1354 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> 420244 T1322 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> 420244 T1309 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> 420244 T1302 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> 420268 T1280 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:61947_
[junit4:junit4] 2> 420270 T1280 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:61947_
[junit4:junit4] 2> 420273 T1338 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> 420273 T1322 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> 420273 T1354 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> 420273 T1302 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> 420273 T1309 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> 420275 T1338 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 420275 T1322 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 420276 T1302 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 420276 T1309 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 420276 T1354 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 420282 T1355 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370374403402/collection1
[junit4:junit4] 2> 420282 T1355 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 420283 T1355 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 420283 T1355 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 420285 T1355 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370374403402/collection1/'
[junit4:junit4] 2> 420286 T1355 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1370374403402/collection1/lib/README' to classloader
[junit4:junit4] 2> 420287 T1355 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1370374403402/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 420339 T1355 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 420399 T1355 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 420501 T1355 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 420507 T1355 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 421089 T1355 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 421093 T1355 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 421095 T1355 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 421101 T1355 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 421131 T1355 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 421132 T1355 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370374403402/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty3/
[junit4:junit4] 2> 421132 T1355 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@17d260f6
[junit4:junit4] 2> 421133 T1355 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 421133 T1355 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty3
[junit4:junit4] 2> 421134 T1355 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty3/index/
[junit4:junit4] 2> 421134 T1355 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 421135 T1355 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty3/index
[junit4:junit4] 2> 421138 T1355 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7d70fddd lockFactory=org.apache.lucene.store.NativeFSLockFactory@771b6baa),segFN=segments_1,generation=1}
[junit4:junit4] 2> 421139 T1355 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 421142 T1355 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 421142 T1355 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 421143 T1355 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 421144 T1355 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 421145 T1355 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 421145 T1355 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 421145 T1355 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 421146 T1355 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 421146 T1355 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 421163 T1355 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 421170 T1355 oass.SolrIndexSearcher.<init> Opening Searcher@226fd298 main
[junit4:junit4] 2> 421171 T1355 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty3/tlog
[junit4:junit4] 2> 421172 T1355 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 421172 T1355 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 421177 T1356 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@226fd298 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 421179 T1355 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 421179 T1355 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 421751 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 421752 T1303 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:61947_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61947"}
[junit4:junit4] 2> 421752 T1303 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 421752 T1303 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 421767 T1338 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> 421767 T1322 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> 421767 T1354 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> 421767 T1302 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> 421767 T1309 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> 422182 T1355 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 422182 T1355 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:61947 collection:collection1 shard:shard1
[junit4:junit4] 2> 422186 T1355 oasc.ZkController.register We are http://127.0.0.1:61947/collection1/ and leader is http://127.0.0.1:24465/collection1/
[junit4:junit4] 2> 422186 T1355 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:61947
[junit4:junit4] 2> 422186 T1355 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 422187 T1355 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1835 name=collection1 org.apache.solr.core.SolrCore@33932f51 url=http://127.0.0.1:61947/collection1 node=127.0.0.1:61947_ C1835_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:61947_, base_url=http://127.0.0.1:61947}
[junit4:junit4] 2> 422187 T1357 C1835 P61947 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 422188 T1355 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 422188 T1357 C1835 P61947 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 422189 T1357 C1835 P61947 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 422189 T1357 C1835 P61947 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 422190 T1280 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 422190 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 422191 T1357 C1835 P61947 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 422191 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 422215 T1312 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 422485 T1280 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 422488 T1280 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:40320
[junit4:junit4] 2> 422489 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 422489 T1280 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 422490 T1280 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370374406836
[junit4:junit4] 2> 422490 T1280 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370374406836/solr.xml
[junit4:junit4] 2> 422491 T1280 oasc.CoreContainer.<init> New CoreContainer 1463418931
[junit4:junit4] 2> 422491 T1280 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370374406836/'
[junit4:junit4] 2> 422492 T1280 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370374406836/'
[junit4:junit4] 2> 422622 T1280 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 422623 T1280 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 422624 T1280 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 422624 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 422625 T1280 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 422625 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 422626 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 422626 T1280 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 422627 T1280 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 422627 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 422645 T1280 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 422646 T1280 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55300/solr
[junit4:junit4] 2> 422646 T1280 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 422648 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 422719 T1369 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3d2e57cb name:ZooKeeperConnection Watcher:127.0.0.1:55300 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 422720 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 422723 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 422736 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 422738 T1371 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7bae4ee5 name:ZooKeeperConnection Watcher:127.0.0.1:55300/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 422738 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 422757 T1280 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 423273 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 423274 T1303 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:61947_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61947"}
[junit4:junit4] 2> 423290 T1338 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> 423290 T1354 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> 423290 T1322 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> 423290 T1302 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> 423290 T1371 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> 423290 T1309 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> 423762 T1280 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40320_
[junit4:junit4] 2> 423764 T1280 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40320_
[junit4:junit4] 2> 423767 T1338 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> 423767 T1322 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> 423767 T1354 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> 423767 T1302 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> 423767 T1309 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> 423768 T1371 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 423769 T1371 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> 423769 T1338 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 423770 T1322 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 423770 T1354 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 423777 T1302 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 423777 T1309 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 423782 T1372 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370374406836/collection1
[junit4:junit4] 2> 423782 T1372 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 423783 T1372 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 423783 T1372 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 423785 T1372 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370374406836/collection1/'
[junit4:junit4] 2> 423787 T1372 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1370374406836/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 423787 T1372 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1370374406836/collection1/lib/README' to classloader
[junit4:junit4] 2> 423840 T1372 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 423900 T1372 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 424003 T1372 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 424010 T1372 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 424217 T1312 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 424217 T1312 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:61947_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2002
[junit4:junit4] 2> 424588 T1372 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 424593 T1372 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 424595 T1372 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 424601 T1372 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 424631 T1372 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 424631 T1372 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370374406836/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4/
[junit4:junit4] 2> 424631 T1372 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@17d260f6
[junit4:junit4] 2> 424632 T1372 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 424633 T1372 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4
[junit4:junit4] 2> 424633 T1372 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4/index/
[junit4:junit4] 2> 424633 T1372 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 424634 T1372 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4/index
[junit4:junit4] 2> 424637 T1372 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40f6dc1b lockFactory=org.apache.lucene.store.NativeFSLockFactory@158614a0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 424638 T1372 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 424641 T1372 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 424641 T1372 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 424642 T1372 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 424643 T1372 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 424643 T1372 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 424643 T1372 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 424644 T1372 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 424644 T1372 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 424645 T1372 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 424660 T1372 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 424667 T1372 oass.SolrIndexSearcher.<init> Opening Searcher@291590b1 main
[junit4:junit4] 2> 424667 T1372 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4/tlog
[junit4:junit4] 2> 424668 T1372 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 424669 T1372 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 424673 T1373 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@291590b1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 424675 T1372 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 424675 T1372 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 424798 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 424799 T1303 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:40320_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40320"}
[junit4:junit4] 2> 424799 T1303 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 424799 T1303 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 424813 T1338 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> 424813 T1302 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> 424813 T1322 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> 424813 T1354 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> 424813 T1371 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> 424813 T1309 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> 425678 T1372 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 425678 T1372 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40320 collection:collection1 shard:shard2
[junit4:junit4] 2> 425682 T1372 oasc.ZkController.register We are http://127.0.0.1:40320/collection1/ and leader is http://127.0.0.1:21410/collection1/
[junit4:junit4] 2> 425683 T1372 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40320
[junit4:junit4] 2> 425683 T1372 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 425683 T1372 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1836 name=collection1 org.apache.solr.core.SolrCore@56b87aa4 url=http://127.0.0.1:40320/collection1 node=127.0.0.1:40320_ C1836_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:40320_, base_url=http://127.0.0.1:40320}
[junit4:junit4] 2> 425684 T1374 C1836 P40320 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 425684 T1372 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 425685 T1374 C1836 P40320 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 425685 T1374 C1836 P40320 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 425686 T1374 C1836 P40320 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 425686 T1280 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 425687 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 425687 T1374 C1836 P40320 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 425687 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 425706 T1280 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 425707 T1328 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 425707 T1280 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 425708 T1280 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 425709 T1280 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C1837 name=collection1 org.apache.solr.core.SolrCore@33932f51 url=http://127.0.0.1:61947/collection1 node=127.0.0.1:61947_ C1837_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:61947_, base_url=http://127.0.0.1:61947}
[junit4:junit4] 2> 426220 T1357 C1837 P61947 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:24465/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 426220 T1357 C1837 P61947 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:61947 START replicas=[http://127.0.0.1:24465/collection1/] nUpdates=100
[junit4:junit4] 2> 426221 T1357 C1837 P61947 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 426222 T1357 C1837 P61947 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 426222 T1357 C1837 P61947 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 426222 T1357 C1837 P61947 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 426222 T1357 C1837 P61947 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 426223 T1357 C1837 P61947 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:24465/collection1/. core=collection1
[junit4:junit4] 2> 426223 T1357 C1837 P61947 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1838 name=collection1 org.apache.solr.core.SolrCore@12af17af url=http://127.0.0.1:24465/collection1 node=127.0.0.1:24465_ C1838_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:24465_, base_url=http://127.0.0.1:24465, leader=true}
[junit4:junit4] 2> 426230 T1313 C1838 P24465 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 426235 T1314 C1838 P24465 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 426238 T1314 C1838 P24465 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@742b1274 lockFactory=org.apache.lucene.store.NativeFSLockFactory@719b949e),segFN=segments_1,generation=1}
[junit4:junit4] 2> 426238 T1314 C1838 P24465 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 426239 T1314 C1838 P24465 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@742b1274 lockFactory=org.apache.lucene.store.NativeFSLockFactory@719b949e),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@742b1274 lockFactory=org.apache.lucene.store.NativeFSLockFactory@719b949e),segFN=segments_2,generation=2}
[junit4:junit4] 2> 426240 T1314 C1838 P24465 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 426240 T1314 C1838 P24465 oass.SolrIndexSearcher.<init> Opening Searcher@73f3b910 realtime
[junit4:junit4] 2> 426241 T1314 C1838 P24465 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 426241 T1314 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 426242 T1357 C1837 P61947 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 426242 T1357 C1837 P61947 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 426244 T1315 C1838 P24465 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 426245 T1315 C1838 P24465 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 426246 T1357 C1837 P61947 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 426246 T1357 C1837 P61947 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 426246 T1357 C1837 P61947 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 426248 T1315 C1838 P24465 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 426249 T1357 C1837 P61947 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 426250 T1357 C1837 P61947 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty3/index.20130604123330871
[junit4:junit4] 2> 426250 T1357 C1837 P61947 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@70b76b08 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f46687f) fullCopy=false
[junit4:junit4] 2> 426253 T1315 C1838 P24465 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 426305 T1357 C1837 P61947 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 426306 T1357 C1837 P61947 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 426306 T1357 C1837 P61947 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 426309 T1357 C1837 P61947 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7d70fddd lockFactory=org.apache.lucene.store.NativeFSLockFactory@771b6baa),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7d70fddd lockFactory=org.apache.lucene.store.NativeFSLockFactory@771b6baa),segFN=segments_2,generation=2}
[junit4:junit4] 2> 426309 T1357 C1837 P61947 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 426310 T1357 C1837 P61947 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 426310 T1357 C1837 P61947 oass.SolrIndexSearcher.<init> Opening Searcher@6a35b183 main
[junit4:junit4] 2> 426311 T1356 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6a35b183 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 426312 T1357 C1837 P61947 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty3/index.20130604123330871 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty3/index.20130604123330871;done=true>>]
[junit4:junit4] 2> 426312 T1357 C1837 P61947 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty3/index.20130604123330871
[junit4:junit4] 2> 426312 T1357 C1837 P61947 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty3/index.20130604123330871
[junit4:junit4] 2> 426313 T1357 C1837 P61947 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 426313 T1357 C1837 P61947 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 426313 T1357 C1837 P61947 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 426313 T1357 C1837 P61947 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 426315 T1357 C1837 P61947 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 426320 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 426321 T1303 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:40320_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40320"}
[junit4:junit4] 2> 426325 T1303 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:61947_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61947"}
[junit4:junit4] 2> 426337 T1338 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> 426337 T1302 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> 426337 T1354 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> 426337 T1322 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> 426337 T1371 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> 426337 T1309 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> 426709 T1328 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 426709 T1328 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:40320_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 426711 T1280 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 427714 T1280 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C1836_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:40320_, base_url=http://127.0.0.1:40320}
[junit4:junit4] 2> 428711 T1374 C1836 P40320 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:21410/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 428711 T1374 C1836 P40320 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40320 START replicas=[http://127.0.0.1:21410/collection1/] nUpdates=100
[junit4:junit4] 2> 428712 T1374 C1836 P40320 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 428712 T1374 C1836 P40320 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 428712 T1374 C1836 P40320 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 428712 T1374 C1836 P40320 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 428713 T1374 C1836 P40320 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 428714 T1374 C1836 P40320 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:21410/collection1/. core=collection1
[junit4:junit4] 2> 428714 T1374 C1836 P40320 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 428718 T1280 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C1839 name=collection1 org.apache.solr.core.SolrCore@8e56d76 url=http://127.0.0.1:21410/collection1 node=127.0.0.1:21410_ C1839_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:21410_, base_url=http://127.0.0.1:21410, leader=true}
[junit4:junit4] 2> 428721 T1329 C1839 P21410 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 428725 T1330 C1839 P21410 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 428728 T1330 C1839 P21410 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2c04f395 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44a07682),segFN=segments_1,generation=1}
[junit4:junit4] 2> 428729 T1330 C1839 P21410 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 428730 T1330 C1839 P21410 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2c04f395 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44a07682),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2c04f395 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44a07682),segFN=segments_2,generation=2}
[junit4:junit4] 2> 428730 T1330 C1839 P21410 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 428731 T1330 C1839 P21410 oass.SolrIndexSearcher.<init> Opening Searcher@2688e103 realtime
[junit4:junit4] 2> 428731 T1330 C1839 P21410 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 428732 T1330 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 428732 T1374 C1836 P40320 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 428733 T1374 C1836 P40320 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 428735 T1331 C1839 P21410 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 428735 T1331 C1839 P21410 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 428736 T1374 C1836 P40320 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 428736 T1374 C1836 P40320 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 428736 T1374 C1836 P40320 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 428739 T1331 C1839 P21410 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 428740 T1374 C1836 P40320 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 428741 T1374 C1836 P40320 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4/index.20130604123333362
[junit4:junit4] 2> 428741 T1374 C1836 P40320 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@69289e0c lockFactory=org.apache.lucene.store.NativeFSLockFactory@37a764c8) fullCopy=false
[junit4:junit4] 2> 428744 T1331 C1839 P21410 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 428797 T1374 C1836 P40320 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 428798 T1374 C1836 P40320 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 428798 T1374 C1836 P40320 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 428800 T1374 C1836 P40320 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40f6dc1b lockFactory=org.apache.lucene.store.NativeFSLockFactory@158614a0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40f6dc1b lockFactory=org.apache.lucene.store.NativeFSLockFactory@158614a0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 428800 T1374 C1836 P40320 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 428800 T1374 C1836 P40320 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 428801 T1374 C1836 P40320 oass.SolrIndexSearcher.<init> Opening Searcher@7b4aa08d main
[junit4:junit4] 2> 428802 T1373 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7b4aa08d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 428803 T1374 C1836 P40320 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4/index.20130604123333362 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4/index.20130604123333362;done=true>>]
[junit4:junit4] 2> 428803 T1374 C1836 P40320 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4/index.20130604123333362
[junit4:junit4] 2> 428803 T1374 C1836 P40320 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4/index.20130604123333362
[junit4:junit4] 2> 428803 T1374 C1836 P40320 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 428804 T1374 C1836 P40320 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 428804 T1374 C1836 P40320 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 428804 T1374 C1836 P40320 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 428806 T1374 C1836 P40320 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 429355 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 429356 T1303 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:40320_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40320"}
[junit4:junit4] 2> 429371 T1338 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> 429371 T1322 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> 429371 T1354 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> 429371 T1302 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> 429371 T1371 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> 429371 T1309 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> 429721 T1280 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 429722 T1280 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C1840 name=collection1 org.apache.solr.core.SolrCore@1105254f url=http://127.0.0.1:42992/collection1 node=127.0.0.1:42992_ C1840_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:42992_, base_url=http://127.0.0.1:42992, leader=true}
[junit4:junit4] 2> 429731 T1292 C1840 P42992 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 429734 T1292 C1840 P42992 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@355e7536 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65bf0fcb),segFN=segments_1,generation=1}
[junit4:junit4] 2> 429735 T1292 C1840 P42992 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 429736 T1292 C1840 P42992 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@355e7536 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65bf0fcb),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@355e7536 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65bf0fcb),segFN=segments_2,generation=2}
[junit4:junit4] 2> 429736 T1292 C1840 P42992 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 429737 T1292 C1840 P42992 oass.SolrIndexSearcher.<init> Opening Searcher@47c62a27 main
[junit4:junit4] 2> 429738 T1292 C1840 P42992 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 429738 T1306 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@47c62a27 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 429739 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 429750 T1316 C1838 P24465 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 429751 T1316 C1838 P24465 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@742b1274 lockFactory=org.apache.lucene.store.NativeFSLockFactory@719b949e),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@742b1274 lockFactory=org.apache.lucene.store.NativeFSLockFactory@719b949e),segFN=segments_3,generation=3}
[junit4:junit4] 2> 429752 T1316 C1838 P24465 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 429752 T1316 C1838 P24465 oass.SolrIndexSearcher.<init> Opening Searcher@7860b23b main
[junit4:junit4] 2> 429753 T1316 C1838 P24465 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 429754 T1324 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7860b23b main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 429754 T1316 C1838 P24465 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:61947/collection1/, StdNode: http://127.0.0.1:21410/collection1/, StdNode: http://127.0.0.1:40320/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 429757 T1332 C1839 P21410 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 429759 T1332 C1839 P21410 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2c04f395 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44a07682),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2c04f395 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44a07682),segFN=segments_3,generation=3}
[junit4:junit4] 2> 429759 T1332 C1839 P21410 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 429760 T1332 C1839 P21410 oass.SolrIndexSearcher.<init> Opening Searcher@3d49dfae main
[junit4:junit4] 2> 429760 T1332 C1839 P21410 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 429761 T1340 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3d49dfae main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 429761 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> C1837_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:61947_, base_url=http://127.0.0.1:61947}
[junit4:junit4] 2> 429765 T1344 C1837 P61947 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C1836_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:40320_, base_url=http://127.0.0.1:40320}
[junit4:junit4] 2> 429765 T1361 C1836 P40320 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 429766 T1344 C1837 P61947 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7d70fddd lockFactory=org.apache.lucene.store.NativeFSLockFactory@771b6baa),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7d70fddd lockFactory=org.apache.lucene.store.NativeFSLockFactory@771b6baa),segFN=segments_3,generation=3}
[junit4:junit4] 2> 429767 T1361 C1836 P40320 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40f6dc1b lockFactory=org.apache.lucene.store.NativeFSLockFactory@158614a0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40f6dc1b lockFactory=org.apache.lucene.store.NativeFSLockFactory@158614a0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 429767 T1344 C1837 P61947 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 429768 T1361 C1836 P40320 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 429768 T1344 C1837 P61947 oass.SolrIndexSearcher.<init> Opening Searcher@277a251 main
[junit4:junit4] 2> 429769 T1361 C1836 P40320 oass.SolrIndexSearcher.<init> Opening Searcher@5c99d7b2 main
[junit4:junit4] 2> 429769 T1344 C1837 P61947 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 429770 T1356 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@277a251 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 429770 T1361 C1836 P40320 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 429771 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 429771 T1373 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5c99d7b2 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 429772 T1361 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 429773 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 23
[junit4:junit4] 2> 429774 T1280 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 429777 T1317 C1838 P24465 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 429779 T1345 C1837 P61947 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 429781 T1333 C1839 P21410 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 429783 T1362 C1836 P40320 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 431789 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436941724060483584)} 0 2
[junit4:junit4] 2> 431797 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1436941724064677888&update.from=http://127.0.0.1:21410/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436941724064677888)} 0 2
[junit4:junit4] 2> 431800 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1436941724068872192&update.from=http://127.0.0.1:24465/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436941724068872192)} 0 1
[junit4:junit4] 2> 431801 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1436941724068872192)} 0 6
[junit4:junit4] 2> 431802 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436941724064677888)} 0 11
[junit4:junit4] 2> 431806 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1436941724079357952)]} 0 1
[junit4:junit4] 2> 431812 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1436941724083552256)]} 0 0
[junit4:junit4] 2> 431813 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1436941724083552256)]} 0 4
[junit4:junit4] 2> 431816 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1436941724090892288)]} 0 0
[junit4:junit4] 2> 431824 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1436941724096135168)]} 0 0
[junit4:junit4] 2> 431825 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!1 (1436941724096135168)]} 0 4
[junit4:junit4] 2> 431826 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1]} 0 7
[junit4:junit4] 2> 431829 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1436941724104523776)]} 0 0
[junit4:junit4] 2> 431835 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1436941724107669504)]} 0 0
[junit4:junit4] 2> 431836 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1436941724107669504)]} 0 4
[junit4:junit4] 2> 431839 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1436941724115009536)]} 0 0
[junit4:junit4] 2> 431846 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1436941724120252416)]} 0 0
[junit4:junit4] 2> 431847 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!3 (1436941724120252416)]} 0 3
[junit4:junit4] 2> 431848 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3]} 0 6
[junit4:junit4] 2> 431850 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1436941724126543872)]} 0 0
[junit4:junit4] 2> 431856 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1436941724129689600)]} 0 0
[junit4:junit4] 2> 431857 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1436941724129689600)]} 0 4
[junit4:junit4] 2> 431860 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1436941724137029632)]} 0 0
[junit4:junit4] 2> 431868 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1436941724143321088)]} 0 0
[junit4:junit4] 2> 431869 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1436941724143321088)]} 0 3
[junit4:junit4] 2> 431870 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5]} 0 7
[junit4:junit4] 2> 431872 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1436941724149612544)]} 0 0
[junit4:junit4] 2> 431877 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1436941724152758272)]} 0 0
[junit4:junit4] 2> 431878 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1436941724152758272)]} 0 3
[junit4:junit4] 2> 431882 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1436941724160098304)]} 0 0
[junit4:junit4] 2> 431888 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1436941724163244032)]} 0 0
[junit4:junit4] 2> 431889 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1436941724163244032)]} 0 4
[junit4:junit4] 2> 431892 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1436941724170584064)]} 0 0
[junit4:junit4] 2> 431899 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1436941724175826944)]} 0 0
[junit4:junit4] 2> 431900 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!8 (1436941724175826944)]} 0 3
[junit4:junit4] 2> 431900 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8]} 0 5
[junit4:junit4] 2> 431903 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1436941724182118400)]} 0 0
[junit4:junit4] 2> 431908 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1436941724185264128)]} 0 0
[junit4:junit4] 2> 431909 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1436941724185264128)]} 0 3
[junit4:junit4] 2> 431911 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1436941724190507008)]} 0 0
[junit4:junit4] 2> 431919 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1436941724195749888)]} 0 0
[junit4:junit4] 2> 431920 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!10 (1436941724195749888)]} 0 4
[junit4:junit4] 2> 431921 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10]} 0 7
[junit4:junit4] 2> 431923 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1436941724203089920)]} 0 0
[junit4:junit4] 2> 431930 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1436941724207284224)]} 0 0
[junit4:junit4] 2> 431931 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!11 (1436941724207284224)]} 0 4
[junit4:junit4] 2> 431932 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11]} 0 6
[junit4:junit4] 2> 431934 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1436941724214624256)]} 0 0
[junit4:junit4] 2> 431942 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1436941724219867136)]} 0 0
[junit4:junit4] 2> 431943 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!12 (1436941724219867136)]} 0 4
[junit4:junit4] 2> 431943 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12]} 0 6
[junit4:junit4] 2> 431947 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1436941724228255744)]} 0 0
[junit4:junit4] 2> 431954 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1436941724232450048)]} 0 0
[junit4:junit4] 2> 431955 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1436941724232450048)]} 0 4
[junit4:junit4] 2> 431958 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1436941724239790080)]} 0 0
[junit4:junit4] 2> 431967 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1436941724246081536)]} 0 1
[junit4:junit4] 2> 431968 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!14 (1436941724246081536)]} 0 4
[junit4:junit4] 2> 431968 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14]} 0 7
[junit4:junit4] 2> 431973 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1436941724254470144)]} 0 0
[junit4:junit4] 2> 431978 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1436941724258664448)]} 0 0
[junit4:junit4] 2> 431979 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1436941724258664448)]} 0 3
[junit4:junit4] 2> 431983 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1436941724266004480)]} 0 0
[junit4:junit4] 2> 431992 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1436941724272295936)]} 0 0
[junit4:junit4] 2> 431993 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1436941724272295936)]} 0 4
[junit4:junit4] 2> 431994 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16]} 0 7
[junit4:junit4] 2> 431997 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1436941724280684544)]} 0 0
[junit4:junit4] 2> 432003 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1436941724283830272)]} 0 0
[junit4:junit4] 2> 432004 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1436941724283830272)]} 0 4
[junit4:junit4] 2> 432007 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1436941724291170304)]} 0 0
[junit4:junit4] 2> 432012 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1436941724294316032)]} 0 0
[junit4:junit4] 2> 432013 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1436941724294316032)]} 0 3
[junit4:junit4] 2> 432016 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1436941724300607488)]} 0 0
[junit4:junit4] 2> 432024 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1436941724306898944)]} 0 0
[junit4:junit4] 2> 432025 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!19 (1436941724306898944)]} 0 3
[junit4:junit4] 2> 432025 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19]} 0 6
[junit4:junit4] 2> 432028 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1436941724313190400)]} 0 0
[junit4:junit4] 2> 432036 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1436941724319481856)]} 0 0
[junit4:junit4] 2> 432037 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!20 (1436941724319481856)]} 0 3
[junit4:junit4] 2> 432037 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20]} 0 6
[junit4:junit4] 2> 432041 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1436941724326821888)]} 0 0
[junit4:junit4] 2> 432047 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1436941724329967616)]} 0 0
[junit4:junit4] 2> 432048 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1436941724329967616)]} 0 4
[junit4:junit4] 2> 432050 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1436941724336259072)]} 0 0
[junit4:junit4] 2> 432056 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1436941724339404800)]} 0 0
[junit4:junit4] 2> 432057 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1436941724339404800)]} 0 4
[junit4:junit4] 2> 432060 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1436941724346744832)]} 0 0
[junit4:junit4] 2> 432069 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1436941724353036288)]} 0 0
[junit4:junit4] 2> 432070 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!23 (1436941724353036288)]} 0 4
[junit4:junit4] 2> 432071 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23]} 0 7
[junit4:junit4] 2> 432074 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1436941724361424896)]} 0 0
[junit4:junit4] 2> 432081 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1436941724365619200)]} 0 0
[junit4:junit4] 2> 432082 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1436941724365619200)]} 0 4
[junit4:junit4] 2> 432086 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1436941724374007808)]} 0 0
[junit4:junit4] 2> 432091 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1436941724377153536)]} 0 0
[junit4:junit4] 2> 432092 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1436941724377153536)]} 0 3
[junit4:junit4] 2> 432095 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1436941724383444992)]} 0 0
[junit4:junit4] 2> 432102 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1436941724388687872)]} 0 0
[junit4:junit4] 2> 432103 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!26 (1436941724388687872)]} 0 3
[junit4:junit4] 2> 432104 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26]} 0 5
[junit4:junit4] 2> 432106 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1436941724394979328)]} 0 0
[junit4:junit4] 2> 432114 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1436941724401270784)]} 0 0
[junit4:junit4] 2> 432115 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!27 (1436941724401270784)]} 0 3
[junit4:junit4] 2> 432115 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27]} 0 6
[junit4:junit4] 2> 432119 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1436941724408610816)]} 0 0
[junit4:junit4] 2> 432125 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1436941724411756544)]} 0 0
[junit4:junit4] 2> 432126 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1436941724411756544)]} 0 4
[junit4:junit4] 2> 432129 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1436941724419096576)]} 0 0
[junit4:junit4] 2> 432138 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1436941724425388032)]} 0 0
[junit4:junit4] 2> 432139 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1436941724425388032)]} 0 4
[junit4:junit4] 2> 432140 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29]} 0 8
[junit4:junit4] 2> 432142 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1436941724432728064)]} 0 0
[junit4:junit4] 2> 432150 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1436941724439019520)]} 0 0
[junit4:junit4] 2> 432151 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!30 (1436941724439019520)]} 0 3
[junit4:junit4] 2> 432152 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30]} 0 7
[junit4:junit4] 2> 432155 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1436941724446359552)]} 0 0
[junit4:junit4] 2> 432161 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1436941724449505280)]} 0 0
[junit4:junit4] 2> 432162 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1436941724449505280)]} 0 4
[junit4:junit4] 2> 432165 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1436941724456845312)]} 0 0
[junit4:junit4] 2> 432172 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1436941724462088192)]} 0 0
[junit4:junit4] 2> 432173 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!32 (1436941724462088192)]} 0 3
[junit4:junit4] 2> 432174 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32]} 0 6
[junit4:junit4] 2> 432176 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1436941724468379648)]} 0 0
[junit4:junit4] 2> 432182 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1436941724472573952)]} 0 0
[junit4:junit4] 2> 432183 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1436941724472573952)]} 0 3
[junit4:junit4] 2> 432186 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1436941724478865408)]} 0 0
[junit4:junit4] 2> 432192 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1436941724482011136)]} 0 0
[junit4:junit4] 2> 432193 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1436941724482011136)]} 0 4
[junit4:junit4] 2> 432196 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1436941724489351168)]} 0 0
[junit4:junit4] 2> 432202 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1436941724492496896)]} 0 0
[junit4:junit4] 2> 432203 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1436941724492496896)]} 0 4
[junit4:junit4] 2> 432206 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1436941724499836928)]} 0 0
[junit4:junit4] 2> 432211 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1436941724502982656)]} 0 0
[junit4:junit4] 2> 432212 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1436941724502982656)]} 0 3
[junit4:junit4] 2> 432215 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1436941724509274112)]} 0 0
[junit4:junit4] 2> 432222 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1436941724514516992)]} 0 0
[junit4:junit4] 2> 432223 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1436941724514516992)]} 0 3
[junit4:junit4] 2> 432224 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37]} 0 6
[junit4:junit4] 2> 432226 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1436941724520808448)]} 0 0
[junit4:junit4] 2> 432234 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1436941724526051328)]} 0 0
[junit4:junit4] 2> 432235 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!38 (1436941724526051328)]} 0 4
[junit4:junit4] 2> 432236 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38]} 0 7
[junit4:junit4] 2> 432239 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1436941724534439936)]} 0 0
[junit4:junit4] 2> 432244 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1436941724537585664)]} 0 0
[junit4:junit4] 2> 432245 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1436941724537585664)]} 0 3
[junit4:junit4] 2> 432248 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1436941724543877120)]} 0 0
[junit4:junit4] 2> 432256 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1436941724549120000)]} 0 0
[junit4:junit4] 2> 432257 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!40 (1436941724549120000)]} 0 4
[junit4:junit4] 2> 432258 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40]} 0 7
[junit4:junit4] 2> 432261 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1436941724557508608)]} 0 0
[junit4:junit4] 2> 432268 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1436941724561702912)]} 0 0
[junit4:junit4] 2> 432269 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1436941724561702912)]} 0 4
[junit4:junit4] 2> 432272 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1436941724569042944)]} 0 0
[junit4:junit4] 2> 432277 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1436941724572188672)]} 0 0
[junit4:junit4] 2> 432278 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1436941724572188672)]} 0 3
[junit4:junit4] 2> 432281 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1436941724578480128)]} 0 0
[junit4:junit4] 2> 432290 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1436941724584771584)]} 0 0
[junit4:junit4] 2> 432291 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!43 (1436941724584771584)]} 0 4
[junit4:junit4] 2> 432292 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43]} 0 8
[junit4:junit4] 2> 432294 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1436941724592111616)]} 0 0
[junit4:junit4] 2> 432301 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1436941724597354496)]} 0 0
[junit4:junit4] 2> 432302 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!44 (1436941724597354496)]} 0 3
[junit4:junit4] 2> 432302 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44]} 0 5
[junit4:junit4] 2> 432305 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1436941724603645952)]} 0 0
[junit4:junit4] 2> 432312 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1436941724608888832)]} 0 0
[junit4:junit4] 2> 432313 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!45 (1436941724608888832)]} 0 3
[junit4:junit4] 2> 432313 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45]} 0 5
[junit4:junit4] 2> 432316 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1436941724615180288)]} 0 0
[junit4:junit4] 2> 432323 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1436941724619374592)]} 0 0
[junit4:junit4] 2> 432324 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1436941724619374592)]} 0 4
[junit4:junit4] 2> 432327 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1436941724626714624)]} 0 0
[junit4:junit4] 2> 432333 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1436941724629860352)]} 0 0
[junit4:junit4] 2> 432334 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1436941724629860352)]} 0 4
[junit4:junit4] 2> 432337 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1436941724637200384)]} 0 0
[junit4:junit4] 2> 432344 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1436941724642443264)]} 0 0
[junit4:junit4] 2> 432345 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!48 (1436941724642443264)]} 0 3
[junit4:junit4] 2> 432345 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48]} 0 5
[junit4:junit4] 2> 432348 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1436941724648734720)]} 0 0
[junit4:junit4] 2> 432353 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1436941724651880448)]} 0 0
[junit4:junit4] 2> 432354 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1436941724651880448)]} 0 3
[junit4:junit4] 2> 432356 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1436941724657123328)]} 0 0
[junit4:junit4] 2> 432362 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1436941724660269056)]} 0 0
[junit4:junit4] 2> 432363 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1436941724660269056)]} 0 4
[junit4:junit4] 2> 432366 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1436941724667609088)]} 0 0
[junit4:junit4] 2> 432372 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1436941724670754816)]} 0 0
[junit4:junit4] 2> 432373 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1436941724670754816)]} 0 4
[junit4:junit4] 2> 432376 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1436941724678094848)]} 0 0
[junit4:junit4] 2> 432382 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1436941724681240576)]} 0 0
[junit4:junit4] 2> 432383 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1436941724681240576)]} 0 4
[junit4:junit4] 2> 432386 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1436941724688580608)]} 0 0
[junit4:junit4] 2> 432391 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1436941724691726336)]} 0 0
[junit4:junit4] 2> 432392 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1436941724691726336)]} 0 3
[junit4:junit4] 2> 432395 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1436941724698017792)]} 0 0
[junit4:junit4] 2> 432402 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1436941724703260672)]} 0 0
[junit4:junit4] 2> 432403 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!54 (1436941724703260672)]} 0 3
[junit4:junit4] 2> 432403 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54]} 0 5
[junit4:junit4] 2> 432407 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55 (1436941724710600704)]} 0 0
[junit4:junit4] 2> 432415 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1436941724715843584)]} 0 0
[junit4:junit4] 2> 432416 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1436941724715843584)]} 0 4
[junit4:junit4] 2> 432417 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55]} 0 7
[junit4:junit4] 2> 432419 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1436941724723183616)]} 0 0
[junit4:junit4] 2> 432424 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1436941724726329344)]} 0 0
[junit4:junit4] 2> 432425 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1436941724726329344)]} 0 3
[junit4:junit4] 2> 432428 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1436941724732620800)]} 0 0
[junit4:junit4] 2> 432433 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1436941724735766528)]} 0 0
[junit4:junit4] 2> 432434 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1436941724735766528)]} 0 3
[junit4:junit4] 2> 432437 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58 (1436941724742057984)]} 0 0
[junit4:junit4] 2> 432442 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1436941724745203712)]} 0 0
[junit4:junit4] 2> 432443 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58 (1436941724745203712)]} 0 3
[junit4:junit4] 2> 432445 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1436941724750446592)]} 0 0
[junit4:junit4] 2> 432453 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1436941724756738048)]} 0 0
[junit4:junit4] 2> 432454 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!59 (1436941724756738048)]} 0 3
[junit4:junit4] 2> 432454 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59]} 0 5
[junit4:junit4] 2> 432457 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1436941724763029504)]} 0 0
[junit4:junit4] 2> 432463 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1436941724767223808)]} 0 0
[junit4:junit4] 2> 432464 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1436941724767223808)]} 0 3
[junit4:junit4] 2> 432467 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1436941724773515264)]} 0 0
[junit4:junit4] 2> 432473 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1436941724777709568)]} 0 0
[junit4:junit4] 2> 432474 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1436941724777709568)]} 0 3
[junit4:junit4] 2> 432479 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62 (1436941724785049600)]} 0 1
[junit4:junit4] 2> 432487 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!62 (1436941724792389632)]} 0 0
[junit4:junit4] 2> 432488 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!62 (1436941724792389632)]} 0 3
[junit4:junit4] 2> 432489 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62]} 0 6
[junit4:junit4] 2> 432492 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63 (1436941724799729664)]} 0 0
[junit4:junit4] 2> 432501 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!63 (1436941724806021120)]} 0 0
[junit4:junit4] 2> 432502 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!63 (1436941724806021120)]} 0 4
[junit4:junit4] 2> 432503 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63]} 0 8
[junit4:junit4] 2> 432506 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64 (1436941724814409728)]} 0 0
[junit4:junit4] 2> 432513 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!64 (1436941724818604032)]} 0 0
[junit4:junit4] 2> 432514 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64 (1436941724818604032)]} 0 4
[junit4:junit4] 2> 432517 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!65 (1436941724825944064)]} 0 0
[junit4:junit4] 2> 432524 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!65 (1436941724830138368)]} 0 0
[junit4:junit4] 2> 432525 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!65 (1436941724830138368)]} 0 4
[junit4:junit4] 2> 432528 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!66 (1436941724837478400)]} 0 0
[junit4:junit4] 2> 432533 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!66 (1436941724839575552)]} 0 0
[junit4:junit4] 2> 432534 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!66 (1436941724839575552)]} 0 4
[junit4:junit4] 2> 432535 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!67 (1436941724844818432)]} 0 0
[junit4:junit4] 2> 432543 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!67 (1436941724850061312)]} 0 0
[junit4:junit4] 2> 432544 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!67 (1436941724850061312)]} 0 4
[junit4:junit4] 2> 432545 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!67]} 0 7
[junit4:junit4] 2> 432547 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!68 (1436941724857401344)]} 0 0
[junit4:junit4] 2> 432556 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!68 (1436941724863692800)]} 0 0
[junit4:junit4] 2> 432557 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!68 (1436941724863692800)]} 0 4
[junit4:junit4] 2> 432558 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!68]} 0 7
[junit4:junit4] 2> 432561 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!69 (1436941724872081408)]} 0 0
[junit4:junit4] 2> 432571 T1363 C1836 P40320 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!69 (1436941724878372864)]} 0 1
[junit4:junit4] 2> 432571 T1332 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!69 (1436941724878372864)]} 0 4
[junit4:junit4] 2> 432572 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!69]} 0 7
[junit4:junit4] 2> 432576 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!70 (1436941724886761472)]} 0 1
[junit4:junit4] 2> 432582 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!70 (1436941724892004352)]} 0 0
[junit4:junit4] 2> 432583 T1318 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!70 (1436941724892004352)]} 0 3
[junit4:junit4] 2> 432584 T1334 C1839 P21410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!70]} 0 6
[junit4:junit4] 2> 432590 T1292 C1840 P42992 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!71 (1436941724899344384)]} 0 3
[junit4:junit4] 2> 432597 T1344 C1837 P61947 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24465/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!71 (1436941724905635840)]} 0 1
[junit4:junit4] 2> 432597 T1316 C1838 P24465 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!71 (1436941724905635840)]} 0 4
[junit4:junit4] 2> 432600 T1292 C1840 P42992 oasup.LogU
[...truncated too long message...]
1371 oasu.PeerSync.handleResponse WARN PeerSync: core=collection1 url=http://127.0.0.1:40320 couldn't connect to http://127.0.0.1:21410/collection1/, counting as success
[junit4:junit4] 2> 600755 T1371 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40320 DONE. sync succeeded
[junit4:junit4] 2> 600755 T1371 oasc.SyncStrategy.syncReplicas We have been closed, won't attempt to sync replicas back to leader
[junit4:junit4] 2> 600756 T1371 oasc.ShardLeaderElectionContext.runLeaderProcess Sync was not a success but no one else is active! I am the leader
[junit4:junit4] 2> 600756 T1371 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:40320/collection1/
[junit4:junit4] 2> 600757 T1371 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@56b87aa4
[junit4:junit4] 2> 600764 T1371 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=2,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=666,adds=666,deletesById=337,deletesByQuery=0,errors=0,cumulative_adds=708,cumulative_deletesById=337,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 600764 T1371 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 600764 T1371 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 600764 T1371 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 600776 T1371 C1880 P40320 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40f6dc1b lockFactory=org.apache.lucene.store.NativeFSLockFactory@158614a0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40f6dc1b lockFactory=org.apache.lucene.store.NativeFSLockFactory@158614a0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 600777 T1371 C1880 P40320 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 600781 T1371 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 600781 T1371 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 600781 T1371 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4;done=false>>]
[junit4:junit4] 2> 600781 T1371 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4
[junit4:junit4] 2> 600782 T1371 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4/index;done=false>>]
[junit4:junit4] 2> 600782 T1371 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1370374390188/jetty4/index
[junit4:junit4] 2> 600782 T1371 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 600783 T1371 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election/89808856035885068-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> 600784 T1371 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 600784 T1371 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> 600784 T1371 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 600784 T1371 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> 600784 T1371 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 600785 T1371 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=Appending, sim=DefaultSimilarity, locale=es_CR, timezone=US/Pacific-New
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=2,free=143497112,total=483393536
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SuggesterFSTTest, TestSystemIdResolver, SchemaVersionSpecificBehaviorTest, SuggesterTest, TestTrie, SampleTest, ShardRoutingTest, EchoParamsTest, TestPartialUpdateDeduplication, RAMDirectoryFactoryTest, SolrCmdDistributorTest, LegacyHTMLStripCharFilterTest, TestPropInject, RegexBoostProcessorTest, CurrencyFieldXmlFileTest, TestExtendedDismaxParser, TermVectorComponentTest, OpenCloseCoreStressTest, StandardRequestHandlerTest, TestSweetSpotSimilarityFactory, TestBadConfig, TestIndexingPerformance, TestStressReorder, JSONWriterTest, TestAnalyzedSuggestions, TestPhraseSuggestions, NotRequiredUniqueKeyTest, SuggesterTSTTest, RequestHandlersTest, FileBasedSpellCheckerTest, TestFiltering, TestFieldTypeCollectionResource, AliasIntegrationTest, TestUtils, TestBinaryResponseWriter, TestFastWriter, DistributedQueryElevationComponentTest, SpellingQueryConverterTest, TestDefaultSearchFieldResource, PrimitiveFieldTypeTest, TestQuerySenderNoQuery, QueryElevationComponentTest, DisMaxRequestHandlerTest, ShardSplitTest]
[junit4:junit4] Completed on J0 in 195.57s, 1 test, 1 error <<< FAILURES!
[...truncated 659 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:386: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:366: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:887: There were test failures: 297 suites, 1238 tests, 1 error, 13 ignored (7 assumptions)
Total time: 50 minutes 43 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure