Create Task
Maniphest T119736

Could not find local user data for {Username}@{wiki}
Open, Unbreak Now!Public
Actions

Description

Username: @SarahTehCat

18:57:07 <SarahTehCat> My issue is this: every time I log in, I get an error page that's entirely blank except for the error message: "Exception encountered, of type "Exception" "
18:57:25 <SarahTehCat> I've tried it in Incognito Mode in Chrome, and I've even done it in safe mode in Firefox.
18:57:57 <SarahTehCat> I copy/pasted the password, so I'm 100% sure my login information is correct, too.
18:58:20 <SarahTehCat> This only started within the last week or so
18:59:32 <SarahTehCat> http://i.imgur.com/dKzoYZ4.png
18:59:49 <SarahTehCat> Note that Firefox is in safe mode in that screenshot :)
19:01:51 <SarahTehCat> Not sure if it's relevant, but I'm running Ubuntu 15.04 on a Dell Inspiron N5010 laptop. Firefox is set to auto-update too, so I have the latest version.
19:35:03 <+Josve05a> SarahTehCat: Do you have cookies turned off whie in secure-mode?
19:35:51 <SarahTehCat> Also, one sec, lemme check
19:36:05 <SarahTehCat> ...How do I check? Lol.
19:36:32 <+Josve05a> https://support.mozilla.org/en-US/kb/enable-and-disable-cookies-website-preferences
19:37:12 <SarahTehCat> Okay, thanks
19:39:14 <SarahTehCat> Okay, I just disabled cookies.
19:39:21 <SarahTehCat> Should I remove all existing cookies as well?
19:46:44 <SarahTehCat> Trying to log into Wikipedia results in this error: http://i.imgur.com/k5oxzsx.png. Trying to click on "Login or Register ... MediaWiki" icon renders this error: http://i.imgur.com/7stmpcE.png.
19:47:29 <+Josve05a> ok, I'm gonna file a ticket...
19:47:46 <+Josve05a> DO I have your permission to copy your messages you've sent here and use in the ticket?
19:47:52 <SarahTehCat> Yup




Request from 10.64.0.107 via cp1070 frontend 8[10.64.0.107]:80), Vanish XID 281144169
Forwarded for: 75.128.80.20, 20.64.0.107
Error: 503, Service Unavailable Thu, 26 Nov 2015 18:45:43 GMT

Details

Parent Tasks
T138555: MW-1.28.0-wmf.9 deployment blockers
T139211: MW-1.28.0-wmf.10 deployment blockers
Subtasks
T140144: Echo triggering CentralAuth "Can only obtain a centralauthtoken when using CentralAuth sessions" error
There are a very large number of changes, so older changes are hidden. Show Older Changes
bd808 added a comment.Thu, Jul 7, 8:44 PM

From the Deepu14basketball occurrence I was able to find a full set of logs that include the initial account creation and subsequent failures to autocreate on commonswiki:

2016-07-07T11:27:56.000Z 	CentralAuth 	enwiki 	registered global account 'Deepu14basketball'
2016-07-07T11:27:56.000Z 	CentralAuth 	enwiki 	Attaching local user Deepu14basketball@enwiki by 'new'
2016-07-07T11:27:56.000Z 	authentication 	enwiki 	Creating user Deepu14basketball during account creation
2016-07-07T11:27:57.000Z 	authentication 	enwiki 	MediaWiki\Auth\AuthManager::continueAccountCreation: Account creation succeeded for Deepu14basketball
2016-07-07T11:27:57.000Z 	authentication 	enwiki 	Logging in Deepu14basketball after account creation
2016-07-07T11:27:57.000Z 	authentication 	enwiki 	throttler data not found for Deepu14basketball
2016-07-07T11:27:59.000Z 	authentication 	loginwiki 	MediaWiki\Auth\AuthManager::autoCreateUser: creating new user (Deepu14basketball) - from: /rpc/RunJobs.php?wiki=loginwiki&...
2016-07-07T11:27:59.000Z 	CentralAuth 	loginwiki 	Attaching local user Deepu14basketball@loginwiki by 'login'
2016-07-07T11:27:59.000Z 	authentication 	metawiki 	MediaWiki\Auth\AuthManager::autoCreateUser: creating new user (Deepu14basketball) - from: /rpc/RunJobs.php?wiki=metawiki&...
2016-07-07T11:27:59.000Z 	CentralAuth 	metawiki 	Attaching local user Deepu14basketball@metawiki by 'login'
2016-07-07T11:28:01.000Z 	authentication 	mediawikiwiki 	MediaWiki\Auth\AuthManager::autoCreateUser: creating new user (Deepu14basketball) - from: /rpc/RunJobs.php?wiki=mediawikiwiki...
2016-07-07T11:28:01.000Z 	CentralAuth 	mediawikiwiki 	Attaching local user Deepu14basketball@mediawikiwiki by 'login'
2016-07-07T11:28:44.000Z 	authentication 	commonswiki 	MediaWiki\Auth\AuthManager::autoCreateUser: creating new user (Deepu14basketball) - from: /w/api.php?action=query&format=...
2016-07-07T11:28:44.000Z 	CentralAuth 	commonswiki 	Attaching local user Deepu14basketball@commonswiki by 'login'
2016-07-07T11:30:51.000Z 	authentication 	commonswiki 	MediaWiki\Auth\AuthManager::autoCreateUser: creating new user (Deepu14basketball) - from: /w/api.php?action=query&format=...
2016-07-07T11:30:51.000Z 	CentralAuth 	commonswiki 	Race condition? Already attached Deepu14basketball@commonswiki, just tried by 'login'
2016-07-07T11:30:51.000Z 	authentication 	commonswiki 	MediaWiki\Auth\AuthManager::autoCreateUser: creating new user (Deepu14basketball) - from: /w/api.php?action=query&format=...
2016-07-07T11:30:51.000Z 	CentralAuth 	commonswiki 	Race condition? Already attached Deepu14basketball@commonswiki, just tried by 'login'
2016-07-07T11:31:22.000Z 	authentication 	commonswiki 	MediaWiki\Auth\AuthManager::autoCreateUser: creating new user (Deepu14basketball) - from: /w/api.php?action=query&format=...
2016-07-07T11:31:22.000Z 	CentralAuth 	commonswiki 	Race condition? Already attached Deepu14basketball@commonswiki, just tried by 'login'
2016-07-07T11:31:22.000Z 	authentication 	commonswiki 	MediaWiki\Auth\AuthManager::autoCreateUser: creating new user (Deepu14basketball) - from: /w/api.php?action=query&format=...
2016-07-07T11:31:22.000Z 	CentralAuth 	commonswiki 	Race condition? Already attached Deepu14basketball@commonswiki, just tried by 'login'
2016-07-07T11:31:46.000Z 	authentication 	commonswiki 	MediaWiki\Auth\AuthManager::autoCreateUser: creating new user (Deepu14basketball) - from: /w/api.php?action=query&format=...
2016-07-07T11:31:46.000Z 	CentralAuth 	commonswiki 	Race condition? Already attached Deepu14basketball@commonswiki, just tried by 'login'
2016-07-07T11:31:46.000Z 	authentication 	commonswiki 	MediaWiki\Auth\AuthManager::autoCreateUser: creating new user (Deepu14basketball) - from: /w/api.php?action=query&format=...
2016-07-07T11:31:46.000Z 	CentralAuth 	commonswiki 	Race condition? Already attached Deepu14basketball@commonswiki, just tried by 'login'
2016-07-07T11:32:19.000Z 	exception 	enwiki 	Could not find local user data for Deepu14basketball@commonswiki
gerritbot added a comment.Fri, Jul 8, 12:40 AM

