Page MenuHomePhabricator
Create Task
Maniphest T281451

Wikimedia\Rdbms\DBTransactionError: Transaction round stage must be 'cursory' (not 'within-rollback-callbacks')
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Description

Error
  • mwversion: 1.37.0-wmf.3
  • reqId: 3c75e13d-35df-4caa-9d8e-a5ab1df5146a
normalized_message
[{reqId}] {exception_url}   Wikimedia\Rdbms\DBTransactionError: Transaction round stage must be 'cursory' (not 'within-rollback-callbacks')
exception.trace
from /srv/mediawiki/php-1.37.0-wmf.1/includes/libs/rdbms/lbfactory/LBFactory.php(819)
#0 /srv/mediawiki/php-1.37.0-wmf.1/includes/libs/rdbms/lbfactory/LBFactory.php(290): Wikimedia\Rdbms\LBFactory->assertTransactionRoundStage(string)
#1 /srv/mediawiki/php-1.37.0-wmf.1/includes/MediaWiki.php(1120): Wikimedia\Rdbms\LBFactory->commitMasterChanges(string)
#2 /srv/mediawiki/rpc/RunSingleJob.php(93): MediaWiki->restInPeace()
#3 {main}
Impact

About 30 in the last 24 hours. Not a train blocker.

Notes

Details

Request URL
/rpc/RunSingleJob.php
SubjectRepoBranchLines +/-
rdbms: add mysql timeout error codes to wasKnownStatementRollbackError()mediawiki/coremaster+5 -1
rdbms: make automatic connection recovery apply to more casesmediawiki/coremaster+901 -218
Expand log level of DBConnection messages from 'error' to 'warning'operations/mediawiki-configmaster+2 -2
rdbms: improve clarity of Database::canRecoverFromDisconnect and add loggingmediawiki/coremaster+42 -16
Customize query in gerrit

Related Objects
Search...

Event Timeline

• LarsWirzenius created this task.Apr 29 2021, 9:19 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptApr 29 2021, 9:19 AM
• LarsWirzenius added a comment.Apr 29 2021, 12:01 PM

This was marked as a train blocker because I'm a klutz. Removing it as a train blocker.

• LarsWirzenius removed a parent task: T278347: 1.37.0-wmf.3 deployment blockers.Apr 29 2021, 12:01 PM
RhinosF1 subscribed.Apr 29 2021, 2:55 PM
Krinkle added projects: WMF-JobQueue, Platform Engineering.May 6 2021, 11:00 PM
Krinkle moved this task from Untriaged to Apr 2021 on the Wikimedia-production-error board.
BPirkle triaged this task as Medium priority.May 11 2021, 7:24 PM
BPirkle edited projects, added Platform Team Workboards (Clinic Duty Team); removed Platform Engineering.
BPirkle moved this task from Inbox to Later on the Platform Team Workboards (Clinic Duty Team) board.
• LarsWirzenius unsubscribed.Jun 15 2021, 5:04 AM
Krinkle edited projects, added MediaWiki-libs-Rdbms; removed WMF-JobQueue, MediaWiki-Core-JobQueue.Oct 11 2021, 1:48 AM
Krinkle subscribed.

Still seen.

Sample from reqId 20b32cae-c28d-40b8-aeca-8c33abff406b (30 Sep 2021 09:32):

  • Sep 30, 2021 @ 09:32:30.124
message
 /rpc/RunSingleJob.php   Wikimedia\Rdbms\DBQueryDisconnectedError: A connection error occurred during a query. 
