Page MenuHomePhabricator

OATHManage special page causes TransactionProfiler warnings
Closed, ResolvedPublic

Description

Summary

The integration of the Special:OATHManage special page and CheckUser causes TransactionProfiler warnings. These should be addressed.

Background & Technical details

message
Expectation (writes <= 0) by MediaWiki\SpecialPage\SpecialPageFactory::executePath not met (actual: 3) in trx #7003b77cde:
role-primary: INSERT INTO `cu_private_event` (cupe_namespace,cupe_title,cupe_log_type,cupe_log_action,cupe_params,cupe_page,cupe_actor,cupe_timestamp,cupe_ip_hex,cupe_xff,cupe_xff_hex,cupe_comment_id,cupe_agent_id) VALUES '?'
trace
from /srv/mediawiki/php-1.46.0-wmf.15/includes/libs/Rdbms/TransactionProfiler.php(569)
#0 /srv/mediawiki/php-1.46.0-wmf.15/includes/libs/Rdbms/TransactionProfiler.php(371): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated(string, Wikimedia\Rdbms\GeneralizedSql, int, string, string)
#1 /srv/mediawiki/php-1.46.0-wmf.15/includes/libs/Rdbms/Database/TransactionManager.php(571): Wikimedia\Rdbms\TransactionProfiler->recordQueryCompletion(Wikimedia\Rdbms\GeneralizedSql, float, bool, int, string, string)
#2 /srv/mediawiki/php-1.46.0-wmf.15/includes/libs/Rdbms/Database/Database.php(847): Wikimedia\Rdbms\TransactionManager->recordQueryCompletion(Wikimedia\Rdbms\GeneralizedSql, float, bool, int, string)
#3 /srv/mediawiki/php-1.46.0-wmf.15/includes/libs/Rdbms/Database/Database.php(705): Wikimedia\Rdbms\Database->attemptQuery(Wikimedia\Rdbms\Query, string, bool)
#4 /srv/mediawiki/php-1.46.0-wmf.15/includes/libs/Rdbms/Database/Database.php(632): Wikimedia\Rdbms\Database->executeQuery(Wikimedia\Rdbms\Query, string, int)
#5 /srv/mediawiki/php-1.46.0-wmf.15/includes/libs/Rdbms/Database/Database.php(1506): Wikimedia\Rdbms\Database->query(Wikimedia\Rdbms\Query, string)
#6 /srv/mediawiki/php-1.46.0-wmf.15/includes/libs/Rdbms/Database/DBConnRef.php(129): Wikimedia\Rdbms\Database->insert(string, array, string, array)
#7 /srv/mediawiki/php-1.46.0-wmf.15/includes/libs/Rdbms/Database/DBConnRef.php(457): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#8 /srv/mediawiki/php-1.46.0-wmf.15/includes/libs/Rdbms/QueryBuilder/InsertQueryBuilder.php(317): Wikimedia\Rdbms\DBConnRef->insert(string, array, string, array)
#9 /srv/mediawiki/php-1.46.0-wmf.15/extensions/CheckUser/src/Services/CheckUserInsert.php(436): Wikimedia\Rdbms\InsertQueryBuilder->execute()
#10 /srv/mediawiki/php-1.46.0-wmf.15/extensions/CheckUser/src/Services/CheckUserInsert.php(180): MediaWiki\CheckUser\Services\CheckUserInsert->insertIntoCuPrivateEventTable(array, string, MediaWiki\User\User, MediaWiki\RecentChanges\RecentChange, bool)
#11 /srv/mediawiki/php-1.46.0-wmf.15/extensions/OATHAuth/src/OATHUserRepository.php(149): MediaWiki\CheckUser\Services\CheckUserInsert->updateCheckUserData(MediaWiki\RecentChanges\RecentChange)
#12 /srv/mediawiki/php-1.46.0-wmf.15/extensions/OATHAuth/src/Module/RecoveryCodes.php(110): MediaWiki\Extension\OATHAuth\OATHUserRepository->createKey(MediaWiki\Extension\OATHAuth\OATHUser, MediaWiki\Extension\OATHAuth\Module\RecoveryCodes, array, string)
#13 /srv/mediawiki/php-1.46.0-wmf.15/extensions/OATHAuth/src/HTMLForm/TOTPEnableForm.php(197): MediaWiki\Extension\OATHAuth\Module\RecoveryCodes->ensureExistence(MediaWiki\Extension\OATHAuth\OATHUser, array)
#14 /srv/mediawiki/php-1.46.0-wmf.15/includes/HTMLForm/HTMLForm.php(820): MediaWiki\Extension\OATHAuth\HTMLForm\TOTPEnableForm->onSubmit(array, MediaWiki\Extension\OATHAuth\HTMLForm\TOTPEnableForm)
#15 /srv/mediawiki/php-1.46.0-wmf.15/includes/HTMLForm/HTMLForm.php(669): MediaWiki\HTMLForm\HTMLForm->trySubmit()
#16 /srv/mediawiki/php-1.46.0-wmf.15/includes/HTMLForm/HTMLForm.php(717): MediaWiki\HTMLForm\HTMLForm->tryAuthorizedSubmit()
#17 /srv/mediawiki/php-1.46.0-wmf.15/extensions/OATHAuth/src/HTMLForm/OATHAuthOOUIHTMLForm.php(53): MediaWiki\HTMLForm\HTMLForm->show()
#18 /srv/mediawiki/php-1.46.0-wmf.15/extensions/OATHAuth/src/Special/OATHManage.php(485): MediaWiki\Extension\OATHAuth\HTMLForm\OATHAuthOOUIHTMLForm->show(null)
#19 /srv/mediawiki/php-1.46.0-wmf.15/extensions/OATHAuth/src/Special/OATHManage.php(401): MediaWiki\Extension\OATHAuth\Special\OATHManage->addCustomContent(MediaWiki\Extension\OATHAuth\Module\TOTP)
#20 /srv/mediawiki/php-1.46.0-wmf.15/extensions/OATHAuth/src/Special/OATHManage.php(96): MediaWiki\Extension\OATHAuth\Special\OATHManage->addModuleHTML(MediaWiki\Extension\OATHAuth\Module\TOTP)
#21 /srv/mediawiki/php-1.46.0-wmf.15/includes/SpecialPage/SpecialPage.php(711): MediaWiki\Extension\OATHAuth\Special\OATHManage->execute(null)
#22 /srv/mediawiki/php-1.46.0-wmf.15/includes/SpecialPage/SpecialPageFactory.php(1745): MediaWiki\SpecialPage\SpecialPage->run(null)
#23 /srv/mediawiki/php-1.46.0-wmf.15/includes/Actions/ActionEntryPoint.php(504): MediaWiki\SpecialPage\SpecialPageFactory->executePath(string, MediaWiki\Context\RequestContext)
#24 /srv/mediawiki/php-1.46.0-wmf.15/includes/Actions/ActionEntryPoint.php(144): MediaWiki\Actions\ActionEntryPoint->performRequest()
#25 /srv/mediawiki/php-1.46.0-wmf.15/includes/MediaWikiEntryPoint.php(180): MediaWiki\Actions\ActionEntryPoint->execute()
#26 /srv/mediawiki/php-1.46.0-wmf.15/index.php(44): MediaWiki\MediaWikiEntryPoint->run()
#27 /srv/mediawiki/w/index.php(3): require(string)
#28 {main}