Change 297936 had a related patch set uploaded (by BryanDavis):
Cleanup localuser records when wiki is missing data

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

JJMC89 added a comment.Fri, Jul 8, 1:31 AM

Special:CentralAuth for Dell_Hawkins gives Fatal exception of type "Exception".

gerritbot added a comment.Fri, Jul 8, 4:44 AM

Change 297946 had a related patch set uploaded (by BryanDavis):
Detach accounts during global rename

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

JJMC89 added a comment.Sun, Jul 10, 12:37 AM

Special:CentralAuth for Acastrohowell gives Fatal exception of type "Exception" after getting To avoid creating high replication lag, this transaction was aborted because the write duration (6.1167709827423) exceeded the 5 seconds limit. If you are changing many items at once, try doing multiple smaller operations instead. when attempting to create at enwiki.

jcrespo added a comment.Sun, Jul 10, 2:29 PM

Since 2016-07-05 at 23h UTC (probably, a software commit) there is high rate of Lock wait timeout exceeded; try restarting transaction (10.64.16.30). This host is centralauth master and the queries are CentralAuthUser::saveSettings:

https://logstash.wikimedia.org/#dashboard/temp/AVXVMNhAw3dCNxx2bE7U

Please advice if this could be related, if not I would file a different bug.

mmodell added a comment.Sun, Jul 10, 9:27 PM

This happened to me AGAIN today and the fix that worked previously doesn't seem to work this time.

Josve05a added a comment.Mon, Jul 11, 8:33 AM

Arsenetaryan is reporting [V4NKsQpAEK4AAHOp32YAAABR] 2016-07-11 07:28:49: Fatal exception of type "Exception" in https://ticket.wikimedia.org/otrs/index.pl?Action=AgentTicketZoom;TicketID=9295094

Maldovix added a subscriber: Maldovix.Mon, Jul 11, 6:13 PM

