Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

DEV-421: Debug error message #15

Draft
wants to merge 6 commits into
base: master
Choose a base branch
from
Draft

DEV-421: Debug error message #15

wants to merge 6 commits into from

Conversation

ethho
Copy link
Contributor

@ethho ethho commented Feb 14, 2024 •
edited
Loading

Mirror of https://datajoint.atlassian.net/browse/DEV-421

Error message observed in prod Percona when using this plugin:

{"log":"2024-01-18T18:53:14.544917Z 908 [ERROR] [MY-000000] [Server] Plugin auth_pam reported: 'Unable to obtain the passwd entry for the user 'ioc-user'.'\n","file":"/var/lib/mysql/mysqld-error.log"}

The cause of this error message is that the user running mysqld does not read access to /etc/shadow, as explained in MariaDB PAM docs. This is reproducible using the MySQL tests on 880d0f7. UPDATE: this is confirmed not to fix the issue.

$ docker compse logs -f percona
pam-oauth2-percona  | [2024-02-14 18:47:15.374][pam-oidc][0.1.5][INFO][4249257301]: Auth detected. Proceeding...
pam-oauth2-percona  | [2024-02-14 18:47:15.375][pam-oidc][0.1.5][INFO][4249257301]: Inputs read.
pam-oauth2-percona  | [2024-02-14 18:47:15.375][pam-oidc][0.1.5][INFO][4249257301]: Check as password.
pam-oauth2-percona  | [2024-02-14 18:47:15.631][pam-oidc][0.1.5][INFO][4249257301]: Verifying token.
pam-oauth2-percona  | [2024-02-14 18:47:15.841][pam-oidc][0.1.5][INFO][4249257301]: Auth success!
pam-oauth2-percona  | 2024-02-14T18:47:15.844550Z 11 [ERROR] [MY-000000] [Server] Plugin auth_pam reported: 'Unable to obtain the passwd entry for the user 'demouser'.'

Fix

The proposed fix is to grant +r /etc/shadow permissions to the user running mysqld in the production DB. The MariaDB PAM docs explain how to do this if this user is mysql. Did not fix, see below.

@ethho
Copy link
Contributor Author

ethho commented Feb 14, 2024

No changes requested. This PR is only for debugging.

@ethho ethho closed this Feb 14, 2024
@ethho
Copy link
Contributor Author

ethho commented Feb 23, 2024

Changes to /etc/shadow in Percona QA deployment did not resolve the error message appearing in logs. I tested again with docker compose and determined that this was not, in fact, the source of the error.

This error message appears to emit from PAM, after calling via the account interface:

pam-oauth2/config/service_example

Lines 1 to 2 in d2e9cc6

auth sufficient libpam_oidc.so /etc/datajoint/libpam_oidc.yaml
account optional libpam_oidc.so 

auth sufficient libpam_oidc.so /etc/datajoint/libpam_oidc.yaml
account optional libpam_oidc.so

All auth fails at the PAM level when the account optional line is removed. In theory, according to the PAM docs, no further interfaces should be called after an auth sufficient returns success, but this is not the behavior we observe in the docker compose stack or the QA deployment (account interface is called, and error message emitted, only when auth sufficient succeeds).

So the root cause of the error message is how account interface is implemented for our custom plugin:

pam-oauth2/pam-oidc/src/lib.rs

Lines 170 to 174 in d2e9cc6

fn acct_mgmt(_pamh: Pam, _flags: PamFlags, _args: Vec<String>) -> PamError {
info!("acct_mgmt called.");
PamError::SUCCESS
// PamError::USER_UNKNOWN
} 

    fn acct_mgmt(_pamh: Pam, _flags: PamFlags, _args: Vec<String>) -> PamError {
        info!("acct_mgmt called.");
        PamError::SUCCESS
        // PamError::USER_UNKNOWN
    }

We see that it always returns success when called with the account interface, which calls the acct_mgmt function here. We reproduce the error message on commit d2e9cc6, which suggests that acct_mgmt (or something that PAM does after receiving PamError::SUCCESS after acct_mgmt) is checking for user demouser in /etc/passwd and failing to find the user (even though our module returned success):

