Page MenuHomePhabricator

New accounts not being reliably created on loginwiki
Open, Needs TriagePublic

Description

There are reports that some accounts are not having a local account created on loginwiki when they are created elsewhere. Examples provided are

The user creation logs on loginwiki seem to show accounts are still being created, with spot checks showing the creations being within the same minute as the initial creation.

After some preliminary investigation, I note that all three show logstash messages for attaching the local user on mediawikiwiki via RunJobs.php, then later a logstash message again from RunJobs.php complaining that the local user can't be created on mediawikiwiki because it already exists.

Searching runJobs.log for one of these accounts, I see jobs for creation on metawiki and loginwiki claim to have been run, but there seem to be no corresponding messages in logstash for other channels.

anomie@mwlog1001:/srv/mw-log$ fgrep DoloresMessier runJobs.log 
2017-08-16 15:58:26 [WZRrngpAMEwAAIkJlJgAAAAB] mw1306 mediawikiwiki 1.30.0-wmf.14 runJobs DEBUG: CentralAuthCreateLocalAccountJob User:DoloresMessier name=DoloresMessier from=plwikiquote session={"ip":"REDACTED","headers":"array(...)","sessionId":"REDACTED","userId":32876} requestId=WZRrngpAMEwAAIkJlJgAAAAB (uuid=c00457475a844642b9d38cf23a5d96da,timestamp=1502899105,QueuePartition=rdb1-6379) STARTING {"job_type":"CentralAuthCreateLocalAccountJob"} 
2017-08-16 15:58:27 [WZRrngpAMEwAAIkJlJgAAAAB] mw1167 metawiki 1.30.0-wmf.13 runJobs DEBUG: CentralAuthCreateLocalAccountJob User:DoloresMessier name=DoloresMessier from=plwikiquote session={"ip":"REDACTED","headers":"array(...)","sessionId":"REDACTED","userId":32876} requestId=WZRrngpAMEwAAIkJlJgAAAAB (uuid=b2ad790ceee8425e9812ab4ab6e07ae3,timestamp=1502899105,QueuePartition=rdb4-6380) STARTING  
2017-08-16 15:58:27 [WZRrngpAMEwAAIkJlJgAAAAB] mw1300 loginwiki 1.30.0-wmf.13 runJobs DEBUG: CentralAuthCreateLocalAccountJob User:DoloresMessier name=DoloresMessier from=plwikiquote session={"ip":"REDACTED","headers":"array(...)","sessionId":"REDACTED","userId":32876} requestId=WZRrngpAMEwAAIkJlJgAAAAB (uuid=3e5007eeb8fd4157a5d794b95b4d12a5,timestamp=1502899105,QueuePartition=rdb2-6380) STARTING  
2017-08-16 15:58:33 [WZRrngpAMEwAAIkJlJgAAAAB] mw1167 metawiki 1.30.0-wmf.13 runJobs INFO: CentralAuthCreateLocalAccountJob User:DoloresMessier name=DoloresMessier from=plwikiquote session={"ip":"REDACTED","headers":"array(...)","sessionId":"","userId":0} requestId=WZRrngpAMEwAAIkJlJgAAAAB (uuid=b2ad790ceee8425e9812ab4ab6e07ae3,timestamp=1502899105,QueuePartition=rdb4-6380) t=6336 good  
2017-08-16 15:58:33 [WZRrngpAMEwAAIkJlJgAAAAB] mw1300 loginwiki 1.30.0-wmf.13 runJobs INFO: CentralAuthCreateLocalAccountJob User:DoloresMessier name=DoloresMessier from=plwikiquote session={"ip":"REDACTED","headers":"array(...)","sessionId":"","userId":0} requestId=WZRrngpAMEwAAIkJlJgAAAAB (uuid=3e5007eeb8fd4157a5d794b95b4d12a5,timestamp=1502899105,QueuePartition=rdb2-6380) t=6333 good  
2017-08-16 15:59:46 [c3c5161bc6c082983786d4dc] mw1305 plwikiquote 1.30.0-wmf.13 runJobs DEBUG: refreshLinksPrioritized REDACTED rootJobTimestamp=20170816155931 useRecursiveLinksUpdate=1 triggeringUser={"userId":32876,"userName":"DoloresMessier"} triggeringRevisionId=471514 requestId=c3c5161bc6c082983786d4dc (uuid=f79f09d7f8a24e139119bf2cefb66f9d,timestamp=1502899171,QueuePartition=rdb1-6381) STARTING  
2017-08-16 15:59:46 [c3c5161bc6c082983786d4dc] mw1305 plwikiquote 1.30.0-wmf.13 runJobs INFO: refreshLinksPrioritized REDACTED rootJobTimestamp=20170816155931 useRecursiveLinksUpdate=1 triggeringUser={"userId":32876,"userName":"DoloresMessier"} triggeringRevisionId=471514 requestId=c3c5161bc6c082983786d4dc (uuid=f79f09d7f8a24e139119bf2cefb66f9d,timestamp=1502899171,QueuePartition=rdb1-6381) t=106 good  
2017-08-16 16:58:28 [WZRrngpAMEwAAIkJlJgAAAAB] mw1303 mediawikiwiki 1.30.0-wmf.14 runJobs DEBUG: CentralAuthCreateLocalAccountJob User:DoloresMessier name=DoloresMessier from=plwikiquote session={"ip":"REDACTED","headers":"array(...)","sessionId":"REDACTED","userId":32876} requestId=WZRrngpAMEwAAIkJlJgAAAAB (uuid=c00457475a844642b9d38cf23a5d96da,timestamp=1502899105,QueuePartition=rdb1-6379) STARTING {"job_type":"CentralAuthCreateLocalAccountJob"} 
2017-08-16 16:58:28 [WZRrngpAMEwAAIkJlJgAAAAB] mw1303 mediawikiwiki 1.30.0-wmf.14 runJobs INFO: CentralAuthCreateLocalAccountJob User:DoloresMessier name=DoloresMessier from=plwikiquote session={"ip":"REDACTED","headers":"array(...)","sessionId":"","userId":0} requestId=WZRrngpAMEwAAIkJlJgAAAAB (uuid=c00457475a844642b9d38cf23a5d96da,timestamp=1502899105,QueuePartition=rdb1-6379) t=8 good {"job_type":"CentralAuthCreateLocalAccountJob","job_duration":8}

