Page MenuHomePhabricator

Expectation (masterConns <= 0) not met (via GrowthExperimentsLinkRecommendationStore constructor)
Closed, ResolvedPublicPRODUCTION ERROR

Description

Error

MediaWiki version: 1.36.0-wmf.33

message
Expectation (masterConns <= 0) by ApiMain::setRequestExpectations not met (actual: 1):
[connect to 10.64.48.35 (testwiki)]

Impact

Notes

It looks like GrowthExperimentsLinkRecommendationStore service, which accepts a master DB connection in its setup, is getting injected to HomepageHooks; HomepageHooks is invoked because it has a callback registered for onUserGetDefaultOptions, and onUserGetDefaultOptions is called from a lot of places. As a result we have ~35,000 of these log messages in the last 24 hours.

Details

Request URL
https://test.wikipedia.org/w/api.php
Stack Trace
exception.trace
from /srv/mediawiki/php-1.36.0-wmf.33/includes/libs/rdbms/TransactionProfiler.php(378)
#0 /srv/mediawiki/php-1.36.0-wmf.33/includes/libs/rdbms/TransactionProfiler.php(189): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated(string, string, integer)
#1 /srv/mediawiki/php-1.36.0-wmf.33/includes/libs/rdbms/loadbalancer/LoadBalancer.php(1006): Wikimedia\Rdbms\TransactionProfiler->recordConnection(string, string, boolean)
#2 /srv/mediawiki/php-1.36.0-wmf.33/includes/libs/rdbms/loadbalancer/LoadBalancer.php(960): Wikimedia\Rdbms\LoadBalancer->getServerConnection(integer, string, integer)
#3 /srv/mediawiki/php-1.36.0-wmf.33/extensions/GrowthExperiments/ServiceWiring.php(112): Wikimedia\Rdbms\LoadBalancer->getConnection(integer)
#4 /srv/mediawiki/php-1.36.0-wmf.33/vendor/wikimedia/services/src/ServiceContainer.php(447): Wikimedia\Services\ServiceContainer->{closure}(MediaWiki\MediaWikiServices)
#5 /srv/mediawiki/php-1.36.0-wmf.33/vendor/wikimedia/services/src/ServiceContainer.php(416): Wikimedia\Services\ServiceContainer->createService(string)
#6 /srv/mediawiki/php-1.36.0-wmf.33/includes/MediaWikiServices.php(261): Wikimedia\Services\ServiceContainer->getService(string)
#7 /srv/mediawiki/php-1.36.0-wmf.33/vendor/wikimedia/services/src/ServiceContainer.php(424): MediaWiki\MediaWikiServices->getService(string)
#8 /srv/mediawiki/php-1.36.0-wmf.33/vendor/wikimedia/object-factory/src/ObjectFactory.php(209): Wikimedia\Services\ServiceContainer->get(string)
#9 /srv/mediawiki/php-1.36.0-wmf.33/vendor/wikimedia/object-factory/src/ObjectFactory.php(150): Wikimedia\ObjectFactory::getObjectFromSpec(array, array)
#10 /srv/mediawiki/php-1.36.0-wmf.33/includes/HookContainer/HookContainer.php(468): Wikimedia\ObjectFactory->createObject(array)
#11 /srv/mediawiki/php-1.36.0-wmf.33/includes/HookContainer/HookContainer.php(159): MediaWiki\HookContainer\HookContainer->getHandlers(string, array)
#12 /srv/mediawiki/php-1.36.0-wmf.33/includes/HookContainer/HookRunner.php(4268): MediaWiki\HookContainer\HookContainer->run(string, array)
#13 /srv/mediawiki/php-1.36.0-wmf.33/includes/user/DefaultOptionsLookup.php(102): MediaWiki\HookContainer\HookRunner->onUserGetDefaultOptions(array)
#14 /srv/mediawiki/php-1.36.0-wmf.33/includes/user/UserOptionsManager.php(497): MediaWiki\User\DefaultOptionsLookup->getDefaultOptions()
#15 /srv/mediawiki/php-1.36.0-wmf.33/includes/user/UserOptionsManager.php(138): MediaWiki\User\UserOptionsManager->loadUserOptions(User, integer)
#16 /srv/mediawiki/php-1.36.0-wmf.33/includes/user/User.php(2664): MediaWiki\User\UserOptionsManager->getOption(User, string, NULL, boolean)
#17 /srv/mediawiki/php-1.36.0-wmf.33/includes/context/RequestContext.php(376): User->getOption(string)
#18 /srv/mediawiki/php-1.36.0-wmf.33/includes/context/DerivativeContext.php(252): RequestContext->getLanguage()
#19 /srv/mediawiki/php-1.36.0-wmf.33/includes/context/ContextSource.php(152): DerivativeContext->getLanguage()
#20 /srv/mediawiki/php-1.36.0-wmf.33/includes/api/ApiHelp.php(47): ContextSource->getLanguage()
#21 /srv/mediawiki/php-1.36.0-wmf.33/includes/api/ApiMain.php(1612): ApiHelp->execute()
#22 /srv/mediawiki/php-1.36.0-wmf.33/includes/api/ApiMain.php(591): ApiMain->executeAction()
#23 /srv/mediawiki/php-1.36.0-wmf.33/includes/api/ApiMain.php(562): ApiMain->executeActionWithErrorHandling()
#24 /srv/mediawiki/php-1.36.0-wmf.33/api.php(90): ApiMain->execute()
#25 /srv/mediawiki/php-1.36.0-wmf.33/api.php(45): wfApiMain()
#26 /srv/mediawiki/w/api.php(3): require(string)
#27 {main}