My username is also having this exact issue, and changing cookie preferences did not solve it. :-(

Username:

Emceeski
bd808 added a comment.Mon, Jul 11, 7:47 PM
In T119736#2448839, @Maldovix wrote:

My username is also having this exact issue, and changing cookie preferences did not solve it. :-(

Username:

Emceeski

Error was "Could not find local user data for Emceeski@commonswiki". I deleted the commonswiki row for Emceeski in the CA localuser table and https://en.wikipedia.org/w/index.php?title=Special%3ACentralAuth&target=Emceeski now works.

bd808 added a comment.Mon, Jul 11, 7:49 PM
In T119736#2446653, @Josve05a wrote:

Arsenetaryan is reporting [V4NKsQpAEK4AAHOp32YAAABR] 2016-07-11 07:28:49: Fatal exception of type "Exception" in https://ticket.wikimedia.org/otrs/index.pl?Action=AgentTicketZoom;TicketID=9295094

Another failure due to a dangling commonswiki reference in the localuser table. Manually corrected in the database -- https://en.wikipedia.org/w/index.php?title=Special%3ACentralAuth&target=Arsenetaryan.

bd808 added a comment.Mon, Jul 11, 7:52 PM
In T119736#2445005, @JJMC89 wrote:

Special:CentralAuth for Acastrohowell gives Fatal exception of type "Exception" after getting To avoid creating high replication lag, this transaction was aborted because the write duration (6.1167709827423) exceeded the 5 seconds limit. If you are changing many items at once, try doing multiple smaller operations instead. when attempting to create at enwiki.

Error was "Could not find local user data for Acastrohowell@enwiki" which interestingly was the "new" wiki for the account. Manually deleted the dangling reference and https://en.wikipedia.org/w/index.php?title=Special%3ACentralAuth&target=Acastrohowell works now.

bd808 added a comment.Mon, Jul 11, 7:55 PM
In T119736#2445587, @jcrespo wrote:

Since 2016-07-05 at 23h UTC (probably, a software commit) there is high rate of Lock wait timeout exceeded; try restarting transaction (10.64.16.30). This host is centralauth master and the queries are CentralAuthUser::saveSettings:

https://logstash.wikimedia.org/#dashboard/temp/AVXVMNhAw3dCNxx2bE7U

Please advice if this could be related, if not I would file a different bug.

@jcrespo it may be related in that that error may be making the problem of occasional local account failures worse, but I think in general it is a separate issue from the main topic of this bug.

matmarex added a subscriber: matmarex.Tue, Jul 12, 1:06 AM

Another instance reported here: https://pl.wikipedia.org/wiki/Wikipedia:Prośby_do_administratorów#Problem_z_logowaniem_na_konto_darlitwiki16 (Darlitwiki16@commonswiki). Could you please fix the affected account?

matmarex added a comment.Tue, Jul 12, 1:07 AM

I think this error has become more frequent lately.

matmarex added a comment.Tue, Jul 12, 2:00 AM

Unless Logstash is lying to me, this appears to have skyrocketed after wmf.9 deployment…

field : message 
query : "Could not find local user data for"

Is there some way to access this data using some less awful interface than https://logstash.wikimedia.org/ to verify?

Legoktm added a comment.Tue, Jul 12, 2:04 AM

P3370 (An Untitled Masterwork)
1​legoktm@fluorine:/a/mw-log/archive$ zgrep -c "Could not find local user data for" exception.log-20160*
2​exception.log-20160412.gz:52
3​exception.log-20160413.gz:62
4​exception.log-20160414.gz:30
5​exception.log-20160415.gz:48
6​exception.log-20160416.gz:24
7​exception.log-20160417.gz:20
8​exception.log-20160418.gz:22
9​exception.log-20160419.gz:34
10​exception.log-20160420.gz:958
11​exception.log-20160421.gz:36
12​exception.log-20160422.gz:664
13​exception.log-20160423.gz:62
14​exception.log-20160424.gz:10
15​exception.log-20160425.gz:30
16​exception.log-20160426.gz:30
17​exception.log-20160427.gz:20
18​exception.log-20160428.gz:28
19​exception.log-20160429.gz:14
20​exception.log-20160430.gz:32
21​exception.log-20160501.gz:18
22​exception.log-20160502.gz:48
23​exception.log-20160503.gz:28
24​exception.log-20160504.gz:36
25​exception.log-20160505.gz:306
26​exception.log-20160506.gz:168
27​exception.log-20160507.gz:80
28​exception.log-20160508.gz:90
29​exception.log-20160509.gz:62
30​exception.log-20160510.gz:56
31​exception.log-20160511.gz:78
32​exception.log-20160512.gz:70
33​exception.log-20160513.gz:108
34​exception.log-20160514.gz:12
35​exception.log-20160515.gz:14
36​exception.log-20160516.gz:20
37​exception.log-20160517.gz:34
38​exception.log-20160518.gz:26
39​exception.log-20160519.gz:20
40​exception.log-20160520.gz:42
41​exception.log-20160521.gz:30
42​exception.log-20160522.gz:30
43​exception.log-20160523.gz:22
44​exception.log-20160524.gz:36
45​exception.log-20160525.gz:22
46​exception.log-20160526.gz:40
47​exception.log-20160527.gz:58
48​exception.log-20160528.gz:94
49​exception.log-20160529.gz:22
50​exception.log-20160530.gz:38
51​exception.log-20160531.gz:114
52​exception.log-20160601.gz:374
53​exception.log-20160602.gz:62
54​exception.log-20160603.gz:40
55​exception.log-20160604.gz:48
56​exception.log-20160605.gz:34
57​exception.log-20160606.gz:30
58​exception.log-20160607.gz:52
59​exception.log-20160608.gz:116
60​exception.log-20160609.gz:150
61​exception.log-20160610.gz:128
62​exception.log-20160611.gz:412
63​exception.log-20160612.gz:256
64​exception.log-20160613.gz:1052
65​exception.log-20160614.gz:512
66​exception.log-20160615.gz:370
67​exception.log-20160616.gz:302
68​exception.log-20160617.gz:392
69​exception.log-20160618.gz:280
70​exception.log-20160619.gz:350
71​exception.log-20160620.gz:288
72​exception.log-20160621.gz:346
73​exception.log-20160622.gz:316
74​exception.log-20160623.gz:490
75​exception.log-20160624.gz:240
76​exception.log-20160625.gz:270
77​exception.log-20160626.gz:166
78​exception.log-20160627.gz:214
79​exception.log-20160628.gz:214
80​exception.log-20160629.gz:316
81​exception.log-20160630.gz:1354
82​exception.log-20160701.gz:420
83​exception.log-20160702.gz:352
84​exception.log-20160703.gz:196
85​exception.log-20160704.gz:246
86​exception.log-20160705.gz:298
87​exception.log-20160706.gz:872
88​exception.log-20160707.gz:3284
89​exception.log-20160708.gz:4056
90​exception.log-20160709.gz:4686
91​exception.log-20160710.gz:4084
92​exception.log-20160711.gz:4730

bd808 added a comment.Tue, Jul 12, 4:33 AM
In T119736#2451064, @matmarex wrote:

Another instance reported here: https://pl.wikipedia.org/wiki/Wikipedia:Prośby_do_administratorów#Problem_z_logowaniem_na_konto_darlitwiki16 (Darlitwiki16@commonswiki). Could you please fix the affected account?

{{done}}

Here's what the data looked like:

[centralauth]> select * from localuser where lu_name = 'Darlitwiki16';
+---------------+--------------+-----------------------+--------------------+
| lu_wiki       | lu_name      | lu_attached_timestamp | lu_attached_method |
+---------------+--------------+-----------------------+--------------------+
| commonswiki   | Darlitwiki16 | 20160710134127        | login              |
| enwiki        | Darlitwiki16 | 20160710130142        | login              |
| loginwiki     | Darlitwiki16 | 20160710130138        | login              |
| mediawikiwiki | Darlitwiki16 | 20160710130139        | login              |
| metawiki      | Darlitwiki16 | 20160710130140        | login              |
| plwiki        | Darlitwiki16 | 20160710130138        | new                |
+---------------+--------------+-----------------------+--------------------+
6 rows in set (0.01 sec)

The commonswiki record is the bad one here. Here are the interesting log messages leading up the errors (newest to oldest):

2016-07-10T13:41:28.000Z commonswiki mw1198 Can only obtain a centralauthtoken when using CentralAuth sessions
2016-07-10T13:41:28.000Z commonswiki mw1198 Race condition? Already attached Darlitwiki16@commonswiki, just tried by 'login'
2016-07-10T13:41:28.000Z commonswiki mw1198 MediaWiki\Auth\AuthManager::autoCreateUser: creating new user (Darlitwiki16) - from: /w/api.php?action=query&format=json&origin=https%3A%2F%2Fpl%2Ewikipedia%2Eorg&centralauthtoken=REDACTED&meta=siteinfo&siprop=uploaddialog&formatversion=2
2016-07-10T13:41:27.000Z commonswiki mw1144 Can only obtain a centralauthtoken when using CentralAuth sessions
2016-07-10T13:41:27.000Z commonswiki mw1144 Attaching local user Darlitwiki16@commonswiki by 'login'
2016-07-10T13:41:27.000Z commonswiki mw1144 MediaWiki\Auth\AuthManager::autoCreateUser: creating new user (Darlitwiki16) - from: /w/api.php?action=query&format=json&origin=https%3A%2F%2Fpl%2Ewikipedia%2Eorg&centralauthtoken=REDACTED&meta=userinfo&uiprop=groups%7Crights

The "Can only obtain a centralauthtoken when using CentralAuth sessions" exceptions look like they may be the cause of the local commonswiki User not being saved.

2016-07-10 13:41:27 [V4JQhwpAEHwAAEgXGxgAAAAV] mw1144 commonswiki 1.28.0-wmf.9 exception ERROR: [V4JQhwpAEHwAAEgXGxgAAAAV] /w/api.php?action=query&format=json&origin=https%3A%2F%2Fpl%2Ewikipedia%2Eorg&centralauthtoken=REDACTED&meta=userinfo&uiprop=groups%7Crights   UsageException from line 1487 of /srv/mediawiki/php-1.28.0-wmf.9/includes/api/ApiBase.php: Can only obtain a centralauthtoken when using CentralAuth sessions {"exception_id":"V4JQhwpAEHwAAEgXGxgAAAAV"}
[Exception UsageException] (/srv/mediawiki/php-1.28.0-wmf.9/includes/api/ApiBase.php:1487) Can only obtain a centralauthtoken when using CentralAuth sessions
  #0 /srv/mediawiki/php-1.28.0-wmf.9/extensions/CentralAuth/includes/api/ApiCentralAuthToken.php(51): ApiBase->dieUsage(string, string)
  #1 /srv/mediawiki/php-1.28.0-wmf.9/includes/api/ApiMain.php(1406): ApiCentralAuthToken->execute()
  #2 /srv/mediawiki/php-1.28.0-wmf.9/includes/api/ApiMain.php(471): ApiMain->executeAction()
  #3 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/includes/ForeignWikiRequest.php(39): ApiMain->execute()
  #4 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/includes/ForeignWikiRequest.php(78): EchoForeignWikiRequest->getCentralAuthToken(User)
  #5 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/includes/ForeignWikiRequest.php(58): EchoForeignWikiRequest->getQueryParams(string)
  #6 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/includes/ForeignWikiRequest.php(25): EchoForeignWikiRequest->getRequestParams()
  #7 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/includes/NotifUser.php(710): EchoForeignWikiRequest->execute()
  #8 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/includes/NotifUser.php(741): MWEchoNotifUser->getForeignData()
  #9 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/includes/NotifUser.php(488): MWEchoNotifUser->getForeignCount(string)
  #10 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/Hooks.php(1147): MWEchoNotifUser->resetNotificationCount()
  #11 /srv/mediawiki/php-1.28.0-wmf.9/includes/Hooks.php(195): EchoHooks::onUserSaveSettings(User)
  #12 /srv/mediawiki/php-1.28.0-wmf.9/includes/user/User.php(3952): Hooks::run(string, array)
  #13 /srv/mediawiki/php-1.28.0-wmf.9/includes/auth/AuthManager.php(1678): User->saveSettings()
  #14 /srv/mediawiki/php-1.28.0-wmf.9/includes/Setup.php(861): MediaWiki\Auth\AuthManager->autoCreateUser(User, string, boolean)
  #15 /srv/mediawiki/php-1.28.0-wmf.9/includes/WebStart.php(137): include(string)
  #16 /srv/mediawiki/php-1.28.0-wmf.9/api.php(38): include(string)
  #17 /srv/mediawiki/w/api.php(3): include(string)
  #18 {main}
Stashbot added a comment.Tue, Jul 12, 4:37 AM

Mentioned in SAL [2016-07-12T04:37:41Z] <ori> Reverted all wikis to wmf8 due to tenfold increase in T119736

MZMcBride added a comment.Tue, Jul 12, 4:46 AM

Reading through this task, we've failed in a number of unacceptable ways here. Once the immediate issue is resolved and we're no longer throwing thousands of exceptions per day, this task should have a full postmortem to ensure that we identify and learn from what went wrong here. I'll file a separate task about doing this.

gerritbot added a comment.Tue, Jul 12, 6:11 AM

Change 298416 had a related patch set uploaded (by Legoktm):
Don't block logins if CentralAuthUser::queryAttached() fails

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

gerritbot added a comment.Tue, Jul 12, 6:27 AM

Change 298416 merged by jenkins-bot:
Don't block logins if CentralAuthUser::queryAttached() fails

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

Stashbot added a comment.Tue, Jul 12, 6:31 AM

Mentioned in SAL [2016-07-12T06:31:57Z] <legoktm@tin> Synchronized wmf-config/CommonSettings.php: Don't block logins if CentralAuthUser::queryAttached() fails - T119736 (duration: 00m 27s)

gerritbot added a comment.Tue, Jul 12, 6:47 AM

Change 295501 merged by jenkins-bot:
Add single-user option to checkLocalUser.php

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

gerritbot added a comment.Tue, Jul 12, 7:07 AM

Change 298417 had a related patch set uploaded (by Catrope):
ForeignWikiRequest: Bail early for non-global users

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

Catrope added a subscriber: Catrope.Tue, Jul 12, 7:08 AM
In T119736#2451220, @bd808 wrote:

[Exception UsageException] (/srv/mediawiki/php-1.28.0-wmf.9/includes/api/ApiBase.php:1487) Can only obtain a centralauthtoken when using CentralAuth sessions

#0 /srv/mediawiki/php-1.28.0-wmf.9/extensions/CentralAuth/includes/api/ApiCentralAuthToken.php(51): ApiBase->dieUsage(string, string)
#1 /srv/mediawiki/php-1.28.0-wmf.9/includes/api/ApiMain.php(1406): ApiCentralAuthToken->execute()
#2 /srv/mediawiki/php-1.28.0-wmf.9/includes/api/ApiMain.php(471): ApiMain->executeAction()
#3 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/includes/ForeignWikiRequest.php(39): ApiMain->execute()
#4 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/includes/ForeignWikiRequest.php(78): EchoForeignWikiRequest->getCentralAuthToken(User)
#5 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/includes/ForeignWikiRequest.php(58): EchoForeignWikiRequest->getQueryParams(string)
#6 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/includes/ForeignWikiRequest.php(25): EchoForeignWikiRequest->getRequestParams()
#7 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/includes/NotifUser.php(710): EchoForeignWikiRequest->execute()
#8 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/includes/NotifUser.php(741): MWEchoNotifUser->getForeignData()
#9 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/includes/NotifUser.php(488): MWEchoNotifUser->getForeignCount(string)
#10 /srv/mediawiki/php-1.28.0-wmf.9/extensions/Echo/Hooks.php(1147): MWEchoNotifUser->resetNotificationCount()
#11 /srv/mediawiki/php-1.28.0-wmf.9/includes/Hooks.php(195): EchoHooks::onUserSaveSettings(User)
#12 /srv/mediawiki/php-1.28.0-wmf.9/includes/user/User.php(3952): Hooks::run(string, array)
#13 /srv/mediawiki/php-1.28.0-wmf.9/includes/auth/AuthManager.php(1678): User->saveSettings()
#14 /srv/mediawiki/php-1.28.0-wmf.9/includes/Setup.php(861): MediaWiki\Auth\AuthManager->autoCreateUser(User, string, boolean)
#15 /srv/mediawiki/php-1.28.0-wmf.9/includes/WebStart.php(137): include(string)
#16 /srv/mediawiki/php-1.28.0-wmf.9/api.php(38): include(string)
#17 /srv/mediawiki/w/api.php(3): include(string)
#18 {main}





This is an unforeseen consequence of $wgEchoBundleTransition / $wgEchoSectionTransition. Only when those variables are set does this code path result in trying to get a CentralAuth token. I've attached a patch that ensures EchoForeignWikiRequest::getCentralAuthToken() is not called if CentralIdLookup::centralIdFromLocalUser() returns zero (if there's a better way to check for unattachedness, please tell me) so that should prevent this exception from ever occurring, at least from an Echo code path.
gerritbot added a comment.Tue, Jul 12, 7:29 AM
Change 298417 merged by jenkins-bot:

ForeignWikiRequest: Bail early for non-global users



https://gerrit.wikimedia.org/r/298417
gerritbot added a comment.Tue, Jul 12, 9:12 AM
Change 298429 had a related patch set uploaded (by Paladox):

ForeignWikiRequest: Bail early for non-global users



https://gerrit.wikimedia.org/r/298429
Josve05a added a comment.Tue, Jul 12, 9:46 AM
[V4SvmgpAMCUAAC@a2goAAABO] 2016-07-12 08:51:39: Fatal exception of type "Exception" in https://ticket.wikimedia.org/otrs/index.pl?Action=AgentTicketZoom;TicketID=9297642
gerritbot added a comment.Tue, Jul 12, 3:12 PM
Change 298429 merged by jenkins-bot:

ForeignWikiRequest: Bail early for non-global users



https://gerrit.wikimedia.org/r/298429
Stashbot added a comment.Tue, Jul 12, 3:33 PM
Mentioned in SAL [2016-07-12T15:33:34Z] <thcipriani@tin> Synchronized php-1.28.0-wmf.9/extensions/Echo/includes/ForeignWikiRequest.php: SWAT: [[gerrit:298429|ForeignWikiRequest: Bail early for non-global users (T119736)]] (duration: 00m 31s)
gerritbot added a comment.Tue, Jul 12, 4:12 PM
Change 298512 had a related patch set uploaded (by Mattflaschen):

ForeignWikiRequest: Bail early for non-global users



https://gerrit.wikimedia.org/r/298512
gerritbot added a comment.Tue, Jul 12, 4:20 PM
Change 298512 merged by jenkins-bot:

ForeignWikiRequest: Bail early for non-global users



https://gerrit.wikimedia.org/r/298512
Stashbot added a comment.Tue, Jul 12, 4:25 PM
Mentioned in SAL [2016-07-12T16:25:35Z] <mattflaschen@tin> Synchronized php-1.28.0-wmf.8/extensions/Echo/includes/ForeignWikiRequest.php: T119736: ForeignWikiRequest: Bail early for non-global users (duration: 00m 32s)
Anomie added a subscriber: Anomie.Tue, Jul 12, 4:29 PM
From IRC:






<greg-g> anomie: what are the next steps on resovling that issue from your prespective? or tgr|away's? is the Echo issue "the" cause or "a" cause?

<anomie> greg-g: Echo is the only cause I see in several spot checks, but I haven't checked the history of all the thousands of accounts affected at the moment. The thing to do is probably to fix Echo, run the maintenance script to fix the currently-affected users, and then try to see what other causes might be left.

<greg-g> anomie: can you comment with something similar on that task, please.



greg added a comment.Tue, Jul 12, 4:33 PM


In T119736#2453896, @Stashbot wrote:


Mentioned in SAL [2016-07-12T16:25:35Z] <mattflaschen@tin> Synchronized php-1.28.0-wmf.8/extensions/Echo/includes/ForeignWikiRequest.php: T119736: ForeignWikiRequest: Bail early for non-global users (duration: 00m 32s)







16:30 < matt_flas> greg-g, it (NB: that deploy) should fix the Echo cause.
16:31 < matt_flas> greg-g, I'm not certain if CentralAuth is doing the right thing here, though.
greg added a subscriber: greg.Tue, Jul 12, 4:44 PM
Mattflaschen-WMF added a subscriber: Mattflaschen-WMF.EditedTue, Jul 12, 4:53 PM
A couple notes:



    

  1. The entire cluster was reverted to wmf/1.28.0-wmf.8 as a result of this bug.
    2. 




    

  1. Echo is one of the causes of this, as shown in @bd808's trace above.  Specifically, while an account is being auto-created, they do not yet have a CentralAuth session.  Echo would try to use CentralAuth in this case, which would fail and prevent the account from being created.  Echo has been updated in master and wmf.8 and wmf.9 (wmf.10 has not been cut yet) to stop trying to use the CentralAuth session in this case, which should fix the Echo trigger for this.  This only happened when the Echo transition flags are on.  We should investigate if CentralAuth can allow this scenario: T140127: "Can only obtain a centralauthtoken when using CentralAuth sessions" during auto-creation.
    2. 




    

  1. The Echo transition flag was first turned on (initially on group 0, rOMWCc05ef5ec3c7e: Enable Echo transition flags on group 0 wikis) on July 5th.  P3370 shows the number of errors starting its current run of "over 100" on 2016-06-08.  There is a spike of over 1000 on 2016-06-13.  It then stays in the low hundreds until starting to spike on 2016-07-06, and then going into the thousands.  So clearly Echo was a major cause, but there is at least one (maybe two) pre-existing causes.
    2. 




    

  1. We still need to run checkLocalUser.php --delete=1 to fix the missing accounts CentralAuth thinks exist.
    2. 

gerritbot added a comment.Tue, Jul 12, 5:04 PM
Change 298527 had a related patch set uploaded (by Paladox):

Add single-user option to checkLocalUser.php



https://gerrit.wikimedia.org/r/298527
gerritbot added a comment.Tue, Jul 12, 5:06 PM
Change 298528 had a related patch set uploaded (by Paladox):

Add single-user option to checkLocalUser.php



https://gerrit.wikimedia.org/r/298528
gerritbot added a comment.Tue, Jul 12, 5:37 PM
Change 298531 had a related patch set uploaded (by Anomie):

AuthManager: Commit transaction after auto-creating a user



https://gerrit.wikimedia.org/r/298531
Mattflaschen-WMF added a comment.Tue, Jul 12, 5:46 PM


In T119736#2454093, @Mattflaschen-WMF wrote:


    

  1. We still need to run checkLocalUser.php --delete=1 to fix the missing accounts CentralAuth thinks exist.
    2. 






Started:



(time foreachwiki extensions/CentralAuth/maintenance/checkLocalUser.php --delete=1 --verbose=1) 2>&1|tee --append 2016-07-12_checkLocalUser.php_delete.log



to clean up existing users with inconsistent state on all wikis.
gerritbot added a comment.Tue, Jul 12, 5:57 PM
Change 298531 merged by jenkins-bot:

AuthManager: Commit transaction after auto-creating a user



https://gerrit.wikimedia.org/r/298531
gerritbot added a comment.Tue, Jul 12, 6:10 PM
Change 298540 had a related patch set uploaded (by Anomie):

AuthManager: Commit transaction after auto-creating a user



https://gerrit.wikimedia.org/r/298540
gerritbot added a comment.Tue, Jul 12, 6:11 PM
Change 298541 had a related patch set uploaded (by Anomie):

AuthManager: Commit transaction after auto-creating a user



https://gerrit.wikimedia.org/r/298541
gerritbot added a comment.Tue, Jul 12, 6:19 PM
Change 298540 merged by jenkins-bot:

AuthManager: Commit transaction after auto-creating a user



https://gerrit.wikimedia.org/r/298540
gerritbot added a comment.Tue, Jul 12, 6:21 PM
Change 298541 merged by jenkins-bot:

AuthManager: Commit transaction after auto-creating a user



https://gerrit.wikimedia.org/r/298541
Maldovix added a comment.Tue, Jul 12, 6:43 PM
Before I unsubscribe to this thread, just wanted to shout a thank you out to bd808 and gerritbot all the other superusers helping out here.  MVPs of the task thread!
Maldovix removed a subscriber: Maldovix.Tue, Jul 12, 6:43 PM
gerritbot added a comment.Tue, Jul 12, 6:54 PM
Change 298551 had a related patch set uploaded (by Mattflaschen):

Troubleshoot why Echo is still triggering CA failures



https://gerrit.wikimedia.org/r/298551
gerritbot added a comment.Tue, Jul 12, 7:15 PM
Change 298551 merged by jenkins-bot:

Troubleshoot why Echo is still triggering CA failures



https://gerrit.wikimedia.org/r/298551
gerritbot added a comment.Tue, Jul 12, 7:17 PM
Change 298553 had a related patch set uploaded (by Mattflaschen):

Troubleshoot why Echo is still triggering CA failures



https://gerrit.wikimedia.org/r/298553
gerritbot added a comment.Tue, Jul 12, 7:17 PM
Change 298554 had a related patch set uploaded (by Mattflaschen):

Troubleshoot why Echo is still triggering CA failures



https://gerrit.wikimedia.org/r/298554
gerritbot added a comment.Tue, Jul 12, 7:25 PM
Change 298553 merged by jenkins-bot:

Troubleshoot why Echo is still triggering CA failures



https://gerrit.wikimedia.org/r/298553
gerritbot added a comment.Tue, Jul 12, 7:25 PM
Change 298554 merged by jenkins-bot:

Troubleshoot why Echo is still triggering CA failures



https://gerrit.wikimedia.org/r/298554
Stashbot added a comment.Tue, Jul 12, 7:30 PM
Mentioned in SAL [2016-07-12T19:30:11Z] <mattflaschen@tin> Synchronized php-1.28.0-wmf.8/extensions/Echo/includes/ForeignWikiRequest.php: T119736: T140144: Troubleshoot why Echo is still triggering CA failures (duration: 00m 39s)
Mattflaschen-WMF added a comment.Tue, Jul 12, 7:31 PM
The Echo fix didn't work as intended, so I put up a troubleshooting patch.  Please follow T140144: Echo triggering CentralAuth "Can only obtain a centralauthtoken when using CentralAuth sessions" error for the Echo-specific part going forward.
Michgrig removed a subscriber: Michgrig.Tue, Jul 12, 9:04 PM
jayvdb added a subscriber: jayvdb.Wed, Jul 13, 12:24 AM
dr0ptp4kt added a subscriber: dr0ptp4kt.Wed, Jul 13, 3:36 PM


In T119736#2451232, @MZMcBride wrote:


Reading through this task, we've failed in a number of unacceptable ways here. Once the immediate issue is resolved and we're no longer throwing thousands of exceptions per day, this task should have a full postmortem to ensure that we identify and learn from what went wrong here. I'll file a separate task about doing this.





Agreed. I've set a meeting for 20-July-2016 at 11:30-12:30 SF time (subject to change, but wanted to get something on people's calendars before their schedules fill up). Anyone who wants to join, please email me directly well ahead of time so I can add you to the Hangout.
JJMC89 added a comment.Wed, Jul 13, 4:52 PM