Query: ROLLBACK
Function: MWExceptionHandler::rollbackPrimaryChangesAndLog
Error: 2006 MySQL server has gone away (db1122)
trace
from /srv/mediawiki/php-1.38.0-wmf.1/includes/libs/rdbms/database/Database.php(1807)
#0 /srv/mediawiki/php-1.38.0-wmf.1/includes/libs/rdbms/database/Database.php(1793): Wikimedia\Rdbms\Database->getQueryException(string, integer, string, string)
#1 /srv/mediawiki/php-1.38.0-wmf.1/includes/libs/rdbms/database/Database.php(1768): Wikimedia\Rdbms\Database->getQueryExceptionAndLog(string, integer, string, string)
#2 /srv/mediawiki/php-1.38.0-wmf.1/includes/libs/rdbms/database/Database.php(1327): Wikimedia\Rdbms\Database->reportQueryError(string, integer, string, string, boolean)
#3 /srv/mediawiki/php-1.38.0-wmf.1/includes/libs/rdbms/database/Database.php(5016): Wikimedia\Rdbms\Database->query(string, string, integer)
#4 /srv/mediawiki/php-1.38.0-wmf.1/includes/libs/rdbms/database/Database.php(4978): Wikimedia\Rdbms\Database->doRollback(string)
#5 /srv/mediawiki/php-1.38.0-wmf.1/includes/libs/rdbms/loadbalancer/LoadBalancer.php(1991): Wikimedia\Rdbms\Database->rollback(string, string)
#6 /srv/mediawiki/php-1.38.0-wmf.1/includes/libs/rdbms/loadbalancer/LoadBalancer.php(2344): Wikimedia\Rdbms\LoadBalancer::Wikimedia\Rdbms\{closure}(Wikimedia\Rdbms\DatabaseMysqli)
#7 /srv/mediawiki/php-1.38.0-wmf.1/includes/libs/rdbms/loadbalancer/LoadBalancer.php(1992): Wikimedia\Rdbms\LoadBalancer->forEachOpenPrimaryConnection(Closure)
#8 /srv/mediawiki/php-1.38.0-wmf.1/includes/libs/rdbms/lbfactory/LBFactory.php(249): Wikimedia\Rdbms\LoadBalancer->rollbackPrimaryChanges(string, integer)
#9 /srv/mediawiki/php-1.38.0-wmf.1/includes/libs/rdbms/lbfactory/LBFactoryMulti.php(236): Wikimedia\Rdbms\LBFactory::Wikimedia\Rdbms\{closure}(Wikimedia\Rdbms\LoadBalancer, string, array)
#10 /srv/mediawiki/php-1.38.0-wmf.1/includes/libs/rdbms/lbfactory/LBFactory.php(251): Wikimedia\Rdbms\LBFactoryMulti->forEachLB(Closure, array)
#11 /srv/mediawiki/php-1.38.0-wmf.1/includes/libs/rdbms/lbfactory/LBFactory.php(342): Wikimedia\Rdbms\LBFactory->forEachLBCallMethod(string, array)
#12 /srv/mediawiki/php-1.38.0-wmf.1/includes/exception/MWExceptionHandler.php(136): Wikimedia\Rdbms\LBFactory->rollbackPrimaryChanges(string)
#13 /srv/mediawiki/php-1.38.0-wmf.1/extensions/EventBus/includes/JobExecutor.php(112): MWExceptionHandler::rollbackPrimaryChangesAndLog(Wikibase\DataModel\Services\Lookup\EntityLookupException)
#14 /srv/mediawiki/rpc/RunSingleJob.php(76): MediaWiki\Extension\EventBus\JobExecutor->execute(array)
#15 {main}
  • Sep 30, 2021 @ 09:32:30.125
message
/rpc/RunSingleJob.php   Wikibase\DataModel\Services\Lookup\EntityLookupException: The critical section "Wikimedia\Rdbms\Database::executeQuery" timed out after 180 seconds
  • Sep 30, 2021 @ 09:32:30.128
/rpc/RunSingleJob.php   Wikimedia\Rdbms\DBUnexpectedError: Cannot execute Wikimedia\Rdbms\Database::runOnTransactionIdleCallbacks critical section while session state is out of sync.

A critical section from Wikimedia\Rdbms\Database::rollback has failed
#0 /srv/mediawiki/php-1.38.0-wmf.1/vendor/wikimedia/request-timeout/src/CriticalSectionScope.php(44): Wikimedia\Rdbms\Database->Wikimedia\Rdbms\{closure}(44)
  • Sep 30, 2021 @ 09:32:30.129
Wikimedia\Rdbms\DBTransactionError: Transaction round stage must be 'cursory' (not 'within-rollback')
  • Sep 30, 2021 @ 09:32:30.237
PHP Fatal error: Uncaught Wikimedia\Rdbms\DBUnexpectedError: Cannot execute Wikimedia\Rdbms\Database::rollback critical section while session state is out of sync.

A critical section from Wikimedia\Rdbms\Database::executeQuery has failed
#0 /srv/mediawiki/php-1.38.0-wmf.1/vendor/wikimedia/request-timeout/src/CriticalSectionScope.php(44):
Restricted Application added a project: Performance-Team. · View Herald TranscriptOct 11 2021, 1:48 AM
• dpifke assigned this task to aaron.Oct 18 2021, 6:39 PM
• dpifke moved this task from Inbox, needs triage to Doing: Prio Interrupt on the Performance-Team board.
Krinkle moved this task from Untriaged to Rdbms library on the MediaWiki-libs-Rdbms board.Oct 27 2021, 6:37 PM

Still seen this week in production. The samples I looked at all issued Database::rollback critical section while session state is out of sync. after a critical section timeout.

gerritbot added a comment.Oct 30 2021, 3:39 AM

Change 735703 had a related patch set uploaded (by Aaron Schulz; author: Aaron Schulz):

