Page MenuHomePhabricator
Create Task
Maniphest T204228

DBQueryTimeoutError on Special:AbuseFilter/test
Closed, ResolvedPublic
Actions

Description

I was testing an AbuseFilter rule on itwiki, and specified in the form an username and selected the option to only show account creations. The user only had a single edit, so I expected a relatively quick query. However, after some time, I got the following error:

MediaWiki internal error.

Original exception: [W5pXBgrAEEYAAHVt@m4AAADX] 2018-09-13 12:25:39: Fatal exception of type "Wikimedia\Rdbms\DBQueryTimeoutError"

Exception caught inside exception handler.

Set $wgShowExceptionDetails = true; at the bottom of LocalSettings.php to show detailed debugging information.

I'd like to see the query that caused the timeout, to see if it's generated wrongly, or if it needs a performance boost in other ways.

Event Timeline

Daimona created this task.Sep 13 2018, 12:29 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 13 2018, 12:29 PM
Daimona triaged this task as High priority.Sep 13 2018, 12:29 PM
Krinkle added a subscriber: Krinkle.Sep 13 2018, 11:03 PM

reqId: W5pXBgrAEEYAAHVt@m4AAADX

channel: exception
A database query timeout has occurred. 
Query: SELECT  rc_id,rc_timestamp,rc_namespace,rc_title,rc_minor,rc_bot,rc_new,rc_cur_id,rc_this_oldid,rc_last_oldid,rc_type,rc_source,rc_patrolled,rc_ip,rc_old_len,rc_new_len,rc_deleted,rc_logid,rc_log_type,rc_log_action,rc_params,COALESCE( comment_rc_comment.comment_text, rc_comment ) AS `rc_comment_text`,comment_rc_comment.comment_data AS `rc_comment_data`,comment_rc_comment.comment_id AS `rc_comment_cid`,rc_user,rc_user_text,NULL AS `rc_actor`  FROM `recentchanges` LEFT JOIN `comment` `comment_rc_comment` ON ((comment_rc_comment.comment_id = rc_comment_id))   WHERE ((rc_user = '###')) AND (rc_source = 'mw.log' AND rc_log_type = 'newusers' AND rc_log_action = 'create')  ORDER BY rc_timestamp desc LIMIT 100  
Function: AbuseFilterViewTestBatch::doTest
Error: 2062 Read timeout is reached (10.192.32.12)

