12:36 p.m.
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 user19client003.ipa.test(a)ipa.test
* (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: user19client003.ipa.test(a)ipa.test
* (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]
* (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