$ ./tests/test.sh '<demouser password>'
# ...
+---+
| 1 |
+---+
| 1 |
+---+
mysql: [Warning] Using a password on the command line interface can be insecure.
ERROR 1045 (28000): Access denied for user 'demouser'@'localhost' (using password: YES)
Failed to authenticate for bogus password
# ...
pam-oauth2-percona  | [2024-02-23 19:15:07.850][pam-oidc][0.1.5][INFO][3775418299]: Auth detected. Proceeding...
pam-oauth2-percona  | [2024-02-23 19:15:07.850][pam-oidc][0.1.5][INFO][3775418299]: Inputs read.
pam-oauth2-percona  | [2024-02-23 19:15:07.850][pam-oidc][0.1.5][INFO][3775418299]: Check as password.
pam-oauth2-percona  | [2024-02-23 19:15:08.242][pam-oidc][0.1.5][INFO][3775418299]: Verifying token.
pam-oauth2-percona  | [2024-02-23 19:15:08.383][pam-oidc][0.1.5][INFO][3775418299]: Auth success!
pam-oauth2-percona  | [2024-02-23 19:15:08.383][pam-oidc][0.1.5][INFO][3775418299]: acct_mgmt called.
pam-oauth2-percona  | 2024-02-23T19:15:08.384691Z 11 [ERROR] [MY-000000] [Server] Plugin auth_pam reported: 'Unable to obtain the passwd entry for the user 'demouser'.'
pam-oauth2-percona  | [2024-02-23 19:15:08.550][pam-oidc][0.1.5][INFO][3775418299]: Auth detected. Proceeding...
pam-oauth2-percona  | [2024-02-23 19:15:08.550][pam-oidc][0.1.5][INFO][3775418299]: Inputs read.
pam-oauth2-percona  | [2024-02-23 19:15:08.550][pam-oidc][0.1.5][INFO][3775418299]: Check as password.
pam-oauth2-percona  | [2024-02-23 19:15:08.764][pam-oidc][0.1.5][INFO][3775418299]: Wrong password provided.

@ethho ethho reopened this Feb 23, 2024
@ethho
Copy link
Contributor Author

ethho commented Feb 23, 2024 •
edited
Loading

See https://github.com/miquels/webnis/tree/master/webnis-pam and https://github.com/salesforce/pam_oidc for examples of PAM modules that uses pamsm

@ethho
Copy link
Contributor Author

ethho commented Feb 23, 2024

Also see the MySQL Enterprise docs: https://dev.mysql.com/doc/refman/8.0/en/pam-pluggable-authentication.html#pam-pluggable-authentication-usage

  • Possible that auth is failing in some of these cases because test client is not using clear text plugin

@ethho
Copy link
Contributor Author

ethho commented Feb 23, 2024

On e0150ad, we reproduce the error log message without the custom PAM plugin at all; we instead use the mysql-any-password module as the MySQL docs recommend for debugging:

$ ./tests/test.sh '<password>'
# ...
+---+
| 1 |
+---+
| 1 |
+---+
mysql: [Warning] Using a password on the command line interface can be insecure.
+---+
| 1 |
+---+
| 1 |
+---+
# ...
pam-oauth2-percona  | 2024-02-23T22:25:48.983815Z 10 [ERROR] [MY-000000] [Server] Plugin auth_pam reported: 'Unable to obtain the passwd entry for the user 'demouser'.'
pam-oauth2-percona  | 2024-02-23T22:25:49.190337Z 11 [ERROR] [MY-000000] [Server] Plugin auth_pam reported: 'Unable to obtain the passwd entry for the user 'demouser'.'

@ethho
Copy link
Contributor Author

ethho commented Feb 23, 2024

I'll next try creating users with a Group Mapping to see if we can resolve this by mapping users to a user group that exists as a Unix user.

@ethho
Copy link
Contributor Author

ethho commented Feb 23, 2024

We see that regardless of how the PAM config file like config/service_example is configured, the auth_pam plugin in Percona will always check the account interface:

https://github.com/percona/percona-server/blob/78a93d56546f82168d2a553a08f072676e236955/plugin/percona-pam-for-mysql/src/auth_pam_common.cc#L148C1-L149C1

@ethho
Copy link
Contributor Author

ethho commented Feb 23, 2024

Maybe try auth_pam_compat.so instead of auth_pam.so?

@ethho
Copy link
Contributor Author

ethho commented Feb 23, 2024

Error message is emitted from this line in the auth_pam plugin: https://github.com/percona/percona-server/blob/78a93d56546f82168d2a553a08f072676e236955/plugin/percona-pam-for-mysql/src/groups.cc#L99

@ethho
Copy link
Contributor Author

ethho commented Feb 23, 2024

Search on the Percona issue board returns no results: https://perconadev.atlassian.net/jira/software/c/projects/PS/issues/?jql=project%20%3D%20%22PS%22%20AND%20text%20~%20%22passwd%20entry%22%20ORDER%20BY%20created%20DESC

@ethho
Copy link
Contributor Author

ethho commented Feb 23, 2024

Same issue observed with auth_pam_compat.so, which makes sense since both plugins use groups.cc which is emitting the error.

@ethho
Copy link
Contributor Author

ethho commented Feb 24, 2024

This SO post explains it perfectly: https://unix.stackexchange.com/a/698020

@ethho
Copy link
Contributor Author

ethho commented Feb 24, 2024

This is an error message that is specific to the Percona distribution of PAM authentication plugin:

❯ rg 'Unable to obtain'               
share/messages_to_error_log.txt
2475:  eng "Unable to obtain lock for dropping event %s from schema %s"
mysql-server on  trunk via △ v3.25.1 
❯ z percona      
percona-server on  8.0 via △ v3.25.1 
❯ rg 'Unable to obtain'
share/messages_to_error_log.txt
2475:  eng "Unable to obtain lock for dropping event %s from schema %s"

plugin/percona-pam-for-mysql/src/groups.cc
77:                          "Unable to obtain the passwd entry for the user "
99:                            "Unable to obtain the group access list for "
128:                          "Unable to obtain the group record for the group "

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
1 participant
@ethho