Page MenuHomePhabricator

Special:CreateAccount causes ApiValidatePassword to log a DBPerformance warning from CentralAuth
Open, Needs TriagePublic

Description

Error

At 120,00 log entries in 7 days (~20 to 100x per minute) with this description, this is one of the most frequent and noisiest logs in the system right now.

https://logstash.wikimedia.org/goto/84ab7b3f6e1019171a0e10ebcd6edad4

```name=stack trace
Expectation (masterConns <= 0) by ApiMain::setRequestExpectations not met (actual: 1):
[connect to 10.64.48.15 (centralauth)]
#0 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/rdbms/TransactionProfiler.php(165): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated()
#1 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/rdbms/loadbalancer/LoadBalancer.php(776): Wikimedia\Rdbms\TransactionProfiler->recordConnection()
#2 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/rdbms/loadbalancer/LoadBalancer.php(850): Wikimedia\Rdbms\LoadBalancer->getConnection()
#3 /srv/mediawiki/php-1.32.0-wmf.19/extensions/CentralAuth/includes/CentralAuthUtils.php(57): Wikimedia\Rdbms\LoadBalancer->getConnectionRef()
#4 /srv/mediawiki/php-1.32.0-wmf.19/extensions/CentralAuth/includes/CentralAuthUser.php(224): CentralAuthUtils::getCentralDB()
#5 /srv/mediawiki/php-1.32.0-wmf.19/extensions/CentralAuth/includes/CentralAuthUser.php(433): CentralAuthUser->getSafeReadDB()
#6 /srv/mediawiki/php-1.32.0-wmf.19/extensions/CentralAuth/includes/CentralAuthUser.php(376): CentralAuthUser->loadFromDatabase()
#7 /srv/mediawiki/php-1.32.0-wmf.19/extensions/CentralAuth/includes/CentralAuthUser.php(597): CentralAuthUser->loadState()
#8 /srv/mediawiki/php-1.32.0-wmf.19/extensions/CentralAuth/includes/CentralAuthHooks.php(813): CentralAuthUser->isAttached()
#9 /srv/mediawiki/php-1.32.0-wmf.19/includes/Hooks.php(174): CentralAuthHooks::onUserSetEmail()
#10 /srv/mediawiki/php-1.32.0-wmf.19/includes/Hooks.php(202): Hooks::callHook()
#11 /srv/mediawiki/php-1.32.0-wmf.19/includes/user/User.php(3059): Hooks::run()
#12 /srv/mediawiki/php-1.32.0-wmf.19/includes/api/ApiValidatePassword.php(30): User->setEmail()
#13 /srv/mediawiki/php-1.32.0-wmf.19/includes/api/ApiMain.php(1587): ApiValidatePassword->execute()
#14 /srv/mediawiki/php-1.32.0-wmf.19/includes/api/ApiMain.php(531): ApiMain->executeAction()
#15 /srv/mediawiki/php-1.32.0-wmf.19/includes/api/ApiMain.php(502): ApiMain->executeActionWithErrorHandling()
#16 /srv/mediawiki/php-1.32.0-wmf.19/api.php(87): ApiMain->execute()
#17 /srv/mediawiki/w/api.php(3): include()
#18 {main}

Notes

The above sample:

It seems to be like this warning is a false negative, given that a master connection during a POST request would normally be acceptable.

Also, it seems this error was previously reported in June 2017 and seemingly fixed:

Change 348658 merged by jenkins-bot:
[mediawiki/extensions/CentralAuth@master] Avoid triggering master queries in ApiValidatePassword

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

Event Timeline

Krinkle created this task.Aug 31 2018, 9:21 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptAug 31 2018, 9:21 PM
Krinkle updated the task description. (Show Details)Aug 31 2018, 9:24 PM
Krinkle updated the task description. (Show Details)
Anomie added a subscriber: Anomie.Sep 4 2018, 1:51 PM

It looks like CentralAuthHooks::onUserSetEmail() may need the same treatment that was given to CentralAuthHooks::onUserSetEmailAuthenticationTimestamp() in rECAU0416f276fd67: Avoid triggering master queries in ApiValidatePassword.

I don't see any stack traces in that patch or in the linked task, so I'm not sure why 0416f27 did onUserSetEmailAuthenticationTimestamp rather than onUserSetEmail in the first place.