In T119736#2449636, @bd808 wrote:




In T119736#2445005, @JJMC89 wrote:


Special:CentralAuth for Acastrohowell gives Fatal exception of type "Exception" after getting To avoid creating high replication lag, this transaction was aborted because the write duration (6.1167709827423) exceeded the 5 seconds limit. If you are changing many items at once, try doing multiple smaller operations instead. when attempting to create at enwiki.





Error was "Could not find local user data for Acastrohowell@enwiki" which interestingly was the "new" wiki for the account. Manually deleted the dangling reference and https://en.wikipedia.org/w/index.php?title=Special%3ACentralAuth&target=Acastrohowell works now.





Not sure if this will be helpful to you or not, but all of the exceptions that I have reported in this task were new accounts created via Special:CreateAccount at enwiki. @ori provided a trace for the first one that I encountered and reported on IRC which did not point to Echo.
Anomie added a subscriber: aaron.Wed, Jul 13, 5:37 PM


In T119736#2458586, @JJMC89 wrote:


Not sure if this will be helpful to you or not, but all of the exceptions that I have reported in this task were new accounts created via Special:CreateAccount at enwiki. @ori provided a trace for the first one that I encountered and reported on IRC which did not point to Echo.





The real cause of the problem for Optimus24 was very likely



exception.log-20160629.gz
2016-06-29 04:26:37 [V3NN9ApAIDEAAAuRbAgAAAAL] mw1179 enwiki 1.28.0-wmf.7 exception ERROR: [V3NN9ApAIDEAAAuRbAgAAAAL] /w/index.php?title=Special:CreateAccount&returnto=[REDACTED]   DBTransactionError from line 235 of /srv/mediawiki/php-1.28.0-wmf.7/includes/db/loadbalancer/LBFactory.php: To avoid creating high replication lag, this transaction was aborted because the write duration (6.002995967865) exceeded the 5 seconds limit.
If you are changing many items at once, try doing multiple smaller operations instead. {"exception_id":"V3NN9ApAIDEAAAuRbAgAAAAL"} 
[Exception DBTransactionError] (/srv/mediawiki/php-1.28.0-wmf.7/includes/db/loadbalancer/LBFactory.php:235) To avoid creating high replication lag, this transaction was aborted because the write duration (6.002995967865) exceeded the 5 seconds limit.
If you are changing many items at once, try doing multiple smaller operations instead.
  #0 /srv/mediawiki/php-1.28.0-wmf.7/includes/db/loadbalancer/LoadBalancer.php(1310): Closure$LBFactory::commitMasterChanges(DatabaseMysqli)
  #1 /srv/mediawiki/php-1.28.0-wmf.7/includes/db/loadbalancer/LBFactory.php(237): LoadBalancer->forEachOpenConnection(Closure$LBFactory::commitMasterChanges;240668706)
  #2 /srv/mediawiki/php-1.28.0-wmf.7/includes/db/loadbalancer/LBFactoryMulti.php(411): Closure$LBFactory::commitMasterChanges#2(LoadBalancer)
  #3 /srv/mediawiki/php-1.28.0-wmf.7/includes/db/loadbalancer/LBFactory.php(238): LBFactoryMulti->forEachLB(Closure$LBFactory::commitMasterChanges#2;240668706)
  #4 /srv/mediawiki/php-1.28.0-wmf.7/includes/MediaWiki.php(562): LBFactory->commitMasterChanges(string, array)
  #5 /srv/mediawiki/php-1.28.0-wmf.7/includes/MediaWiki.php(540): MediaWiki::preOutputCommit(RequestContext)
  #6 /srv/mediawiki/php-1.28.0-wmf.7/includes/MediaWiki.php(753): MediaWiki->doPreOutputCommit()
  #7 /srv/mediawiki/php-1.28.0-wmf.7/includes/MediaWiki.php(520): MediaWiki->main()
  #8 /srv/mediawiki/php-1.28.0-wmf.7/index.php(43): MediaWiki->run()
  #9 /srv/mediawiki/w/index.php(3): include(string)
  #10 {main}