[mediawiki/core@master] rdbms: improve clarity of Database::canRecoverFromDisconnect and add logging

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

gerritbot added a project: Patch-For-Review.Oct 30 2021, 3:39 AM
gerritbot added a comment.Oct 30 2021, 5:39 AM

Change 735703 merged by jenkins-bot:

[mediawiki/core@master] rdbms: improve clarity of Database::canRecoverFromDisconnect and add logging

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

ReleaseTaggerBot added a project: MW-1.38-notes (1.38.0-wmf.7; 2021-11-02).Oct 30 2021, 6:00 AM
Maintenance_bot removed a project: Patch-For-Review.Oct 30 2021, 6:10 AM
aaron added a comment.Nov 2 2021, 10:45 PM

One problem is that RevisionBasedEntityLookup is catching generic Exceptions and throwing a different exception, so any entrypoint logic (e.g. jobrunner, runSingleJob, MediaWiki class, MWExceptionHandler class) won't know that the original error was a timeout (via an interrupt, leaving a bunch of function calls unfinished).

Even if it did bubble up, we'd still need to improve those entry points to handle timeouts better. Perhaps rollbackPrimaryChanges() could also:

It would be nice to have some method to handle this for replica connections too, since they can also timeout on queries.

Also, the Database subclasses could catch timeout exceptions that occur right after the driver call (the pecl extension C methods are not interrupted) and treat it as a non-state-corrupting DBError, while bubbling the error up at the same time. This would avoid a lot of these problem cases.

aaron added a comment.Nov 2 2021, 11:01 PM

Using mysql-level query timeouts would also be an option to limit this from occurring (though it could still happen with multiple slow queries).

gerritbot added a comment.Nov 24 2021, 12:44 AM

Change 737824 had a related patch set uploaded (by Aaron Schulz; author: Aaron Schulz):

[mediawiki/core@master] [WIP] rdbms: make automatic connection recovery apply to more cases

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

gerritbot added a project: Patch-For-Review.Nov 24 2021, 12:44 AM
Krinkle added a subtask: T297424: Reduce LBFactory::rollbackPrimaryChanges() callers in core.Dec 13 2021, 7:36 PM
gerritbot added a comment.Feb 21 2022, 1:25 PM

Change 764359 had a related patch set uploaded (by Krinkle; author: Krinkle):

[operations/mediawiki-config@master] Increase logging of DBConnection messages from 'error' to 'warning'

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

gerritbot added a comment.Feb 28 2022, 2:40 PM

Change 764359 merged by jenkins-bot:

[operations/mediawiki-config@master] Expand log level of DBConnection messages from 'error' to 'warning'

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

Krinkle added a comment.Mar 1 2022, 5:28 PM

These messages are now coming in: https://logstash.wikimedia.org/goto/e1814ec3fb96e7905f8c647a44a22a65

gerritbot added a comment.Mar 10 2022, 12:08 AM

Change 737824 merged by jenkins-bot:

[mediawiki/core@master] rdbms: make automatic connection recovery apply to more cases

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

Maintenance_bot removed a project: Patch-For-Review.Mar 10 2022, 12:10 AM
• nnikkhoui subscribed.EditedMar 14 2022, 6:55 PM

I'm seeing this same error locally when testing specific behavior of some REST API endpoint changes for T303352, but having a hard time debugging the path from ParameterAssertionException being thrown here to this error being thrown. I think @aaron's comment above might explain the problem i'm seeing, any chance of helping me step through this particular use case @aaron ? :)

aaron closed subtask T297424: Reduce LBFactory::rollbackPrimaryChanges() callers in core as Resolved.Mar 15 2022, 8:20 PM
aaron closed this task as Resolved.Mar 16 2022, 5:38 PM
In T281451#7775513, @nnikkhoui wrote:

I'm seeing this same error locally when testing specific behavior of some REST API endpoint changes for T303352, but having a hard time debugging the path from ParameterAssertionException being thrown here to this error being thrown. I think @aaron's comment above might explain the problem i'm seeing, any chance of helping me step through this particular use case @aaron ? :)

That might just be T303887.

aaron closed this task as a duplicate of T303887: Wikimedia\Rdbms\DBTransactionError: Transaction round stage must be 'cursory' (not 'within-rollback-session').Mar 16 2022, 5:44 PM
Krinkle added a parent task: T300202: 1.38.0-wmf.26 deployment blockers.Mar 18 2022, 1:20 PM
Krinkle merged a task: T303887: Wikimedia\Rdbms\DBTransactionError: Transaction round stage must be 'cursory' (not 'within-rollback-session').
Krinkle added subscribers: jeena, Ladsgroup, • LarsWirzenius and 2 others.
In T303887#7779693, @jeena wrote:

Related to T303885 ?

