Server issue MySQL query error [1062]: Duplicate entry 'hasan69' for key 'xf_user.username'

[Nirjonadda]

Affected version

2.2.3 Patch 1

Server error log:

XF\Db\DuplicateKeyException: MySQL query error [1062]: Duplicate entry 'hasan69' for key 'xf_user.username' src/XF/Db/AbstractStatement.php:228

Generated by: Unknown account Mar 3, 2021 at 2:40 PM

Stack trace

INSERT  INTO `xf_user` (`visible`, `activity_visible`, `user_group_id`, `timezone`, `language_id`, `last_summary_email_date`, `username`, `email`, `user_state`, `privacy_policy_accepted`, `terms_accepted`, `dbtech_shop_purchase`, `display_style_group_id`, `secondary_group_ids`, `secret_key`, `user_id`, `username_date`, `username_date_visible`, `style_id`, `permission_combination_id`, `message_count`, `question_solution_count`, `alerts_unviewed`, `alerts_unread`, `conversations_unread`, `register_date`, `last_activity`, `trophy_points`, `avatar_date`, `avatar_width`, `avatar_height`, `avatar_highdpi`, `gravatar`, `security_lock`, `is_moderator`, `is_admin`, `is_staff`, `is_banned`, `reaction_score`, `vote_score`, `custom_title`, `warning_points`, `af_as_award_total`, `af_as_award_points`, `af_moods_mood_id`, `dbtech_credits_credits`, `dbtech_credits_lastdaily`, `dbtech_credits_lastinterest`, `dbtech_credits_lastpaycheck`, `dbtech_credits_lasttaxation`, `dbtech_mail_defaultkeyword`, `dbtech_mail_inactivereminder`, `dbtech_mail_numreminders`, `dbtech_mail_newsletter_frequency`, `dbtech_mail_newsletter_receive`, `dbtech_mail_newsletter_lastreceive`, `dbtech_mail_validation_date`, `dbtech_security_forcenewpass`, `dbtech_security_lastbreach`, `dbtech_security_breached`, `dbtech_shop_points`, `dbtech_shop_purchases`, `dbtech_shop_immunity`, `dbtech_shop_pendingtrades`, `dbtech_shop_item_count`, `eaetc_thread_count`, `snog_flag`, `thdonate_total_donation`, `thdonate_total_public_donation`, `thdonate_total_anonymous_donation`, `thdonate_num_donation`, `thdonate_num_public_donation`, `thdonate_num_anonymous_donation`, `xentr_verified`, `xfmg_album_count`, `xfmg_media_count`, `xfmg_media_quota`, `user_disable_id`, `useress_tags`, `siropu_easy_user_ban_count`, `siropu_referrer_id`, `siropu_referral_count`, `siropu_referrer_credit`, `snog_forms`, `trophies_level`) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
------------

#0 src/XF/Db/Mysqli/Statement.php(196): XF\Db\AbstractStatement->getException('MySQL query err...', 1062, '23000')
#1 src/XF/Db/Mysqli/Statement.php(77): XF\Db\Mysqli\Statement->getException('MySQL query err...', 1062, '23000')
#2 src/XF/Db/AbstractAdapter.php(94): XF\Db\Mysqli\Statement->execute()
#3 src/XF/Db/AbstractAdapter.php(218): XF\Db\AbstractAdapter->query('INSERT  INTO `x...', Array)
#4 src/XF/Mvc/Entity/Entity.php(1510): XF\Db\AbstractAdapter->insert('xf_user', Array, false)
#5 src/XF/Mvc/Entity/Entity.php(1242): XF\Mvc\Entity\Entity->_saveToSource()
#6 src/XF/Service/User/Registration.php(298): XF\Mvc\Entity\Entity->save()
#7 src/addons/SV/ModeratorEssentials/XF/Service/User/Registration.php(24): XF\Service\User\Registration->_save()
#8 src/XF/Service/ValidateAndSavableTrait.php(40): SV\ModeratorEssentials\XF\Service\User\Registration->_save()
#9 src/XF/Pub/Controller/Register.php(308): XF\Service\User\Registration->save()
#10 src/XF/Mvc/Dispatcher.php(350): XF\Pub\Controller\Register->actionConnectedAccountRegister(Object(XF\Mvc\ParameterBag))
#11 src/XF/Mvc/Dispatcher.php(257): XF\Mvc\Dispatcher->dispatchClass('XF:Register', 'ConnectedAccoun...', Object(XF\Mvc\RouteMatch), Object(AddonFlare\PaidRegistrations\XF\Pub\Controller\Register), NULL)
#12 src/XF/Mvc/Dispatcher.php(113): XF\Mvc\Dispatcher->dispatchFromMatch(Object(XF\Mvc\RouteMatch), Object(AddonFlare\PaidRegistrations\XF\Pub\Controller\Register), NULL)
#13 src/XF/Mvc/Dispatcher.php(55): XF\Mvc\Dispatcher->dispatchLoop(Object(XF\Mvc\RouteMatch))
#14 src/XF/App.php(2326): XF\Mvc\Dispatcher->run()
#15 src/XF.php(488): XF\App->run()
#16 index.php(20): XF::runApp('XF\\Pub\\App')
#17 {main}

Request state