The immediate culprit for this one is @aaron's $wgMaxUserDBWriteDuration arbitrarily rolling back the creation of the user because the request took more than 5 seconds to process for some unknown reason. Mintudazel, Mtrmananes, and Agusteknik2016 that you reported all look like the same thing.



For anyone else with access to the logs who wants to try to track down causes, this is the procedure:



    

  1. Determine the wiki with the problem, i.e. the "{wiki}" in "Could not find local user data for {Username}@{wiki}".
    2. 

  2. Find the request ID for the creation of the user on the wiki. Generally, this will be in CentralAuth.log as "Attaching local user {Username}@{wiki}"
    3. 

  3. Look for other log messages, particularly exception logs, for that request ID.
      

    1. If the exception found would have caused a database rollback, you've probably found the culprit.
      2. 

    2. If the exception was before yesterday and the creation in step 2 was "by 'login'" chances are pretty good that https://gerrit.wikimedia.org/r/298531 fixed it already. Look for more recent examples.
      3. 

    4. 

bd808 added a comment.EditedWed, Jul 13, 5:46 PM


In T119736#2458586, @JJMC89 wrote:


Not sure if this will be helpful to you or not, but all of the exceptions that I have reported in this task were new accounts created via Special:CreateAccount at enwiki. @ori provided a trace for the first one that I encountered and reported on IRC which did not point to Echo.





