Am Mon, Jan 24, 2022 at 01:36:28PM -0500 schrieb Rob Crittenden: > I'm trying to get a multi-threaded PAM app working to log in users using > the 'login' service to generate client load: > > https://github.com/freeipa/freeipa-perftest/blob/master/src/pamtest.c > > The load is generated by running multiple client VMs and on each client > running the pam tester with multiple threads. > > It works about 99% of the time and I'm struggling to find out why it > occasionally fails with: Authentication failure (7) > > The environment is IPA with pre-created users all set with the same > known LDAP and Kerberos password. The password is not marked as expired. > > The journal is reporting a different PAM error: > > Jan 24 16:11:57 client003.ipa.test pamtest[4285]: pam_sss(login:auth): > authentication failure; logname= uid=0 euid=0 tty= ruser= rhost= > user=user19client003.ipa.test > Jan 24 16:11:57 client003.ipa.test pamtest[4285]: pam_sss(login:auth): > received for user user19client003.ipa.test: 6 (Permission denied) > Jan 24 16:11:59 client003.ipa.test pamtest[4285]: > pam_unix(login:session): session opened for user > user19client003.ipa.test(uid=1751200171) by (uid=0) > Jan 24 16:14:01 client003.ipa.test pamtest[4285]: > pam_unix(login:session): session closed for user user19client003.ipa.test > > The sssd pam log reports: > > * (2022-01-24 16:11:50): [pam] [pam_cmd_authenticate] (0x0100): > entering pam_cmd_authenticate > * (2022-01-24 16:11:50): [pam] [sss_domain_get_state] (0x1000): > Domain ipa.test is Active > [ short snip of parse_name ] > * (2022-01-24 16:11:50): [pam] [pd_set_primary_name] (0x0400): > User's primary name is [email protected] > * (2022-01-24 16:11:50): [pam] [pam_initgr_check_timeout] (0x2000): > User [user19client003.ipa.test] found in PAM cache. > * (2022-01-24 16:11:50): [pam] [pam_dp_send_req] (0x0100): Sending > request [CID #2] with the following data: > * (2022-01-24 16:11:50): [pam] [pam_print_data] (0x0100): [CID #2] > command: SSS_PAM_AUTHENTICATE > * (2022-01-24 16:11:50): [pam] [pam_print_data] (0x0100): [CID #2] > domain: ipa.test > * (2022-01-24 16:11:50): [pam] [pam_print_data] (0x0100): [CID #2] > user: [email protected] > * (2022-01-24 16:11:50): [pam] [pam_print_data] (0x0100): [CID #2] > service: login > * (2022-01-24 16:11:50): [pam] [pam_print_data] (0x0100): [CID #2] > tty: not set > * (2022-01-24 16:11:50): [pam] [pam_print_data] (0x0100): [CID #2] > ruser: not set > * (2022-01-24 16:11:50): [pam] [pam_print_data] (0x0100): [CID #2] > rhost: not set > * (2022-01-24 16:11:50): [pam] [pam_print_data] (0x0100): [CID #2] > authtok type: 1 (Password) > * (2022-01-24 16:11:50): [pam] [pam_print_data] (0x0100): [CID #2] > newauthtok type: 0 (No authentication token available) > * (2022-01-24 16:11:50): [pam] [pam_print_data] (0x0100): [CID #2] > priv: 1 > * (2022-01-24 16:11:50): [pam] [pam_print_data] (0x0100): [CID #2] > cli_pid: 4285 > * (2022-01-24 16:11:50): [pam] [pam_print_data] (0x0100): [CID #2] > logon name: user19client003.ipa.test > * (2022-01-24 16:11:50): [pam] [pam_print_data] (0x0100): [CID #2] > flags: 2 > * (2022-01-24 16:11:50): [pam] [pam_dom_forwarder] (0x0100): > pam_dp_send_req returned 0 > * (2022-01-24 16:11:53): [pam] [pam_initgr_cache_remove] (0x2000): > [user20client003.ipa.test] removed from PAM initgroup cache > * (2022-01-24 16:11:55): [pam] [pam_initgr_cache_remove] (0x2000): > [user19client003.ipa.test] removed from PAM initgroup cache > * (2022-01-24 16:11:57): [pam] [sbus_dispatch] (0x4000): Dispatching. > * (2022-01-24 16:11:57): [pam] [pam_dp_send_req_done] (0x0200): > received: [6 (Permission denied)][ipa.test][CID #2]
Hi, the PAM_PERM_DENIED error is returned from the backend. Please check the backend log and krb5_child.log. I agree that it looks a bit like a timeout issue since the default krb5_auth_timeout is 6s but I would expect a different return code in this case. It looks like currently PAM_PERM_DENIED is returned during authentication only if the KDC returns KRB5KDC_ERR_CLIENT_REVOKED, i.e. the account is locked or similar. bye, Sumit > * (2022-01-24 16:11:57): [pam] [pam_reply] (0x4000): pam_reply > initially called with result [6]: Permission denied. this result might > be changed during processing > > I just can't tell what the permission denied means. Permission to do > what? I can provide fuller logs if needed. > > I suspect it may be a timeout as there is a several second delay in some > of the processing. > > There is nothing wrong with this particular user. I can manually re-run > the tool and it will pass 100% but the server is under significantly > less stress. > > Hoping for suggestions on where to start looking. > > thanks > > rob > _______________________________________________ > sssd-users mailing list -- [email protected] > To unsubscribe send an email to [email protected] > Fedora Code of Conduct: > https://docs.fedoraproject.org/en-US/project/code-of-conduct/ > List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines > List Archives: > https://lists.fedorahosted.org/archives/list/[email protected] > Do not reply to spam on the list, report it: > https://pagure.io/fedora-infrastructure _______________________________________________ sssd-users mailing list -- [email protected] To unsubscribe send an email to [email protected] Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/[email protected] Do not reply to spam on the list, report it: https://pagure.io/fedora-infrastructure
