Page MenuHomePhabricator

CentralAuthHooks::attemptAddUser: failed with message Username entered already in use. on loginwiki
Closed, ResolvedPublic

Description

I think this is a race condition of some kind:

2014-07-14 23:44:02 mw1209 loginwiki: CentralAuthHooks::attemptAddUser: creating new user ([username])
2014-07-14 23:44:02 mw1049 loginwiki: CentralAuthHooks::attemptAddUser: creating new user ([username])
2014-07-14 23:44:02 mw1049 loginwiki: CentralAuthHooks::attemptAddUser: failed with message Username entered already in use.
Please choose a different name.

For some reason, there were two simultaneous autocreation attempts, one succeeded, and the other of course failed. Here's a scarier one:

2014-07-14 23:44:53 mw1150 loginwiki: CentralAuthHooks::attemptAddUser: creating new user ([username2])
2014-07-14 23:44:53 mw1062 loginwiki: CentralAuthHooks::attemptAddUser: creating new user ([username2])
2014-07-14 23:44:53 mw1174 loginwiki: CentralAuthHooks::attemptAddUser: creating new user ([username2])
2014-07-14 23:44:53 mw1019 loginwiki: CentralAuthHooks::attemptAddUser: creating new user ([username2])
2014-07-14 23:44:53 mw1187 loginwiki: CentralAuthHooks::attemptAddUser: creating new user ([username2])
2014-07-14 23:44:53 mw1174 loginwiki: CentralAuthHooks::attemptAddUser: failed with message Username entered already in use.
Please choose a different name.
2014-07-14 23:44:53 mw1062 loginwiki: CentralAuthHooks::attemptAddUser: failed with message Username entered already in use.
Please choose a different name.
2014-07-14 23:44:53 mw1187 loginwiki: CentralAuthHooks::attemptAddUser: failed with message Username entered already in use.
Please choose a different name.
2014-07-14 23:44:53 mw1019 loginwiki: CentralAuthHooks::attemptAddUser: failed with message Username entered already in use.
Please choose a different name.
2014-07-14 23:44:53 mw1038 loginwiki: CentralAuthHooks::attemptAddUser: creating new user ([username2])
2014-07-14 23:44:53 mw1038 loginwiki: CentralAuthHooks::attemptAddUser: failed with message Username entered already in use.
Please choose a different name.

This one has 6! attempts, 5 of which fail.


Version: unspecified
Severity: normal

Details

Reference
bz68012
Related Gerrit Patches:

Event Timeline

bzimport raised the priority of this task from to Needs Triage.Nov 22 2014, 3:31 AM
bzimport set Reference to bz68012.
bzimport added a subscriber: Unknown Object (MLST).
Legoktm created this task.Jul 15 2014, 12:21 AM

There's some weird stuff going on here.

2014-07-15 01:29:15 mw1025 metawiki: CentralAuthHooks::attemptAddUser: creating new user ([username3])
2014-07-15 01:29:15 mw1188 metawiki: CentralAuthHooks::attemptAddUser: creating new user ([username3])
2014-07-15 01:29:15 mw1188 metawiki: CentralAuthHooks::attemptAddUser: failed with message El nombre de usuario indicado ya está en uso.

Now, if we just autocreated the user, how is their language already set to Spanish? metawiki's default should be English.

Aklapper triaged this task as Low priority.Mar 23 2015, 5:37 PM
Aklapper added a subscriber: Aklapper.

There's some weird stuff going on here.

Anybody knows if this is still an issue nowadays?

Yes, it is still occurring.

Tgr added a subscriber: Tgr.Feb 12 2016, 3:54 AM

What probably happens here is that when the user makes their first login after account creation, CentralAuth displays a bunch of site icons (one for each SUL-enabled second-level domain that's not wikimedia.org, plus one for meta and commons each) which are supposed to preemptively log the user in on sites on that domain. Those images are generated by Special:CentralAuthAutologin on the respective sites, and those first redirect to loginwiki to check that the user is centrally logged in. These requests happen simultaneously and they each trigger autocreation, and that apparently results in race conditions.

Is that's true then there is some user effect from this as the autocreation failure means the user ends up as unauthenticated in that request, so the preemptive autologin fails. Not a big deal because there is still the normal autologin which is triggered when the users visits the given wiki.

Tgr added a comment.Feb 12 2016, 3:57 AM

Anybody knows if this is still an issue nowadays?

Happens fairly often, yes (on the scale of 1/s). https://logstash.wikimedia.org/#dashboard/temp/AVLTn06zptxhN1XaS38e

Tgr added a comment.Feb 18 2016, 1:01 AM
tgr@fluorine:~$ zcat /a/mw-log/archive/CentralAuth-Bug39996.log-20151215.gz | grep 'Username entered already in use.' | wc -l
1681

https://logstash.wikimedia.org/#dashboard/temp/AVLx4-B5ptxhN1Xap4QK
1445

So it does not seem like this bug has been significantly affected by SessionManager (and as such it's probably not the reason for T125054). Nevertheless, should be an easy fix.

Change 271460 had a related patch set uploaded (by Gergő Tisza):
Do not unauthenticate if autocreation fails due to a race

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

Change 271460 merged by jenkins-bot:
Do not unauthenticate if autocreation fails due to a race

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

Change 272835 had a related patch set uploaded (by Gergő Tisza):
Do not unauthenticate if autocreation fails due to a race

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

Change 272835 merged by jenkins-bot:
Do not unauthenticate if autocreation fails due to a race

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

Tgr closed this task as Resolved.Mar 4 2016, 1:49 AM
Tgr claimed this task.

The warning disappeared from the logs pretty much the same time the patch was deployed, and no ill effects were reported.