The stack traces for the end user visible "Could not find local user data for ..." exceptions actually aren't very interesting. They will all lead back to one of two or three methods in CentralAuthUser where the data from the localuser table is checked against the attached wiki user table.



The interesting traces are the ones that caused the transaction creating the user row to be rolled back after the CentralAuth association was made initially. These however are pretty tricky to find and actually correlate with the creation of the localuser record. I mostly stumbled upon the correlation mentioned in T119736#2451220 that lead to @Catrope and @Mattflaschen-WMF's work in T140144.



@Anomie's patch at rMW83c66caa0831: AuthManager: Commit transaction after auto-creating a user should help quite a bit with narrowing the types of problems that can cause the local wiki's User record to be rolled back. It forces a transaction commit just before the end of AuthManager::autoCreateUser. The window for a rollback error is now limited to unhandled exceptions and fatal errors that happen via:



    

  • autoCreatedAccount calls on primary and secondary authentication providers
    • 

  • AuthPluginAutoCreate and LocalUserCreated hook handlers
    • 

  • User::saveSettings
    • 

  • User::addWatch
    • 

  • ManualLogEntry::insert
    • 




The Flow related bug was causing an unhandled exception during User::saveSettings via a UserSaveSettings hook call.
Add Comment
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 and Privacy Policy. · Wikimedia Foundation · Privacy Policy · Terms of Use · Disclaimer · CC-BY-SA · GPL