Page MenuHomePhabricator
Create Task
Maniphest T274455

AbuseFilter DB writes to af_hit_count during action=raw page views
Closed, ResolvedPublic
Actions

Description

From the DBPerformance log channel:

message:
Expectation (writes <= 0) by MediaWiki::main not met (actual: 5):
query-m: UPDATE `abuse_filter` SET af_hit_count=af_hit_count+N WHERE af_id = N [TRX#14c379]

backtrace:
from /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/TransactionProfiler.php(378)
#0 /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/TransactionProfiler.php(250): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated(string, Wikimedia\Rdbms\GeneralizedSql, integer)
#1 /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/database/Database.php(1415): Wikimedia\Rdbms\TransactionProfiler->recordQueryCompletion(Wikimedia\Rdbms\GeneralizedSql, double, boolean, integer)
#2 /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/database/Database.php(1297): Wikimedia\Rdbms\Database->executeQueryAttempt(string, string, boolean, string, integer)
#3 /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/database/Database.php(1226): Wikimedia\Rdbms\Database->executeQuery(string, string, integer)
#4 /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/database/Database.php(2460): Wikimedia\Rdbms\Database->query(string, string, integer)
#5 /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/database/DBConnRef.php(68): Wikimedia\Rdbms\Database->update(string, array, string, string)
#6 /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/database/DBConnRef.php(375): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#7 /srv/mediawiki/php-1.36.0-wmf.27/extensions/AbuseFilter/includes/Watcher/UpdateHitCountWatcher.php(58): Wikimedia\Rdbms\DBConnRef->update(string, array, array, string)
#8 /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/database/Database.php(4188): MediaWiki\Extension\AbuseFilter\Watcher\UpdateHitCountWatcher->MediaWiki\Extension\AbuseFilter\Watcher\{closure}(Wikimedia\Rdbms\DatabaseMysqli)
#9 /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/loadbalancer/LoadBalancer.php(1675): Wikimedia\Rdbms\Database->runOnTransactionPreCommitCallbacks()
#10 /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/loadbalancer/LoadBalancer.php(2216): Wikimedia\Rdbms\LoadBalancer->Wikimedia\Rdbms\{closure}(Wikimedia\Rdbms\DatabaseMysqli)
#11 /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/loadbalancer/LoadBalancer.php(1676): Wikimedia\Rdbms\LoadBalancer->forEachOpenMasterConnection(Closure)
#12 /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/lbfactory/LBFactory.php(305): Wikimedia\Rdbms\LoadBalancer->finalizeMasterChanges(string, integer)
#13 /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/lbfactory/LBFactoryMulti.php(222): Wikimedia\Rdbms\LBFactory->Wikimedia\Rdbms\{closure}(Wikimedia\Rdbms\LoadBalancer)
#14 /srv/mediawiki/php-1.36.0-wmf.27/includes/libs/rdbms/lbfactory/LBFactory.php(306): Wikimedia\Rdbms\LBFactoryMulti->forEachLB(Closure)
#15 /srv/mediawiki/php-1.36.0-wmf.27/includes/MediaWiki.php(683): Wikimedia\Rdbms\LBFactory->commitMasterChanges(string, array)
#16 /srv/mediawiki/php-1.36.0-wmf.27/includes/MediaWiki.php(653): MediaWiki::preOutputCommit(RequestContext, Closure)
#17 /srv/mediawiki/php-1.36.0-wmf.27/includes/MediaWiki.php(960): MediaWiki->doPreOutputCommit(Closure)
#18 /srv/mediawiki/php-1.36.0-wmf.27/includes/MediaWiki.php(548): MediaWiki->main()
#19 /srv/mediawiki/php-1.36.0-wmf.27/index.php(53): MediaWiki->run()
#20 /srv/mediawiki/php-1.36.0-wmf.27/index.php(46): wfIndexMain()
#21 /srv/mediawiki/w/index.php(3): require(string)
#22 {main}

url:
/wiki/Caracalla
	
wiki:
itwiki

I also saw URLs like 'https://en.wikisource.org/w/index.php?title=MediaWiki:Base.js&action=raw&ctype=text/javascript'

These updates should use the job queue.

Details

SubjectRepoBranchLines +/-
Update hit counts in a DeferredUpdatemediawiki/extensions/AbuseFilterwmf/1.36.0-wmf.32+19 -24
Update hit counts in a DeferredUpdatemediawiki/extensions/AbuseFiltermaster+19 -24
Customize query in gerrit

Related Objects

Event Timeline

aaron created this task.Feb 10 2021, 11:58 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptFeb 10 2021, 11:58 PM
aaron added a comment.EditedFeb 11 2021, 12:03 AM

Possibly triggered by MediaWiki\Auth\AuthManager->autoCreateUser calls, which I also see in the logging for the same reqId.

from /srv/mediawiki/php-1.36.0-wmf.27/includes/user/User.php(341)
#0 /srv/mediawiki/php-1.36.0-wmf.27/includes/user/User.php(2041): User->load()
#1 /srv/mediawiki/php-1.36.0-wmf.27/includes/user/User.php(2979): User->getId()
#2 /srv/mediawiki/php-1.36.0-wmf.27/includes/user/UserOptionsManager.php(606): User->isRegistered()
#3 /srv/mediawiki/php-1.36.0-wmf.27/includes/user/UserOptionsManager.php(491): MediaWiki\User\UserOptionsManager->canUseCachedValues(User, integer)
#4 /srv/mediawiki/php-1.36.0-wmf.27/includes/user/UserOptionsManager.php(138): MediaWiki\User\UserOptionsManager->loadUserOptions(User, integer)
#5 /srv/mediawiki/php-1.36.0-wmf.27/includes/user/UserOptionsLookup.php(123): MediaWiki\User\UserOptionsManager->getOption(User, string, integer, boolean, integer)
#6 /srv/mediawiki/php-1.36.0-wmf.27/includes/user/User.php(2628): MediaWiki\User\UserOptionsLookup->getIntOption(User, string, integer)
#7 /srv/mediawiki/php-1.36.0-wmf.27/includes/user/User.php(2820): User->getIntOption(string)
#8 /srv/mediawiki/php-1.36.0-wmf.27/includes/linker/LinkRendererFactory.php(99): User->getStubThreshold()
#9 /srv/mediawiki/php-1.36.0-wmf.27/includes/ServiceWiring.php(626): MediaWiki\Linker\LinkRendererFactory->createForUser(User)
#10 /srv/mediawiki/php-1.36.0-wmf.27/vendor/wikimedia/services/src/ServiceContainer.php(447): Wikimedia\Services\ServiceContainer->{closure}(MediaWiki\MediaWikiServices)
#11 /srv/mediawiki/php-1.36.0-wmf.27/vendor/wikimedia/services/src/ServiceContainer.php(416): Wikimedia\Services\ServiceContainer->createService(string)
#12 /srv/mediawiki/php-1.36.0-wmf.27/includes/MediaWikiServices.php(889): Wikimedia\Services\ServiceContainer->getService(string)
#13 /srv/mediawiki/php-1.36.0-wmf.27/includes/logging/LogFormatter.php(148): MediaWiki\MediaWikiServices->getLinkRenderer()
#14 /srv/mediawiki/php-1.36.0-wmf.27/extensions/AbuseFilter/includes/LogFormatter/AbuseLogHitFormatter.php(22): LogFormatter->getLinkRenderer()
#15 /srv/mediawiki/php-1.36.0-wmf.27/includes/logging/LogFormatter.php(491): MediaWiki\Extension\AbuseFilter\LogFormatter\AbuseLogHitFormatter->getMessageParameters()
#16 /srv/mediawiki/php-1.36.0-wmf.27/includes/logging/LogFormatter.php(466): LogFormatter->getActionMessage()
#17 /srv/mediawiki/php-1.36.0-wmf.27/includes/logging/LogFormatter.php(214): LogFormatter->getActionText()
#18 /srv/mediawiki/php-1.36.0-wmf.27/extensions/CheckUser/includes/CheckUserHooks.php(109): LogFormatter->getPlainActionText()
#19 /srv/mediawiki/php-1.36.0-wmf.27/extensions/AbuseFilter/includes/AbuseLogger.php(252): CheckUserHooks::updateCheckUserData(RecentChange)
#20 /srv/mediawiki/php-1.36.0-wmf.27/extensions/AbuseFilter/includes/AbuseLogger.php(161): MediaWiki\Extension\AbuseFilter\AbuseLogger->insertLocalLogEntries(array, Wikimedia\Rdbms\DBConnRef)
#21 /srv/mediawiki/php-1.36.0-wmf.27/extensions/AbuseFilter/includes/FilterRunner.php(288): MediaWiki\Extension\AbuseFilter\AbuseLogger->addLogEntries(array)
#22 /srv/mediawiki/php-1.36.0-wmf.27/extensions/AbuseFilter/includes/AbuseFilterPreAuthenticationProvider.php(56): MediaWiki\Extension\AbuseFilter\FilterRunner->run()
#23 /srv/mediawiki/php-1.36.0-wmf.27/extensions/AbuseFilter/includes/AbuseFilterPreAuthenticationProvider.php(32): MediaWiki\Extension\AbuseFilter\AbuseFilterPreAuthenticationProvider->testUser(User, User, boolean)
#24 /srv/mediawiki/php-1.36.0-wmf.27/includes/auth/AuthManager.php(1712): MediaWiki\Extension\AbuseFilter\AbuseFilterPreAuthenticationProvider->testUserForCreation(User, string, array)
#25 /srv/mediawiki/php-1.36.0-wmf.27/includes/Setup.php(816): MediaWiki\Auth\AuthManager->autoCreateUser(User, string, boolean)
#26 /srv/mediawiki/php-1.36.0-wmf.27/includes/WebStart.php(89): require_once(string)
#27 /srv/mediawiki/php-1.36.0-wmf.27/index.php(44): require(string)
#28 /srv/mediawiki/w/index.php(3): require(string)
#29 {main}
aaron updated the task description. (Show Details)Feb 11 2021, 12:26 AM
Daimona subscribed.Feb 11 2021, 5:46 PM
In T274455#6820953, @aaron wrote:

Possibly triggered by MediaWiki\Auth\AuthManager->autoCreateUser calls, which I also see in the logging for the same reqId.

Yes, autocreation is the only situation when filters can be executed for a similar request.

Krinkle added a project: Sustainability (MediaWiki-MultiDC).Feb 11 2021, 9:16 PM
Krinkle subscribed.Feb 11 2021, 9:26 PM

@Daimona Could this be moved to a queued job, or at least a post-send deferred update?

RhinosF1 subscribed.Feb 11 2021, 9:29 PM
Daimona added a comment.Feb 11 2021, 10:06 PM
In T274455#6824721, @Krinkle wrote:

@Daimona Could this be moved to a queued job, or at least a post-send deferred update?

Absolutely, this is not critical for the request. In fact, I thought it was already happening in a deferred update.

gerritbot added a comment.Feb 12 2021, 1:15 PM

Change 663825 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Update hit counts in a DeferredUpdate

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

gerritbot added a project: Patch-For-Review.Feb 12 2021, 1:15 PM
Daimona claimed this task.Feb 12 2021, 1:18 PM
Krinkle moved this task from Inbox, needs triage to Radar on the Performance-Team board.Feb 13 2021, 3:54 AM
Krinkle edited projects, added Performance-Team (Radar); removed Performance-Team.
gerritbot added a comment.Feb 23 2021, 6:12 AM

Change 666084 had a related patch set uploaded (by Krinkle; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@wmf/1.36.0-wmf.32] Update hit counts in a DeferredUpdate

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

Krinkle moved this task from Limbo to Perf recommendation on the Performance-Team (Radar) board.Feb 23 2021, 6:12 AM
gerritbot added a comment.Feb 23 2021, 6:34 AM

Change 663825 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Update hit counts in a DeferredUpdate

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

ReleaseTaggerBot added a project: MW-1.36-notes (1.36.0-wmf.33; 2021-03-02).Feb 23 2021, 10:00 PM
gerritbot added a comment.Feb 24 2021, 1:25 AM

Change 666084 abandoned by Krinkle:
[mediawiki/extensions/AbuseFilter@wmf/1.36.0-wmf.32] Update hit counts in a DeferredUpdate

Reason:

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

Daimona closed this task as Resolved.Feb 26 2021, 6:16 PM
Krinkle mentioned this in T254634: Determine and implement multi-dc strategy for ChronologyProtector.Mar 1 2021, 7:00 PM
Maintenance_bot removed a project: Patch-For-Review.Mar 12 2021, 9:55 AM
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 · Credits