Acceptance criteria

  • These warnings are no longer created

Event Timeline

Seen 289 of these warnings in the last week. https://logstash.wikimedia.org/goto/9cfdc4c087d121f746b81f7078ba454a shows all these logs

Catrope and mmartorana, can you address these logs please. It should be fine to either ignore the primary DB warnings if they are expected and/or create the CheckUser row in a deferred update. See https://gerrit.wikimedia.org/g/mediawiki/extensions/AbuseFilter/+/6719e77ec081932b6c88e3cbe05376768654b9b4/includes/AbuseLogger.php#204 for an example of this being addressed

I presume that this special page cannot be a POST request, which is the only way to address these logs without specifically ignoring them

I think the root cause of this is the call to RecoveryCodes->ensureExistence in a GET request when the special page is viewed. This conditionally calls OATHUserRepository->createKey, which also does a write query. This doesn't appear in the logs because only the last write query is logged, but the (actual: 3) part tells you there were three write queries (not sure what the third is).

We should address this in two ways:

  • Don't log to CheckUser when the user creates a RecoveryCodes instance (or generally, a key whose module's ->isSpecial() returns true). It's just noise, it doesn't correspond to what we want to log. This won't make the problem go away, but it'll move it out of CheckUser-land and off your dashboard.
  • Somehow move the creation of the RecoveryCodes instance into a DeferredUpdate. Right now the way ensureExistence works doesn't really support that because it can't return null, so we'll have to find another way.
  • Somehow move the creation of the RecoveryCodes instance into a DeferredUpdate. Right now the way ensureExistence works doesn't really support that because it can't return null, so we'll have to find another way.

Thanks. I would note that DeferredUpdates don't fully suppress the warnings as PostSend-GET still expects no writes to the DB, so it would need to be coupled with suppressing transaction profiler warnings

I was totally wrong about the causes of this. I just noticed this in the stack trace:

#14 /srv/mediawiki/php-1.46.0-wmf.15/includes/HTMLForm/HTMLForm.php(820): MediaWiki\Extension\OATHAuth\HTMLForm\TOTPEnableForm->onSubmit(array, MediaWiki\Extension\OATHAuth\HTMLForm\TOTPEnableForm)

And looking back at the Logstash event linked in the task description:

http_method: POST

It looks like we never set doesWrites() to return true in SpecialOATHManage, that's what causes this. It would have been throwing these false warnings for OATHAuth's entire existence, even before multiple authenticators.

Change #1243173 had a related patch set uploaded (by Catrope; author: Catrope):

[mediawiki/extensions/OATHAuth@master] OATHManage: Declare that this special page does writes

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

Change #1243173 merged by jenkins-bot:

[mediawiki/extensions/OATHAuth@master] OATHManage: Declare that this special page does writes

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