From T143367#4432497:
it seems like the exception logs are filled with CAS update failed on user_touched error messages, with about ~1000/day being emitted, which currently accounts to ~30-40% of all exception log lines.
This error is specifically thrown by User::saveSettings() https://gerrit.wikimedia.org/r/plugins/gitiles/mediawiki/core/+/master/includes/user/User.php#4211
Almost all exceptions came from calls to the api.php endpoint; a naive view of the code seems to suggest that the exception is raised when no row is affected by the request.
In all errors, the message reported that the read was performed on the master database, so I doubt that lag might be the cause.
I think it's reasonable to try to manage the error and do some better logging maybe (e.g. reporting both what is the timestamp on the database and what is the one we're trying to write). I also doubt we have 1000 race conditions per day.
In any case, this should probably not be an unhandled exception.
Here is an example of the stack trace:
{
"backtrace": [
{
"args": [
"Wikimedia\\Rdbms\\DatabaseMysqli",
"string"
],
"file": "/srv/mediawiki/php-1.32.0-wmf.16/includes/libs/rdbms/database/Database.php",
"function": "Closure$User::saveSettings",
"line": 3731
},
{
"args": [
"string",
"Closure$User::saveSettings;309"
],
"class": "Wikimedia\\Rdbms\\Database",
"file": "/srv/mediawiki/php-1.32.0-wmf.16/includes/user/User.php",
"function": "doAtomicSection",
"line": 4222,
"type": "->"
},
{
"args": [],
"class": "User",
"file": "/srv/mediawiki/php-1.32.0-wmf.16/extensions/BetaFeatures/includes/BetaFeaturesHooks.php",
"function": "saveSettings",
"line": 284,
"type": "->"
},
{
"args": [],
"file": "/srv/mediawiki/php-1.32.0-wmf.16/includes/deferred/MWCallableUpdate.php",
"function": "Closure$BetaFeaturesHooks::getPreferences",
"line": 34
},
{
"args": [],
"class": "MWCallableUpdate",
"file": "/srv/mediawiki/php-1.32.0-wmf.16/includes/deferred/DeferredUpdates.php",
"function": "doUpdate",
"line": 268,
"type": "->"
},
{
"args": [
"MWCallableUpdate",
"Wikimedia\\Rdbms\\LBFactoryMulti",
"string",
"integer"
],
"class": "DeferredUpdates",
"file": "/srv/mediawiki/php-1.32.0-wmf.16/includes/deferred/DeferredUpdates.php",
"function": "runUpdate",
"line": 214,
"type": "::"
},
{
"args": [
"array",
"string",
"integer"
],
"class": "DeferredUpdates",
"file": "/srv/mediawiki/php-1.32.0-wmf.16/includes/deferred/DeferredUpdates.php",
"function": "execute",
"line": 134,
"type": "::"
},
{
"args": [
"string"
],
"class": "DeferredUpdates",
"file": "/srv/mediawiki/php-1.32.0-wmf.16/includes/MediaWiki.php",
"function": "doUpdates",
"line": 913,
"type": "::"
},
{
"args": [
"string",
"boolean"
],
"class": "MediaWiki",
"file": "/srv/mediawiki/php-1.32.0-wmf.16/includes/MediaWiki.php",
"function": "restInPeace",
"line": 733,
"type": "->"
},
{
"args": [],
"function": "Closure$MediaWiki::doPostOutputShutdown"
}
],
"caught_by": "mwe_handler",
"code": 0,
"file": "/srv/mediawiki/php-1.32.0-wmf.16/includes/user/User.php",
"id": "...",
"line": 4211,
"message": "CAS update failed on user_touched for user ID 'XXXXXX' (read from master); the version of the user to be saved is older than the current version.",
"type": "MWException",
"url": "/w/api.php"
}the corresponding (redacted for privacy) line in api.log
2018-08-17 16:15:04 [...] mw1314 enwiki 1.32.0-wmf.16 api INFO: API POST USER_NAME USER_IP T=415ms action=options format=json change=wllimit%3D200 token=[redacted] formatversion=2