Database error when trying to view user logs of user with many log events
Open, Needs TriagePublicPRODUCTION ERROR
Actions

Assigned To

None

Authored By

	RPI2026F1
	Dec 13 2022, 1:28 PM

Description

Steps to replicate the issue (include links if applicable):

https://en.wikipedia.org/wiki/Special:Log/ST47ProxyBot

What happens?:

[00b1c367-a3cb-4f31-9dd6-73c51215b3d3] 2022-12-13 13:24:34: Fatal exception of type "Wikimedia\Rdbms\DBQueryTimeoutError"

What should have happened instead?: Not a timeout.

Software version (skip for WMF-hosted wikis like Wikipedia):

Other information (browser name/version, screenshots, etc.): This user automatically blocks a lot of proxies, but the logs page should only show the first 50.

2022-12-13 13:24:34.096066 [00b1c367-a3cb-4f31-9dd6-73c51215b3d3] mw1432 enwiki 1.40.0-wmf.13 exception ERROR: [00b1c367-a3cb-4f31-9dd6-73c51215b3d3] /wiki/Special:Log/ST47ProxyBot   Wikimedia\Rdbms\DBQueryTimeoutError: A database query timeout has occurred. 
Query: SET STATEMENT max_statement_time=30 FOR SELECT  /*! STRAIGHT_JOIN */ log_id,log_type,log_action,log_timestamp,log_namespace,log_title,log_params,log_deleted,user_id,user_name,log_actor,logging_actor.actor_user AS `log_user`,logging_actor.actor_name AS `log_user_text`,comment_log_comment.comment_text AS `log_comment_text`,comment_log_comment.comment_data AS `log_comment_data`,comment_log_comment.comment_id AS `log_comment_cid`,(SELECT  GROUP_CONCAT(ctd_name SEPARATOR ',')  FROM `change_tag` JOIN `change_tag_def` ON ((ct_tag_id=ctd_id))   WHERE ct_log_id=log_id  ) AS `ts_tags`  FROM `logging` FORCE INDEX (log_actor_type_time) JOIN `actor` `logging_actor` ON ((actor_id=log_actor)) LEFT JOIN `user` ON ((user_id=logging_actor.actor_user)) JOIN `comment` `comment_log_comment` ON ((comment_log_comment.comment_id = log_comment_id))   WHERE (log_type NOT IN ('spamblacklist','titleblacklist','urlshortener','abusefilter','abusefilterprivatedetails','oath','ipinfo','suppress')) AND (log_type != 'review') AND (log_type != 'thanks') AND (log_type != 'patrol') AND (log_type != 'tag') AND log_actor = 198977042 AND ((log_deleted & 4) = 0)  ORDER BY log_timestamp DESC,log_id DESC LIMIT 51  
Function: IndexPager::buildQueryInfo (LogPager)
Error: 1969 Query execution was interrupted (max_statement_time exceeded)
 {"exception_url":"/wiki/Special:Log/ST47ProxyBot","reqId":"00b1c367-a3cb-4f31-9dd6-73c51215b3d3","caught_by":"entrypoint"} 