In T303887#7779707, @Ladsgroup wrote:

Caused by the same thing https://gerrit.wikimedia.org/r/c/mediawiki/core/+/737824/

I'm inclined to revert that patch and follow ups

In T303887#7784533, @gerritbot wrote:

Change 771081 merged by jenkins-bot:

[mediawiki/core@master] rdbms: fix owner id and RELEASE_ALL_LOCKS query in session flushing methods

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

hashar reopened this task as Open.Mar 21 2022, 12:56 PM
hashar subscribed.

We had the error again on mediawikiwiki when promoting to 1.39.0-wmf.1:

Wikimedia\Rdbms\DBTransactionError: Transaction round stage must be 'cursory' (not 'within-rollback-callbacks') from /rpc/RunSingleJob.php

Error
normalized_message
[{reqId}] {exception_url}   Wikimedia\Rdbms\DBTransactionError: Transaction round stage must be 'cursory' (not 'within-rollback-callbacks')
exception.trace
from /srv/mediawiki/php-1.39.0-wmf.1/includes/libs/rdbms/lbfactory/LBFactory.php(818)
#0 /srv/mediawiki/php-1.39.0-wmf.1/includes/libs/rdbms/lbfactory/LBFactory.php(290): Wikimedia\Rdbms\LBFactory->assertTransactionRoundStage(string)
#1 /srv/mediawiki/php-1.39.0-wmf.1/includes/MediaWiki.php(1110): Wikimedia\Rdbms\LBFactory->commitPrimaryChanges(string)
#2 /srv/mediawiki/rpc/RunSingleJob.php(93): MediaWiki->restInPeace()
#3 {main}
hashar added a parent task: T300203: 🧪🚂 Trainsperiment Week: 1.39.0-wmf.1, 1.39.0-wmf.2, 1.39.0-wmf.3, 1.39.0-wmf.4 deployment blockers.Mar 21 2022, 12:56 PM
hashar added a comment.EditedMar 21 2022, 12:58 PM

Fun thing with f01738ac-a46e-4e0f-a8a8-039b77b5ed41: it is an user creating an account on mediawiki.org (1.39.0-wmf.1) with a global account created on meta (1.38.0-wmf.26). The two mediawiki versions surprised me.

[f01738ac-a46e-4e0f-a8a8-039b77b5ed41] /rpc/RunSingleJob.php Wikimedia\Rdbms\DBTransactionError: Transaction round stage must be 'cursory' (not 'within-rollback-callbacks')

Before that there is:

[f01738ac-a46e-4e0f-a8a8-039b77b5ed41] /rpc/RunSingleJob.php Wikimedia\Rdbms\DBUnexpectedError: Cannot execute Wikimedia\Rdbms\Database::runOnTransactionIdleCallbacks critical section while session state is out of sync.

And after:

Error 1062 from EchoNotificationMapper::insert, Duplicate entry '17604325-1515299' for key 'PRIMARY' (db1157) INSERT INTO echo_notification (notification_event,notification_user,notification_timestamp,notification_read_timestamp,notification_bundle_hash) VALUES (1515299,17604325,'20220321124005',NULL,'') db1157

hashar mentioned this in T304307: Wikimedia\Timestamp\TimestampException: Wikimedia\Timestamp\ConvertibleTimestamp::getTimestamp: The timestamp cannot be represented in the specified format.Mar 21 2022, 1:14 PM
hashar mentioned this in T244898: Notifications ('Echo') should work with postgres.
hoo subscribed.Mar 21 2022, 2:02 PM
Zabe unsubscribed.Mar 21 2022, 2:25 PM
Zabe subscribed.
hashar closed this task as Resolved.Mar 21 2022, 3:04 PM

I am marking this one resolved again. The error message Transaction round stage must be 'cursory' (not 'within-rollback-callbacks') pointed me there but after looking at exceptions and errors for the requests the issues were due to a duplicate primary key for echo notifications. I highly suspect the root cause was T304307.

gerritbot added a comment.Mar 23 2022, 1:14 AM

Change 771755 had a related patch set uploaded (by Aaron Schulz; author: Aaron Schulz):

[mediawiki/core@master] rdbms: add mysql timeout error codes to wasKnownStatementRollbackError()

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

gerritbot added a project: Patch-For-Review.Mar 23 2022, 1:14 AM
gerritbot added a comment.Mar 23 2022, 1:31 AM

Change 771755 merged by jenkins-bot:

[mediawiki/core@master] rdbms: add mysql timeout error codes to wasKnownStatementRollbackError()

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

Maintenance_bot removed a project: Patch-For-Review.Mar 23 2022, 2:10 AM
Krinkle mentioned this in T305016: Think about rdbms reconnection logic.Mar 30 2022, 12:29 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