array(4) {
  ["url"] => string(44) "/register/connected-accounts/google/register"
  ["referrer"] => string(58) "/register/connected-accounts/google/"
  ["_GET"] => array(0) {
  }
  ["_POST"] => array(14) {
    ["username"] => string(7) "hasan69"
    ["dob_month"] => string(1) "5"
    ["dob_day"] => string(1) "1"
    ["dob_year"] => string(4) "1994"
    ["location"] => string(5) "china"
    ["custom_fields"] => array(2) {
      ["gender"] => string(4) "male"
      ["siropu_referrer"] => string(0) ""
    }
    ["email_choice"] => string(1) "1"
    ["accept"] => string(1) "1"
    ["_xfRedirect"] => string(1) "/"
    ["timezone"] => string(0) ""
    ["_xfToken"] => string(8) "********"
    ["_xfRequestUri"] => string(36) "/register/connected-accounts/google/"
    ["_xfWithData"] => string(1) "1"
    ["_xfResponseType"] => string(4) "json"
  }
}

 

[Mike]

Realistically, I don't think we're going to make any explicit changes here. There just appears to be a race condition and we've done as much as we can to mitigate it. There are client side mitigations as well, which would normally mean that 2 browser windows would normally be required (or JS would be disabled).

At best we could catch it and not log the error, but the message we'd display to the end user would ultimately be the same thing. I'd rather have the error in this case because there was a period in the past where the code flow made the race condition much larger. (It's an edge case, if we got this error, I would not consider it safe to automatically log the user into the conflicting account without a bunch of other validation.) And given the other mitigations, this should be quite rare.

(I believe I've made reference to this before, but you have posted a number of race condition-based error logs like this. While they are certainly more likely on larger installs, high server loads will dramatically expand the window where they can occur.)

 

[PaulB]

@Mike Why not wrap this in a transaction? You'll get a proper error message if you do that. I know the idea of adding more transactions to XenForo is a contentious one, but the existing codebase just isn't written in a manner that's safe without transactions.

 

[Mike]

I don't think transactions are related here (though there are transactions here). The issue is really just the standard "time of check to time of use" race condition. One of the last things we do before we do the insert is check whether the username (and email) are used and trigger a "choose something different" message. Arguably more extensive transactions could extend the window (depending on isolation levels).

There are more extensive things that we could do to try to account for this but they ultimately end up in essentially the same thing and as far as I can tell, the only reports we've had of this issue since 2017 are actually from this user. (Pre-2017, the window was larger and we moved/reverified availability much closer to the save for that reason; that change seemed to stop virtually all reports.)

 

[PaulB]

the only reports we've had of this issue since 2017 are actually from this user.

We used to encounter quite a few race conditions on XF1; for obvious reasons, we don't report them, but instead fix them internally. In XF2, it certainly appears as though some of the same issues continue to exist, but we won't know for certain until we roll out XF2.

Arguably more extensive transactions could extend the window (depending on isolation levels).

I think the checks involved here are quick enough that extending it a little bit on the final check would make sense. If someone really hates transactions, they're free to tinker with the isolation level on their database at their own peril.

Over the years, I've seen some very strange reports of race conditions similar to this when they really shouldn't have been possible, yet specific users were able to reliably reproduce them. In some cases, it turned out that users actually had faulty mice, and, for whatever reason, were effectively double-clicking in such a way that the debounce JavaScript wasn't catching it.

There are more extensive things that we could do to try to account for this

I don't think that's necessary. As far as I can tell, the race condition here is unlikely to result in an inconsistent state, although it's possible. It should be as simple as wrapping the following lines from the Register controller in a transaction:

if (!$registration->validate($errors))
{
    return $this->error($errors);
}

$user = $registration->save();

Ideally, you'd extend the transaction to start before this line to avoid other possible race conditions, although it wouldn't have been necessary in the very specific example provided in this thread:

$userConnected = $this->getConnectedAccountRepo()->getUserConnectedAccountFromProviderData($providerData);

 

[Xon]

I think just capturing the DuplicateKeyException exception and telling the user they have already registered might be enough to mostly prevent this error.

:edit: Looking at the code; getUserConnectedAccountFromProviderData/associateConnectedAccountWithUser really need to go into the register service save transaction to ensure consistency is maintained.

The query in getUserConnectedAccountFromProviderData should likely be called with a FOR UPDATE row lock too.

 

[PaulB]

I think just capturing the DuplicateKeyException exception and telling the user they have already registered might be enough to mostly prevent this error.

It'll prevent the error described here, but it could still result in consistency issues due to conflicts earlier in that method. Currently, it looks a bit like the following:

1. Ensure the external provider account isn't already connected to a XenForo user
2. Validate and create the user
3. Associate the external provider account with the new XenForo user

The problem is #3: if there's an existing association, it'll be deleted:

// The provider+key combination is unique to a single user, so if we're trying to associate this
// account with a user, we need to remove any other association first.
$connectedAccount = $this->em->findOne('XF:UserConnectedAccount', [
   'provider' => $providerId,
   'provider_key' => $providerKey
]);
if ($connectedAccount && $connectedAccount->user_id != $user->user_id)
{
   $connectedAccount->delete();
   $connectedAccount = null;
}

The race condition could therefore result in a dangling user. This isn't the end of the world, but it's certainly a consistency issue. I can't imagine this is likely to occur often, since someone would need to try to submit two different usernames at the same time, but I could see it happening if someone with an unstable internet connection attempting two separate form submissions and ultimately sending both requests simultaneously. Weirder race conditions have happened.