#0 /srv/mediawiki/php-1.32.0-wmf.20/includes/libs/rdbms/database/Database.php(1428): Wikimedia\Rdbms\Database->makeQueryException(string, integer, string, string)
#1 /srv/mediawiki/php-1.32.0-wmf.20/includes/libs/rdbms/database/Database.php(1198): Wikimedia\Rdbms\Database->reportQueryError(string, integer, string, string, boolean)
#2 /srv/mediawiki/php-1.32.0-wmf.20/includes/libs/rdbms/database/Database.php(1655): Wikimedia\Rdbms\Database->query(string, string)
#3 /srv/mediawiki/php-1.32.0-wmf.20/extensions/AbuseFilter/includes/Views/AbuseFilterViewTestBatch.php(185): Wikimedia\Rdbms\Database->select(array, array, array, string, array, array)
#4 /srv/mediawiki/php-1.32.0-wmf.20/extensions/AbuseFilter/includes/Views/AbuseFilterViewTestBatch.php(119): AbuseFilterViewTestBatch->doTest()
#5 /srv/mediawiki/php-1.32.0-wmf.20/extensions/AbuseFilter/includes/special/SpecialAbuseFilter.php(122): AbuseFilterViewTestBatch->show()
#6 /srv/mediawiki/php-1.32.0-wmf.20/includes/specialpage/SpecialPage.php(569): SpecialAbuseFilter->execute(string)
#7 /srv/mediawiki/php-1.32.0-wmf.20/includes/specialpage/SpecialPageFactory.php(581): SpecialPage->run(string)
#8 /srv/mediawiki/php-1.32.0-wmf.20/includes/MediaWiki.php(288): MediaWiki\Special\SpecialPageFactory->executePath(Title, RequestContext)
#9 /srv/mediawiki/php-1.32.0-wmf.20/includes/MediaWiki.php(868): MediaWiki->performRequest()
#10 /srv/mediawiki/php-1.32.0-wmf.20/includes/MediaWiki.php(525): MediaWiki->main()
#11 /srv/mediawiki/php-1.32.0-wmf.20/index.php(42): MediaWiki->run()
channel: DBPerformance
Expectation (readQueryTime <= 5) by MediaWiki::main not met (actual: 60.060605049133):
query: SELECT rc_id,rc_timestamp,rc_namespace,rc_title,rc_minor,rc_bot,rc_new,rc_cur_id,rc_this_oldid,rc_last_oldid,rc_type,rc_source,rc_patrolled,rc_ip,rc_old_len,rc_new_len,rc_deleted,rc_logid,rc_log_type,rc_log_action,rc_params,COALESCE( comment_rc_comment.co [TRX#a9c639]
#0 /srv/mediawiki/php-1.32.0-wmf.20/includes/libs/rdbms/TransactionProfiler.php(228): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated()
#1 /srv/mediawiki/php-1.32.0-wmf.20/includes/libs/rdbms/database/Database.php(1258): Wikimedia\Rdbms\TransactionProfiler->recordQueryCompletion()
#2 /srv/mediawiki/php-1.32.0-wmf.20/includes/libs/rdbms/database/Database.php(1155): Wikimedia\Rdbms\Database->doProfiledQuery()
#3 /srv/mediawiki/php-1.32.0-wmf.20/includes/libs/rdbms/database/Database.php(1655): Wikimedia\Rdbms\Database->query()
#4 /srv/mediawiki/php-1.32.0-wmf.20/extensions/AbuseFilter/includes/Views/AbuseFilterViewTestBatch.php(185): Wikimedia\Rdbms\Database->select()
#5 /srv/mediawiki/php-1.32.0-wmf.20/extensions/AbuseFilter/includes/Views/AbuseFilterViewTestBatch.php(119): AbuseFilterViewTestBatch->doTest()
Daimona lowered the priority of this task from High to Low.Sep 14 2018, 11:06 AM

Hmm the query seems normal. Might this be caused by a temporary DB overload? After all, I managed to get the results of the same query in a couple of seconds some time later.

Daimona raised the priority of this task from Low to Medium.Sep 18 2018, 8:38 AM

I experienced this problem again, more than once. It's really annoying, and the query probably needs some tweaking.

abian added a subscriber: abian.EditedSep 23 2018, 10:54 AM

Today on Wikidata...

MediaWiki internal error.

Original exception: [W6dwOgrAAD8AAJHtzMoAAABI] 2018-09-23 10:52:39: Fatal exception of type "Wikimedia\Rdbms\DBQueryTimeoutError"

Exception caught inside exception handler.

Set $wgShowExceptionDetails = true; at the bottom of LocalSettings.php to show detailed debugging information.

https://www.wikidata.org/wiki/Special:AbuseFilter/96 should have prevented https://www.wikidata.org/?diff=749441379, but it didn't.

Daimona added a comment.EditedSep 23 2018, 11:14 AM

@abian I don't think that a filter failure would be related. The error from this task is only related to Special:AbuseFilter/test. @Krinkle may you please check the stacktrace of the error above?

As for why the filter didn't match, check added_lines... They don't have the property name. I don't know why, but it shouldn't surely happen.

Krinkle added a comment.Sep 23 2018, 5:56 PM
In T204228#4608845, @abian wrote:

Today on Wikidata...

Original exception: [W6dwOgrAAD8AAJHtzMoAAABI] 2018-09-23 10:52:39: Fatal exception of type "Wikimedia\Rdbms\DBQueryTimeoutError"
channellevelmessage
DBQueryERRORAbuseFilterViewTestBatch::doTest ## Read timeout is reached (##) SELECT rc_id,rc_timestamp,rc_namespace,rc_title, rc_minor,rc_bot,rc_new,rc_cur_id,rc_this_oldid,rc_last_oldid, rc_type,rc_source,rc_patrolled,rc_ip,rc_old_len,rc_new_len,rc_deleted, rc_logid,rc_log_type,rc_log_action,rc_params, COALESCE( comment_rc_comment.comment_text, rc_comment ) AS rc_comment_text,comment_rc_comment.comment_data AS rc_comment_data,comment_rc_comment.comment_id AS rc_comment_cid,rc_user,rc_user_text,NULL AS rc_actor FROM recentchanges LEFT JOIN comment comment_rc_comment ON ((comment_rc_comment.comment_id = rc_comment_id)) WHERE rc_title = '###' AND (rc_source IN ('mw.edit','mw.new') OR (rc_source = 'mw.log' AND ((rc_log_type = 'move' AND rc_log_action = 'move') OR (rc_log_type = 'newusers' AND rc_log_action IN ('create','autocreate') ) OR (rc_log_type = 'delete' AND rc_log_action = 'delete')))) ORDER BY rc_timestamp desc LIMIT ###
exceptionERRORWikimedia\Rdbms\DBQueryTimeoutError
DBPerformanceWARNINGExpectation (readQueryTime <= 5) by MediaWiki::main not met (actual: 60.060236930847)
matej_suchanek added a subscriber: matej_suchanek.Sep 24 2018, 6:46 AM

rc_title = '###'? Shouldn't we query for title-namespace or id?

Daimona added a comment.Sep 24 2018, 8:25 AM

@matej_suchanek Yes. I was going to say that I don't understand why rc_namespace doesn't appear in the query, since we do add it. But then I understood: this array_filter strips the namespace if it's equal to 0. And it's always been like that: I moved the array_filter in this commit because it also stripped the hide-bots option, but apparently it's not the only one. An easy solution would be to set the conds on title after the array_filter, but the big question is: why are we filtering the array? At a quick glance, I don't see any reason to do it. Removing it (and building the array in a better way if needed) would also make adding further options easier, since it wouldn't unexpectedly strip stuff.

gerritbot added a subscriber: gerritbot.Sep 24 2018, 12:35 PM

Change 462447 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Remove useless array_filter

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

Daimona claimed this task.Sep 24 2018, 12:36 PM
gerritbot added a comment.Oct 19 2018, 10:14 AM

Change 462447 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Remove useless array_filter

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

Daimona closed this task as Resolved.Oct 19 2018, 11:03 AM
Daimona removed a project: Patch-For-Review.

The query doesn't filesort anymore.

mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:09 PM
Content licensed under Creative Commons Attribution-ShareAlike 3.0 (CC-BY-SA) unless otherwise noted; code licensed under GNU General Public License (GPL) or 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