Event Timeline

'GrowthExperimentsLinkRecommendationStore' => function (
		MediaWikiServices $services
	): LinkRecommendationStore {
		$loadBalancer = GrowthExperimentsServices::wrap( $services )->getLoadBalancer();
		return new LinkRecommendationStore(
			$loadBalancer->getConnection( DB_REPLICA ),
			$loadBalancer->getConnection( DB_MASTER ),
			$services->getTitleFactory(),
			$services->getLinkBatchFactory()
		);
	},

@Tgr should we just pass in a ILoadBalancer, and have some code in LinkRecommendationStore that gets the read and write connection on the fly if it's not already opened?

Change 668029 had a related patch set uploaded (by Gergő Tisza; owner: Gergő Tisza):
[mediawiki/extensions/GrowthExperiments@master] Do not open DB connections during service initialization

https://gerrit.wikimedia.org/r/668029

@Tgr should we just pass in a ILoadBalancer, and have some code in LinkRecommendationStore that gets the read and write connection on the fly if it's not already opened?

That would work too; using lazy connections is maybe a bit simpler.

Change 668046 had a related patch set uploaded (by Kosta Harlan; owner: Gergő Tisza):
[mediawiki/extensions/GrowthExperiments@wmf/1.36.0-wmf.33] Do not open DB connections during service initialization

https://gerrit.wikimedia.org/r/668046

Change 668029 merged by jenkins-bot:
[mediawiki/extensions/GrowthExperiments@master] Do not open DB connections during service initialization

https://gerrit.wikimedia.org/r/668029

Change 668046 merged by jenkins-bot:
[mediawiki/extensions/GrowthExperiments@wmf/1.36.0-wmf.33] Do not open DB connections during service initialization

https://gerrit.wikimedia.org/r/668046

@Tgr, @kostajh - can you backport the fix to train?

Yes, it's happening right now (T276307#6878173)

Mentioned in SAL (#wikimedia-operations) [2021-03-03T12:29:18Z] <urbanecm@deploy1002> Synchronized php-1.36.0-wmf.33/extensions/GrowthExperiments/ServiceWiring.php: cf635b46a112433f78979b04eb21729783cb2033: Do not open DB connections during service initialization (T276307) (duration: 01m 11s)

kostajh moved this task from Code Review to QA on the Growth-Team (Current Sprint) board.

image.png (598×1 px, 76 KB)

I think all is OK here now.

Re-opening - hewiki wmf.35 shows a spike of such errors (total count:1430)- https://logstash.wikimedia.org/app/dashboards#/view/AWl4jlZ78aQffZ3Ho7BV?_g=h@a91e569&_a=h@8dca6aa

Screen Shot 2021-03-17 at 1.37.13 PM.png (303×1 px, 67 KB)

This issue has a different stack trace, so it probably deserves its own issue. The underlying cause of the problems here seems to code added for T274179: Deprecate and remove UserIdentity::getActorId() which is supposed to be removed soon:

/**
	 * Sets the actor id.
	 *
	 * This method is deprecated upon introduction. It only exists for transition to ActorStore,
	 * and will be removed shortly - T274148
	 *
	 * @internal
	 * @deprecated since 1.36
	 * @param int $actorId
	 */
	public function setActorId( int $actorId ) {
		$this->mActorId = $actorId;
		$this->invalidateCache();
		$this->setItemLoaded( 'actor' );
	}

The invalidateCache() line seems to be what leads to a connection to the main DB.

Maybe this is solved by https://gerrit.wikimedia.org/r/c/mediawiki/extensions/GrowthExperiments/+/672802, not sure how the new mechanism interacts with the cache.

It's not, that just skips one level of indirection in the stack.

I think this is actually a core bug of sorts (it should call $this->clearSharedCache( 'refresh' ) since the change to the user object is immediate and hasn't got anything to do with the transaction) but as you say the whole mechanism is a temporary hack so we should just ignore it IMO.

(And even if we didn't want to ignore it, I don't think there's much we could do about it.)

Krinkle renamed this task from Expectation (masterConns <= 0) by ApiMain::setRequestExpectations not met (actual: 1):[connect to 10.64.48.35 (testwiki)] to Expectation (masterConns <= 0) not met (via GrowthExperimentsLinkRecommendationStore constructor).Mar 25 2021, 3:00 AM

Change 674746 had a related patch set uploaded (by Krinkle; author: Krinkle):
[mediawiki/core@master] rdbms: Group DBPerformance logs by violated measure (take 2)

https://gerrit.wikimedia.org/r/674746