Page MenuHomePhabricator
Create Task
Maniphest T276307

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

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}
SubjectRepoBranchLines +/-
Do not open DB connections during service initializationmediawiki/extensions/GrowthExperimentsmaster+2 -2
Do not open DB connections during service initializationmediawiki/extensions/GrowthExperimentswmf/1.36.0-wmf.33+2 -2
Customize query in gerrit

Related Objects

Event Timeline

kostajh created this task.Mar 3 2021, 10:05 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMar 3 2021, 10:05 AM
kostajh added a subscriber: Tgr.Mar 3 2021, 10:07 AM
'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?

kostajh moved this task from Incoming to Ready for Development on the Growth-Team (Sprint 0 (Growth Team)) board.Mar 3 2021, 10:07 AM
gerritbot added a comment.Mar 3 2021, 10:36 AM

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

gerritbot added a project: Patch-For-Review.Mar 3 2021, 10:36 AM
Tgr added a comment.Mar 3 2021, 10:37 AM
In T276307#6877816, @kostajh wrote:

@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.

Tgr claimed this task.Mar 3 2021, 10:39 AM
Tgr moved this task from Ready for Development to Code Review on the Growth-Team (Sprint 0 (Growth Team)) board.
gerritbot added a comment.Mar 3 2021, 11:57 AM

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

kostajh mentioned this in T274937: 1.36.0-wmf.33 deployment blockers.Mar 3 2021, 12:00 PM
gerritbot added a comment.Mar 3 2021, 12:12 PM

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

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

RhinosF1 subscribed.Mar 3 2021, 12:13 PM
• LarsWirzenius subscribed.Mar 3 2021, 12:17 PM

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

gerritbot added a comment.Mar 3 2021, 12:18 PM

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

kostajh added a comment.Mar 3 2021, 12:18 PM
In T276307#6878269, @LarsWirzenius wrote:

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

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

Urbanecm_WMF triaged this task as High priority.Mar 3 2021, 12:22 PM
Stashbot added a comment.Mar 3 2021, 12:29 PM

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 closed this task as Resolved.Mar 3 2021, 12:37 PM
kostajh moved this task from Code Review to QA on the Growth-Team (Sprint 0 (Growth Team)) board.

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

I think all is OK here now.

• LarsWirzenius added a comment.Mar 3 2021, 12:39 PM

Thanks, @kostajh !

ReleaseTaggerBot added a project: MW-1.36-notes (1.36.0-wmf.33; 2021-03-02).Mar 3 2021, 1:00 PM
Maintenance_bot removed a project: Patch-For-Review.Mar 3 2021, 1:10 PM
Etonkovidova reopened this task as Open.Mar 17 2021, 8:41 PM
Etonkovidova moved this task from QA to Test in Production | Watching on the Growth-Team (Sprint 0 (Growth Team)) board.
Etonkovidova subscribed.

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)

kostajh added a comment.Mar 17 2021, 9:39 PM
In T276307#6922995, @Etonkovidova wrote:

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.

kostajh added a comment.Mar 17 2021, 10:01 PM

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.

Tgr added a comment.Mar 17 2021, 11:10 PM
In T276307#6923235, @kostajh wrote:

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.

Tgr added a comment.Mar 17 2021, 11:12 PM

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

• LarsWirzenius unsubscribed.Mar 18 2021, 1:14 PM
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
gerritbot added a comment.Mar 25 2021, 3:09 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

gerritbot added a project: Patch-For-Review.Mar 25 2021, 3:09 AM
Tgr closed this task as Resolved.Mar 25 2021, 9:44 AM

Closing per T276307#6878344 and T276307#6923173.

Krinkle moved this task from Untriaged to Mar 2021 on the Wikimedia-production-error board.Apr 21 2022, 8:11 PM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL