Page MenuHomePhabricator

mw.Api#saveOptions performs multiple concurrent requests, which is unreliable
Closed, ResolvedPublic

Description

I got this when I visited ur.wikipedia.org

There was an error: internal_api_error_DBQueryError; [3131f233] Database query error

This happened when my GlobalPreferences.js attempted to set my preferences on that wiki using the MW API.

Event Timeline

He7d3r created this task.May 30 2015, 8:55 PM
He7d3r raised the priority of this task from to Needs Triage.
He7d3r updated the task description. (Show Details)
He7d3r added a subscriber: He7d3r.
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMay 30 2015, 8:55 PM
Reedy added a subscriber: Reedy.May 30 2015, 8:57 PM

Can you tell us exactly what preference you were setting? Ideally, what query string (GET and POST if appropriate) you tried

Reedy added a comment.May 30 2015, 8:59 PM
2015-05-30 20:52:23 mw1126 urwiki exception INFO: [3131f233] /w/api.php   DBQueryError from line 1276 of /srv/mediawiki/php-1.26wmf7/includes/db/Database.php: A database error has occurred. Did you forget to run maintenance/update.php after upgrading?  See: https://www.mediawiki.org/wiki/Manual:Upgrading#Run_the_update_script
Query: UPDATE  `user` SET user_name = 'He7d3r',user_password = '',user_newpassword = '',user_newpass_time = NULL,user_real_name = '',user_email = 'helder.wiki@gmail.com',user_email_authenticated = '<REDACTED>',user_touched = '<REDACTED>',user_token = '<REDACTED>',user_email_token = NULL,user_email_token_expires = NULL,user_password_expires = NULL WHERE user_id = '19948' AND user_touched = '20150530205228'
Function: User::saveSettings
Error: 1213 Deadlock found when trying to get lock; try restarting transaction (10.64.16.27)

#0 /srv/mediawiki/php-1.26wmf7/includes/db/Database.php(1231): DatabaseBase->reportQueryError()
#1 /srv/mediawiki/php-1.26wmf7/includes/db/Database.php(2183): DatabaseBase->query()
#2 /srv/mediawiki/php-1.26wmf7/includes/User.php(3681): DatabaseBase->update()
#3 /srv/mediawiki/php-1.26wmf7/includes/api/ApiOptions.php(125): User->saveSettings()
#4 /srv/mediawiki/php-1.26wmf7/includes/api/ApiMain.php(1131): ApiOptions->execute()
#5 /srv/mediawiki/php-1.26wmf7/includes/api/ApiMain.php(469): ApiMain->executeAction()
#6 /srv/mediawiki/php-1.26wmf7/includes/api/ApiMain.php(442): ApiMain->executeActionWithErrorHandling()
#7 /srv/mediawiki/php-1.26wmf7/api.php(90): ApiMain->execute()
#8 /srv/mediawiki/w/api.php(3): include()
#9 {main} {"private":false}
He7d3r updated the task description. (Show Details)May 30 2015, 10:25 PM
He7d3r set Security to None.

I'm not sure, because Firefox didn't show the response for the POST request in the console.
But I tried visiting a few other wikis and I got the same error (with id "3856db8e") on
https://ceb.wikipedia.org/w/index.php?uselang=en&special:blankpage&useskin=vector
and then (with id "e8308e8e") on
https://sr.wikipedia.org/w/index.php?uselang=en&special:blankpage&useskin=vector

I can reproduce it by executing this in the console:

mw.loader.using( 'mediawiki.api.options' )
.done( function () {
    ( new mw.Api() )
    .saveOptions( {"nickname":"[[User:foobar|foobar]]","searchNs829":"1"} )
    .always( function ( a, b ) {
        console.log( 'error?', JSON.stringify( b.error ) );
    } );
} );

I can reproduce it by executing this in the console:

mw.loader.using( 'mediawiki.api.options' )
.done( function () {
    ( new mw.Api() )
    .saveOptions( {"nickname":"[[User:foobar|foobar]]","searchNs829":"1"} )
    .always( function ( a, b ) {
        console.log( 'error?', JSON.stringify( b.error ) );
    } );
} );

With this code, I can reproduce the issue locally. The deadlock error seems to have been fixed by rMW833bdbab37cda3fa, though there is now a different error in my debug log:

[exception] [98ed095a] /w/api.php   MWException from line 3687 of /home/ki/Projects/mediawiki/core/includes/User.php: CAS update failed on user_touched for user ID '1';the version of the user to be saved is older than the current version.
#0 /home/ki/Projects/mediawiki/core/includes/api/ApiOptions.php(125): User->saveSettings()
#1 /home/ki/Projects/mediawiki/core/includes/api/ApiMain.php(1098): ApiOptions->execute()
#2 /home/ki/Projects/mediawiki/core/includes/api/ApiMain.php(436): ApiMain->executeAction()
#3 /home/ki/Projects/mediawiki/core/includes/api/ApiMain.php(409): ApiMain->executeActionWithErrorHandling()
#4 /home/ki/Projects/mediawiki/core/api.php(88): ApiMain->execute()
#5 {main}

This indicates a problem with core's "mediawiki.api.options" module, one I was already aware of yet forgot to report.

action=options&change= does not have a quoting mechanism, so it is necessary to perform a separate request in order to save any value containing "|". The JS code does this, yet it fails to wait until the previous request has finished (apparently even intentionally!). Because of the way the User class works, this is not reliable. If request B loads the user data after request A has done so but before it has saved the data, the changes from request B will be lost, as indicated above.

The JS code should be fixed. Also, a quoting mechanism should be added to the API (to allow setting all options at once), as well as proper reporting of this kind of error.

PleaseStand renamed this task from Database query error to mw.Api#saveOptions performs multiple concurrent requests, which is unreliable.Jun 3 2015, 12:01 AM
aaron added a comment.Jun 3 2015, 12:02 AM

I'm curious what causes T95839. I suspect some sort of concurrent or double posting, and it seems to a effect a small number of users many times (judging from the user IDs).

So as I understand it, the issue is caused by trying to run multiple concurrent UPDATE queries against the 'user' table… but why are we even firing these? When changing user options (preferences), and not user settings (email, password, etc.), we shouldn't need to update anything in the 'user' table, only in 'user_properties', where the separate requests would be changing separate and seemingly independent rows in the database.

I can change the JS code not to perform concurrent requests, of course, but it seems that the real bug is in PHP code.

(And if concurrent requests to the API can cause silent data loss, then that is clearly an API bug. It should either work or throw an error.)

demon triaged this task as Normal priority.Jul 2 2015, 6:40 PM
Anomie added a subscriber: Anomie.Jan 21 2017, 8:54 PM

This should be mostly fixed as of rMW75a85b412c4a: API: Use U+001F (Unit Separator) for separating multi-valued parameters since there are now very few values that require sending multiple API requests. Cases when it's not fixed are:

  • If you're setting an option with a name containing an '=' (assuming any such name is even valid input).
  • If you're setting options.ajax.url when constructing your mw.Api and not also setting options.useUS = true (the assumption being that you're making a cross-wiki request and the target wiki might be older than 1.28.0-wmf.17).

So as I understand it, the issue is caused by trying to run multiple concurrent UPDATE queries against the 'user' table… but why are we even firing these? When changing user options (preferences), and not user settings (email, password, etc.), we shouldn't need to update anything in the 'user' table, only in 'user_properties', where the separate requests would be changing separate and seemingly independent rows in the database.

Abstraction. The code calls $user->setOption() for however many options are passed, then calls $user->saveSettings() to save the changes, which writes to both user and user_properties.

While $user->saveOptions() exists, it's currently protected and cache integrity might rely on user_touched being updated anyway.

(And if concurrent requests to the API can cause silent data loss, then that is clearly an API bug. It should either work or throw an error.)

It looks like that was fixed by rMWed1b8d3a0e68: Upgraded User::saveSettings logged errors to exceptions making User::saveSettings() actually throw an exception on error instead of silently failing, although the error returned isn't currently the most helpful ("internal_api_error_MWException", I believe, with the non-localized "CAS update failed [blah blah]" as the error text).

Change 333782 had a related patch set uploaded (by Bartosz Dziewoński):
mediawiki.api.options: Use sequential API requests in the remaining edge cases

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

Change 333782 merged by jenkins-bot:
mediawiki.api.options: Use sequential API requests in the remaining edge cases

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

matmarex closed this task as Resolved.Jan 24 2017, 12:06 AM
matmarex removed a project: Patch-For-Review.