[Exception Wikimedia\Rdbms\DBQueryTimeoutError] (/srv/mediawiki/php-1.40.0-wmf.13/includes/libs/rdbms/database/Database.php:1551) A database query timeout has occurred. 
Query: SET STATEMENT max_statement_time=30 FOR SELECT  /*! STRAIGHT_JOIN */ log_id,log_type,log_action,log_timestamp,log_namespace,log_title,log_params,log_deleted,user_id,user_name,log_actor,logging_actor.actor_user AS `log_user`,logging_actor.actor_name AS `log_user_text`,comment_log_comment.comment_text AS `log_comment_text`,comment_log_comment.comment_data AS `log_comment_data`,comment_log_comment.comment_id AS `log_comment_cid`,(SELECT  GROUP_CONCAT(ctd_name SEPARATOR ',')  FROM `change_tag` JOIN `change_tag_def` ON ((ct_tag_id=ctd_id))   WHERE ct_log_id=log_id  ) AS `ts_tags`  FROM `logging` FORCE INDEX (log_actor_type_time) JOIN `actor` `logging_actor` ON ((actor_id=log_actor)) LEFT JOIN `user` ON ((user_id=logging_actor.actor_user)) JOIN `comment` `comment_log_comment` ON ((comment_log_comment.comment_id = log_comment_id))   WHERE (log_type NOT IN ('spamblacklist','titleblacklist','urlshortener','abusefilter','abusefilterprivatedetails','oath','ipinfo','suppress')) AND (log_type != 'review') AND (log_type != 'thanks') AND (log_type != 'patrol') AND (log_type != 'tag') AND log_actor = 198977042 AND ((log_deleted & 4) = 0)  ORDER BY log_timestamp DESC,log_id DESC LIMIT 51  
Function: IndexPager::buildQueryInfo (LogPager)
Error: 1969 Query execution was interrupted (max_statement_time exceeded)

  #0 /srv/mediawiki/php-1.40.0-wmf.13/includes/libs/rdbms/database/Database.php(1539): Wikimedia\Rdbms\Database->getQueryException(string, integer, string, string)
  #1 /srv/mediawiki/php-1.40.0-wmf.13/includes/libs/rdbms/database/Database.php(1513): Wikimedia\Rdbms\Database->getQueryExceptionAndLog(string, integer, string, string)
  #2 /srv/mediawiki/php-1.40.0-wmf.13/includes/libs/rdbms/database/Database.php(893): Wikimedia\Rdbms\Database->reportQueryError(string, integer, string, string, boolean)
  #3 /srv/mediawiki/php-1.40.0-wmf.13/includes/libs/rdbms/database/Database.php(1647): Wikimedia\Rdbms\Database->query(string, string, integer)
  #4 /srv/mediawiki/php-1.40.0-wmf.13/includes/libs/rdbms/database/DBConnRef.php(119): Wikimedia\Rdbms\Database->select(array, array, array, string, array, array)
  #5 /srv/mediawiki/php-1.40.0-wmf.13/includes/libs/rdbms/database/DBConnRef.php(338): Wikimedia\Rdbms\DBConnRef->__call(string, array)
  #6 /srv/mediawiki/php-1.40.0-wmf.13/includes/pager/IndexPager.php(460): Wikimedia\Rdbms\DBConnRef->select(array, array, array, string, array, array)
  #7 /srv/mediawiki/php-1.40.0-wmf.13/includes/pager/IndexPager.php(282): IndexPager->reallyDoQuery(string, integer, boolean)
  #8 /srv/mediawiki/php-1.40.0-wmf.13/includes/logging/LogPager.php(506): IndexPager->doQuery()
  #9 /srv/mediawiki/php-1.40.0-wmf.13/includes/pager/IndexPager.php(564): LogPager->doQuery()
  #10 /srv/mediawiki/php-1.40.0-wmf.13/includes/specials/SpecialLog.php(297): IndexPager->getBody()
  #11 /srv/mediawiki/php-1.40.0-wmf.13/includes/specials/SpecialLog.php(176): SpecialLog->show(FormOptions, array)
  #12 /srv/mediawiki/php-1.40.0-wmf.13/includes/specialpage/SpecialPage.php(700): SpecialLog->execute(string)
  #13 /srv/mediawiki/php-1.40.0-wmf.13/includes/specialpage/SpecialPageFactory.php(1451): SpecialPage->run(string)
  #14 /srv/mediawiki/php-1.40.0-wmf.13/includes/MediaWiki.php(311): MediaWiki\SpecialPage\SpecialPageFactory->executePath(string, RequestContext)
  #15 /srv/mediawiki/php-1.40.0-wmf.13/includes/MediaWiki.php(902): MediaWiki->performRequest()
  #16 /srv/mediawiki/php-1.40.0-wmf.13/includes/MediaWiki.php(560): MediaWiki->main()
  #17 /srv/mediawiki/php-1.40.0-wmf.13/index.php(50): MediaWiki->run()
  #18 /srv/mediawiki/php-1.40.0-wmf.13/index.php(46): wfIndexMain()
  #19 /srv/mediawiki/w/index.php(3): require(string)
  #20 {main}

Details

	Subject	Repo	Branch	Lines +/-
	logging: Fix USE INDEX for log_actor and log_type index	mediawiki/core	master	+9 -9
	logging: Fix the check if a log type filter is present	mediawiki/core	master	+1 -1

Customize query in gerrit

Related Objects