One other interesting item of note is that there's no entry in runJobs.log for the completion of the CentralAuthCreateLocalAccountJob job on mw1306 for mediawikiwiki. The other two show the same pattern for the CentralAuthCreateLocalAccountJob jobs.

Event Timeline

Anomie created this task.Aug 16 2017, 7:09 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptAug 16 2017, 7:09 PM
Anomie updated the task description. (Show Details)Aug 16 2017, 7:18 PM

One other item of note. I looked for accounts throwing the same sort of error to spot check, and found LEANDRO12121212 that did get the account auto-created on loginwiki but is missing metawiki. The runJobs.log logs for that one are

2017-08-16 17:07:27 [WZR7ywpAMFYAAKuSfIoAAAAQ] mw1299 loginwiki 1.30.0-wmf.13 runJobs DEBUG: CentralAuthCreateLocalAccountJob User:LEANDRO12121212 name=LEANDRO12121212 from=ptwiki session={"ip":"REDACTED","headers":"array(...)","sessionId":"REDACTED","userId":1982397} requestId=WZR7ywpAMFYAAKuSfIoAAAAQ (uuid=8b8e589a612543198b16bfdbd40e96c9,timestamp=1502903247,QueuePartition=rdb2-6379) STARTING  
2017-08-16 17:07:27 [WZR7ywpAMFYAAKuSfIoAAAAQ] mw1299 loginwiki 1.30.0-wmf.13 runJobs INFO: CentralAuthCreateLocalAccountJob User:LEANDRO12121212 name=LEANDRO12121212 from=ptwiki session={"ip":"REDACTED","headers":"array(...)","sessionId":"","userId":0} requestId=WZR7ywpAMFYAAKuSfIoAAAAQ (uuid=8b8e589a612543198b16bfdbd40e96c9,timestamp=1502903247,QueuePartition=rdb2-6379) t=87 good  
2017-08-16 17:07:27 [WZR7ywpAMFYAAKuSfIoAAAAQ] mw1304 mediawikiwiki 1.30.0-wmf.14 runJobs DEBUG: CentralAuthCreateLocalAccountJob User:LEANDRO12121212 name=LEANDRO12121212 from=ptwiki session={"ip":"REDACTED","headers":"array(...)","sessionId":"REDACTED","userId":1982397} requestId=WZR7ywpAMFYAAKuSfIoAAAAQ (uuid=fe69d8385011456a814653ec6fe9c1bb,timestamp=1502903247,QueuePartition=rdb4-6379) STARTING {"job_type":"CentralAuthCreateLocalAccountJob"} 
2017-08-16 17:07:34 [WZR7ywpAMFYAAKuSfIoAAAAQ] mw1165 metawiki 1.30.0-wmf.13 runJobs DEBUG: CentralAuthCreateLocalAccountJob User:LEANDRO12121212 name=LEANDRO12121212 from=ptwiki session={"ip":"REDACTED","headers":"array(...)","sessionId":"REDACTED","userId":1982397} requestId=WZR7ywpAMFYAAKuSfIoAAAAQ (uuid=5df246ca2cad41a8ab220d378f05f718,timestamp=1502903247,QueuePartition=rdb1-6381) STARTING  
2017-08-16 17:07:40 [WZR7ywpAMFYAAKuSfIoAAAAQ] mw1165 metawiki 1.30.0-wmf.13 runJobs INFO: CentralAuthCreateLocalAccountJob User:LEANDRO12121212 name=LEANDRO12121212 from=ptwiki session={"ip":"REDACTED","headers":"array(...)","sessionId":"","userId":0} requestId=WZR7ywpAMFYAAKuSfIoAAAAQ (uuid=5df246ca2cad41a8ab220d378f05f718,timestamp=1502903247,QueuePartition=rdb1-6381) t=6346 good  
2017-08-16 18:07:36 [WZR7ywpAMFYAAKuSfIoAAAAQ] mw1306 mediawikiwiki 1.30.0-wmf.14 runJobs DEBUG: CentralAuthCreateLocalAccountJob User:LEANDRO12121212 name=LEANDRO12121212 from=ptwiki session={"ip":"REDACTED","headers":"array(...)","sessionId":"REDACTED","userId":1982397} requestId=WZR7ywpAMFYAAKuSfIoAAAAQ (uuid=fe69d8385011456a814653ec6fe9c1bb,timestamp=1502903247,QueuePartition=rdb4-6379) STARTING {"job_type":"CentralAuthCreateLocalAccountJob"} 
2017-08-16 18:07:36 [WZR7ywpAMFYAAKuSfIoAAAAQ] mw1306 mediawikiwiki 1.30.0-wmf.14 runJobs INFO: CentralAuthCreateLocalAccountJob User:LEANDRO12121212 name=LEANDRO12121212 from=ptwiki session={"ip":"REDACTED","headers":"array(...)","sessionId":"","userId":0} requestId=WZR7ywpAMFYAAKuSfIoAAAAQ (uuid=fe69d8385011456a814653ec6fe9c1bb,timestamp=1502903247,QueuePartition=rdb4-6379) t=8 good {"job_type":"CentralAuthCreateLocalAccountJob","job_duration":8}

Same situation where there's no log for the end of the initial mediawikiwiki run. In this case it seems to have done the loginwiki job before the mediawikiwiki run rather than after, which is slightly suggestive that the mediawikiwiki run is somehow also preventing the concurrent/following CentralAuthCreateLocalAccountJobs from working properly.