POST /auth/oidc returns a 404 and logs error ID 3 in the Moodle logs for some users

[chrisfosterelli]

Hi there,

For some users, when they attempt to login, the login is recorded as successful on the O365 side, but fails on the Moodle side.

The request logs show the normal flow we would expect: they land on the home page, are redirected (we use the forced redirect), and then POST back to /auth/oidc.

However, instead of a successful login event from the OIDC plugin, we see a Moodle system event: "Login failed for user 'XXX'. Most likely the password did not match (error ID '3')"

The status code of the request is returned as 404, instead of the usual 303, which makes it apparent in the logs.

I have tried digging into the root cause but, without ability to directly reproduce, am finding it difficult to sort out. Do you have any advice for how this can happen, or where to look further?

[weilai-irl]

Hi @chrisfosterelli,

Assuming you are using the "Authorization code flow" in auth_oidc settings, the error you saw can be thrown at two occasions:

• If the user doesn't have an account in Moodle, therefore auth_oidc tries to create an account for the user, but the Moodle site "Prevent account creation when authenticating" is enabled.
• If Moodle has a valid token for the user (in mdl_auth_oidc_token table, search by "oidcusername" field matching user's UPN), but the "userid" field of the token record doesn't link to a valid active Moodle user. This can be caused by e.g. the Moodle account of the user is manually delete from other sources. In this case, you may want to delete the old invalid token record from DB.

Please check which situation your user is in.

Regards,
Lai

[chrisfosterelli]

Hey @weilai-irl

Thanks a lot for the response.

Assuming you are using the "Authorization code flow" in auth_oidc settings

Correct, this is the authorization code flow.

Moodle site "Prevent account creation when authenticating" is enabled

This setting is not enabled. Additionally, the user does have an account (the Moodle log shows the account in the 'affected user' column when it shows the error ID 3)

If Moodle has a valid token for the user (in mdl_auth_oidc_token table, search by "oidcusername" field matching user's UPN), but the "userid" field of the token record doesn't link to a valid active Moodle user.

If I search the table for the user's OIDC username, one row exists and the userid points to the correct Moodle account.

[chrisfosterelli]

We have enabled some additional debugging and captured some relevant stack traces:

During the request, it first triggers this warning:

PHP Notice:  Error: mdb->get_record() found more than one record!
line 1683 of /lib/dml/moodle_database.php: call to debugging()
line 1643 of /lib/dml/moodle_database.php: call to moodle_database->get_record_sql()
line 1622 of /lib/dml/moodle_database.php: call to moodle_database->get_record_select()
line 154 of /auth/oidc/classes/loginflow/authcode.php: call to moodle_database->get_record()
line 195 of /auth/oidc/auth.php: call to auth_oidc\\loginflow\\authcode->user_login()
line 4387 of /lib/moodlelib.php: call to auth_plugin_oidc->user_login()
line 510 of /auth/oidc/classes/loginflow/authcode.php: call to authenticate_user_login()
line 276 of /auth/oidc/classes/loginflow/authcode.php: call to auth_oidc\\loginflow\\authcode->handlelogin()
line 114 of /auth/oidc/classes/loginflow/authcode.php: call to auth_oidc\\loginflow\\authcode->handleauthresponse()
line 165 of /auth/oidc/auth.php: call to auth_oidc\\ in /var/www/html/lib/weblib.php on line 3257

Then eventually throws with:

Default exception handler: There was a problem logging you in. Please contact your administrator for assistance. Debug: 2
Error code: errorauthgeneral
* line 528 of /auth/oidc/classes/loginflow/authcode.php: moodle_exception thrown
* line 276 of /auth/oidc/classes/loginflow/authcode.php: call to auth_oidc\\loginflow\\authcode->handlelogin()
* line 114 of /auth/oidc/classes/loginflow/authcode.php: call to auth_oidc\\loginflow\\authcode->handleauthresponse()
* line 165 of /auth/oidc/auth.php: call to auth_oidc\\loginflow\\authcode->handleredirect()
* line 29 of /auth/oidc/index.php: call to auth_plugin_oidc->handleredirect()\n, referer: https://login.microsoftonline.com/

So it seems the final exception ultimately comes from here, suggesting that the call to moodle's authenticate_user_login is failing for whatever reason.

The first error that we see, about there being more than one record, seems to come from here, which is a query to the same table that you just mentioned. However, when I query the table, there is only one record. This may be because this section of code tries to delete the token, but does it based on the token ID rather than the username, so it'd only be clearing the first token that was returned up in the call to $DB->get_record in user_login. That'd suggest a new token is being created on every request, and I'm not sure what that token looks like, but perhaps it has some sort of issue?

Does that help at all? Should we delete the existing token in the table? Is my understanding correct that there is a new token being inserted on each request (I guess from here, meaning the oidcuniqid is not matching the one in the table) that is invalid, and then removed?

[chrisfosterelli]

@weilai-irl To update on this, we tried removing the token from the mdl_auth_oidc_token table and it did not resolve the issue. We instead had to delete the student's account as they were sort of eager to get going. Reauthenticating through OIDC after the previous account was deleted created a new account that was funcitonal.

So not too sure what the root cause was unfortunately. If you wish us to close this that's OK with me as it's technically resolved for us, but I'll leave it open for now in case you have thoughts or think this is a bug that needs further addressing.

[chrisfosterelli]

As an update, we have seen this happen with two additional students, both who have not logged in in some time.

[mmulrthelp]

@chrisfosterelli did you get any further in solving the issue which you are seeing. We are possibly seeing the same thing (I’ll do some log digging tomorrow).

What we see only effects a small number of users and only starts to re-occur after a new version of the o365 plugins has been installed. We have just installed the oct release and students are reporting this to us, but in small numbers.

To solve we currently take this users id and delete their token from the mdl_auth_oidc_token table & get the student to login again.

We are now thinking maybe because this seems to only occur after a new version is deployed, whether we should be deleting the entire mdl_auth_oidc_token table after deployment. As you say it always creates a new token on login. We have done this before without any issues as we had to many people experiencing it.

Something does not match on some peoples accounts… it could be certain devices / browsers which are causing it.

Hopefully in the next few days I’ll have some more information to report and help @weilai-irl solve for good.

[chrisfosterelli]

@mmulrthelp Not much further unfortunately. We got as far as determining that all the accounts exhibiting the issue were really old but had signed in at least once. We think it was associated with an upgrade as well.

The impact was small enough that we opted to manually delete any students that reached out with the error rather than continue investigating. We did an upgrade a few days later to 3.11.1 which mentioned it rewrote a lot of the logic so we were hoping that'd help. I haven't heard anything on this from the staff since then.