Mentioned In: T345145: DBQueryTimeoutError for QBA-bot’s logs in Russian Wikipedia
T342420: en:Special:Log/ST47ProxyBot not loading due to database error
T326177: Special:Log/gwtoolset emits DB Query Timeout Error
Mentioned Here: T303089: Consistent fatal timeout when visiting Special:Log default view for some users

Event Timeline

RPI2026F1 created this task.Dec 13 2022, 1:28 PM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptDec 13 2022, 1:28 PM

Reedy added projects: MediaWiki-Logevents, Performance Issue, Wikimedia-production-error.Dec 13 2022, 1:35 PM

Reedy changed the subtype of this task from "Bug Report" to "Production Error".

Reedy updated the task description. (Show Details)

MariaDB [enwiki]> explain SELECT  /*! STRAIGHT_JOIN */ log_id,log_type,log_action,log_timestamp,log_namespace,log_title,log_params,log_deleted,user_id,user_name,log_actor,logging_actor.actor_user AS `log_user`,logging_actor.actor_name AS `log_user_text`,comment_log_comment.comment_text AS `log_comment_text`,comment_log_comment.comment_data AS `log_comment_data`,comment_log_comment.comment_id AS `log_comment_cid`,(SELECT  GROUP_CONCAT(ctd_name SEPARATOR ',')  FROM `change_tag` JOIN `change_tag_def` ON ((ct_tag_id=ctd_id))   WHERE ct_log_id=log_id  ) AS `ts_tags`  FROM `logging` FORCE INDEX (log_actor_type_time) JOIN `actor` `logging_actor` ON ((actor_id=log_actor)) LEFT JOIN `user` ON ((user_id=logging_actor.actor_user)) JOIN `comment` `comment_log_comment` ON ((comment_log_comment.comment_id = log_comment_id))   WHERE (log_type NOT IN ('spamblacklist','titleblacklist','urlshortener','abusefilter','abusefilterprivatedetails','oath','ipinfo','suppress')) AND (log_type != 'review') AND (log_type != 'thanks') AND (log_type != 'patrol') AND (log_type != 'tag') AND log_actor = 198977042 AND ((log_deleted & 4) = 0)  ORDER BY log_timestamp DESC,log_id DESC LIMIT 51;
+------+--------------------+---------------------+--------+----------------------------+---------------------+---------+---------------------------------+----------+------------------------------------------------------------------------+
| id   | select_type        | table               | type   | possible_keys              | key                 | key_len | ref                             | rows     | Extra                                                                  |
+------+--------------------+---------------------+--------+----------------------------+---------------------+---------+---------------------------------+----------+------------------------------------------------------------------------+
|    1 | PRIMARY            | logging             | range  | log_actor_type_time        | log_actor_type_time | 42      | NULL                            | 19574732 | Using index condition; Using where; Rowid-ordered scan; Using filesort |
|    1 | PRIMARY            | logging_actor       | const  | PRIMARY                    | PRIMARY             | 8       | const                           | 1        |                                                                        |
|    1 | PRIMARY            | user                | eq_ref | PRIMARY                    | PRIMARY             | 4       | enwiki.logging_actor.actor_user | 1        | Using where                                                            |
|    1 | PRIMARY            | comment_log_comment | eq_ref | PRIMARY                    | PRIMARY             | 8       | enwiki.logging.log_comment_id   | 1        |                                                                        |
|    2 | DEPENDENT SUBQUERY | change_tag          | ref    | ct_log_tag_id,ct_tag_id_id | ct_log_tag_id       | 5       | enwiki.logging.log_id           | 6        | Using index                                                            |
|    2 | DEPENDENT SUBQUERY | change_tag_def      | eq_ref | PRIMARY                    | PRIMARY             | 4       | enwiki.change_tag.ct_tag_id     | 1        |                                                                        |
+------+--------------------+---------------------+--------+----------------------------+---------------------+---------+---------------------------------+----------+------------------------------------------------------------------------+
6 rows in set (0.009 sec)

thcipriani moved this task from Untriaged to Dec 2022 on the Wikimedia-production-error board.Dec 15 2022, 4:26 PM

So it does FORCE INDEX (log_actor_type_time), which is defined as

CREATE INDEX log_actor_type_time ON logging (
  log_actor, log_type, log_timestamp
);

but the query never selects on log_type, there are just negative operators log_type NOT IN or log_type !=. I guess it tries to sort those 19 million rows in memory.
The force index hint was added recently in T303089.

Same issue with GWToolSet log on Wikimedia Commons: https://commons.wikimedia.org/wiki/Special:Log/gwtoolset

[64db5e05-8def-4471-ae2b-36c76124a010] 2022-12-22 16:22:57: Fatal exception of type "Wikimedia\Rdbms\DBQueryTimeoutError" ([[MediaWiki:Internalerror-fatal-exception]])

ST47 subscribed.Dec 24 2022, 7:19 PM

Zabe subscribed.Jan 3 2023, 3:37 PM

Change 874895 had a related patch set uploaded (by Zabe; author: Zabe):

[mediawiki/core@master] logging: Fix the check if a log type filter is present

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

gerritbot added a project: Patch-For-Review.Jan 3 2023, 3:51 PM

Change 874895 abandoned by Zabe:

[mediawiki/core@master] logging: Fix the check if a log type filter is present

Reason:

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

Maintenance_bot removed a project: Patch-For-Review.Jan 3 2023, 5:29 PM

Pols12 mentioned this in T326177: Special:Log/gwtoolset emits DB Query Timeout Error.Jan 3 2023, 9:15 PM

FWIW look like https://en.wikipedia.org/w/index.php?title=Special:Log&user=ST47ProxyBot&type=block works

Umherirrender added a project: Wikimedia-Slow-DB-Query.Jan 19 2023, 7:46 PM

When the code choose a database index it is wrong looking at the filtering params, because there is always a log type included by default (newusers), when exclude also that log the list is fast, because the right index is forced - https://en.wikipedia.org/wiki/Special:Log/ST47ProxyBot?hide_newusers_log=1

In T325062#8496526, @Nintendofan885 wrote:

FWIW look like https://en.wikipedia.org/w/index.php?title=Special:Log&user=ST47ProxyBot&type=block works

That looks for a specifc log type and is not affected, only viewing the default public logs.

Change 886943 had a related patch set uploaded (by Umherirrender; author: Umherirrender):

[mediawiki/core@master] logging: Fix USE INDEX for log_actor and log_type index

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

gerritbot added a project: Patch-For-Review.Feb 6 2023, 9:40 PM

Umherirrender claimed this task.Feb 10 2023, 7:44 PM

Why was this task closed? I still cannot visit the original link without the error.

@RPI2026F1: What makes you think that this task is closed?

Sorry I misread the notification, my bad. The Needs Triage color is too similar to the “Resolved” color

Change 886943 abandoned by Umherirrender:

[mediawiki/core@master] logging: Fix USE INDEX for log_actor and log_type index

Reason:

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

Umherirrender removed Umherirrender as the assignee of this task.May 1 2023, 12:06 PM

Umherirrender removed a project: Patch-For-Review.

Umherirrender unsubscribed.

taavi merged a task: T342420: en:Special:Log/ST47ProxyBot not loading due to database error.Jul 21 2023, 9:59 AM

taavi added a subscriber: Johannnes89.

Johannnes89 mentioned this in T342420: en:Special:Log/ST47ProxyBot not loading due to database error.Jul 21 2023, 10:08 AM

taavi merged a task: T342506: DBQueryTimeoutError on Special:Log/ST47ProxyBot.Jul 23 2023, 2:24 PM

taavi added a subscriber: Framawiki.

TheresNoTime mentioned this in T345145: DBQueryTimeoutError for QBA-bot’s logs in Russian Wikipedia.Aug 29 2023, 12:25 PM

Umherirrender renamed this task from Database error when trying to view user logs of ST47ProxyBot on enwiki to Database error when trying to view user logs of user with many log events.Aug 29 2023, 6:32 PM

Umherirrender merged a task: T345145: DBQueryTimeoutError for QBA-bot’s logs in Russian Wikipedia.

Umherirrender added subscribers: stjn, Ladsgroup, TheresNoTime and 2 others.

kostajh subscribed.Sep 15 2023, 1:03 PM

Urbanecm subscribed.Oct 15 2023, 11:00 PM

matmarex merged a task: Restricted Task.Oct 31 2023, 8:40 PM

matmarex added subscribers: matmarex, taavi.

kolbert subscribed.Nov 18 2023, 5:08 PM

A_smart_kitten subscribed.Wed, Apr 10, 11:40 AM