Hi,
As in the title a very odd behaviour if I keep opening new ssh sessions using same IPA user after few successful ones I have ssh authentication failed error and in krb5 logs on freeipa server, I can see the following errors: Nov 19 07:21:39 lab-ipa.stuxnet.lab krb5kdc[4894](info): AS_REQ (8 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), UNSUPPORTED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 192.168.10.64: NEEDED_PREAUTH: c000000@STUXNET.LAB for krbtgt/STUXNET.LAB@STUXNET.LAB, Additional pre-authentication required Nov 19 07:21:39 lab-ipa.stuxnet.lab krb5kdc[4894](info): closing down fd 11
At the same time, I can use the same user and connect to other hosts or use kinit or freeipa web portal. It looks like after N successful attempts I'm hitting some kind of time or max concurrent connections limit, but I can't find any related settings. It's standard Fedora-based freeipa 4.8.10 and hosts to connect are ubuntu. If I wait a few minutes I'm allowed to open another connection but then again if I try to open few I hit the error. I've been checking KRB_TRACE for kinit and sshd DEBUG3 level logs but I can't find why would it happen the only error is the one above with pre-auth.
Thanks
mir mal via FreeIPA-users wrote:
Hi,
As in the title a very odd behaviour if I keep opening new ssh sessions using same IPA user after few successful ones I have ssh authentication failed error and in krb5 logs on freeipa server, I can see the following errors: Nov 19 07:21:39 lab-ipa.stuxnet.lab krb5kdc[4894](info): AS_REQ (8 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), UNSUPPORTED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 192.168.10.64: NEEDED_PREAUTH: c000000@STUXNET.LAB for krbtgt/STUXNET.LAB@STUXNET.LAB, Additional pre-authentication required Nov 19 07:21:39 lab-ipa.stuxnet.lab krb5kdc[4894](info): closing down fd 11
At the same time, I can use the same user and connect to other hosts or use kinit or freeipa web portal. It looks like after N successful attempts I'm hitting some kind of time or max concurrent connections limit, but I can't find any related settings. It's standard Fedora-based freeipa 4.8.10 and hosts to connect are ubuntu. If I wait a few minutes I'm allowed to open another connection but then again if I try to open few I hit the error. I've been checking KRB_TRACE for kinit and sshd DEBUG3 level logs but I can't find why would it happen the only error is the one above with pre-auth.
I think you'll need to provide more details on your environment. What auth mechanism you're using for ssh, for example.
How certain are you that the pre-auth failure is related to the ssh failure? Are you thinking that on the remote side a kinit is happening upon login?
How is the connection failing on the remote side? sssd logging would be useful to see.
rob
Hi,
Sorry, maybe I wasn't detailed enough. The environments are client Ubuntu 20.04, FreeIPA Fedora 32 - freeipa-server-4.8.9-2.fc32.x86_64 It's an odd behaviour which should really not happen in a live environment we've discovered it during testing and therefore started opening multiple ssh connections to the host. In our example, in real life, you wouldn't try to open 5 concurrent SSH connection to the same host in a minute, but nevertheless, the behaviour is as follow: Start connecting SSH to Ubuntu client after a few successful connections I start receiving preauth failures. On client in auth.log you can't see anything other than standard failed to auth even on Debug3 level I couldn't find anything that would indicate client setup issue, it looks the same as wrong password error. As I mentioned exactly the same password base method worked ok a few seconds ago and if I wait for a few minutes it does work fine again. The sssd log is empty and auth.log and krb5kdc.log are not showing anything other then a standard generic error, it looks like there is some delay or max connection limit somewhere on Kerberos side but I couldn't find anything in the documentation. I've checked our SSH and there are no limits there, in fact, I can use public key auth for the same user on the same host no problem it's just FreeIPA authentication that is affected. I can create tickets with kinit using the same user as well. Happy to provide more details, just don't know what details at the moment.
auth.log snippet Nov 27 05:54:32 csc-64 sshd[513083]: debug3: send packet: type 53 [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug1: userauth_send_banner: sent [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug2: input_userauth_request: try method none [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: user_specific_delay: user specific delay 0.000ms [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: ensure_minimum_time_since: elapsed 4.484ms, delaying 0.949ms (requested 5.433ms) [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: userauth_finish: failure partial=0 next methods="publickey,gssapi-keyex,gssapi-with-mic,password,keyboard-interactive" [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: send packet: type 51 [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: receive packet: type 50 [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug1: userauth-request for user c111111 service ssh-connection method publickey [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug1: attempt 1 failures 0 [preauth]
On FreeIPA server krb5kdc.log snippet Nov 27 05:55:39 lab-ipa.stuxnet.lab krb5kdc[4894](info): AS_REQ (8 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), UNSUPPORTED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 192.168.10.64: NEEDED_PREAUTH: host/csc-64.stuxnet.lab@STUXNET.LAB for krbtgt/STUXNET.LAB@STUXNET.LAB, Additional pre-authentication required Nov 27 05:55:39 lab-ipa.stuxnet.lab krb5kdc[4894](info): closing down fd 11
klist output from an existing ssh connection on the same host, create just a few seconds before. c111111@csc-64:~$ klist Ticket cache: KEYRING:persistent:1938600006:krb_ccache_5K4WZSD Default principal: c111111@STUXNET.LAB
Valid starting Expires Service principal 27/11/20 06:09:22 28/11/20 06:09:22 krbtgt/STUXNET.LAB@STUXNET.LAB
On Fri, Nov 27, 2020 at 06:17:40AM -0000, mir mal via FreeIPA-users wrote:
Hi,
Sorry, maybe I wasn't detailed enough. The environments are client Ubuntu 20.04, FreeIPA Fedora 32 - freeipa-server-4.8.9-2.fc32.x86_64 It's an odd behaviour which should really not happen in a live environment we've discovered it during testing and therefore started opening multiple ssh connections to the host. In our example, in real life, you wouldn't try to open 5 concurrent SSH connection to the same host in a minute, but nevertheless, the behaviour is as follow: Start connecting SSH to Ubuntu client after a few successful connections I start receiving preauth failures. On client in auth.log you can't see anything other than standard failed to auth even on Debug3 level I couldn't find anything that would indicate client setup issue, it looks the same as wrong password error. As I mentioned exactly the same password base method worked ok a few seconds ago and if I wait for a few minutes it does work fine again. The sssd log is empty and auth.log and krb5kdc.log are not showing anything other then a standard generic error, it looks like there is some delay or max connection limit somewhere on Kerberos side but I couldn't find anything in the documentation. I've checked our SSH and there are no limits there, in fact, I can use public key auth for the same user on the same host no problem it's just FreeIPA authentication that is affected. I can create tickets with kinit using the same user as well. Happy to provide more details, just don't know what details at the moment.
auth.log snippet Nov 27 05:54:32 csc-64 sshd[513083]: debug3: send packet: type 53 [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug1: userauth_send_banner: sent [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug2: input_userauth_request: try method none [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: user_specific_delay: user specific delay 0.000ms [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: ensure_minimum_time_since: elapsed 4.484ms, delaying 0.949ms (requested 5.433ms) [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: userauth_finish: failure partial=0 next methods="publickey,gssapi-keyex,gssapi-with-mic,password,keyboard-interactive" [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: send packet: type 51 [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: receive packet: type 50 [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug1: userauth-request for user c111111 service ssh-connection method publickey [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug1: attempt 1 failures 0 [preauth]
On FreeIPA server krb5kdc.log snippet Nov 27 05:55:39 lab-ipa.stuxnet.lab krb5kdc[4894](info): AS_REQ (8 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), UNSUPPORTED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 192.168.10.64: NEEDED_PREAUTH: host/csc-64.stuxnet.lab@STUXNET.LAB for krbtgt/STUXNET.LAB@STUXNET.LAB, Additional pre-authentication required Nov 27 05:55:39 lab-ipa.stuxnet.lab krb5kdc[4894](info): closing down fd 11
Hi,
the 'NEEDED_PREAUTH' messages in krb5kdc.log are expected and do not indicate an error. The '[preauth]' messages in the sshd debug output indicate some specific internal sshd steps and are not related to the Kerberos message.
For further investigations I would suggest to add 'debug_level = 9' to the [pam] and [domain/...] sections in sssd.conf, restart SSSD, rerun the test until it fails and send the SSSD logs together with the full sshd logs. With this it should be possible to identify if the issue is caused by SSSD or Kerberos or if it is related to sssd.
bye, Sumit
klist output from an existing ssh connection on the same host, create just a few seconds before. c111111@csc-64:~$ klist Ticket cache: KEYRING:persistent:1938600006:krb_ccache_5K4WZSD Default principal: c111111@STUXNET.LAB
Valid starting Expires Service principal 27/11/20 06:09:22 28/11/20 06:09:22 krbtgt/STUXNET.LAB@STUXNET.LAB _______________________________________________ FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org 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/freeipa-users@lists.fedorahoste...
Hi,
I've enabled lvl 9 debug, I've started from 6 to see if there is anything obvious, but I can't see anything. It looks like on lvl 6 the difference between successful and not successful login is that the not successful one is not even triggering SSS_PAM_ACCT_MGMT command. What's interesting is that if I destroy c111111 user ticket from the machine and try login again, it will fail but my current login user can see that the krb ticket has been created. On lvl 9 I can see communication with IPA server is successful as well as it's querying all user info. I've disabled krb5_store_password_if_offline and cleared sssd cache on the host but still the same thing. The symptoms are almost like krb won't check the password and just return OK to ssh.
c111111@csc-64:/home/ubuntu$ klist -l Principal name Cache name -------------- ---------- c111111@STUXNET.LAB KEYRING:persistent:1938600006:krb_ccache_VaG0P4I
When failing the following is not process at all, it just return OK (Mon Nov 30 07:05:50 2020) [sssd[be[stuxnet.lab]]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.pamHandler: Success (Mon Nov 30 07:05:50 2020) [sssd[be[stuxnet.lab]]] [child_sig_handler] (0x0100): child [602785] finished successfully.
when successful the lvl 6 log continue with: (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [dp_pam_handler_send] (0x0100): Got request with the following data (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): command: SSS_PAM_ACCT_MGMT (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): domain: stuxnet.lab (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): user: c111111@stuxnet.lab (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): service: sshd (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): tty: ssh (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): ruser: (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): rhost: 10.0.0.6 (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): authtok type: 0 (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): newauthtok type: 0 (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): priv: 1 (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): cli_pid: 602527 (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): logon name: not set (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): flags: 0 (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [dp_attach_req] (0x0400): DP Request [PAM Account #7]: New request. Flags [0000]. (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [sdap_access_send] (0x0400): Performing access check for user [c111111@stuxnet.lab] (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [sdap_account_expired_rhds] (0x0400): Performing RHDS
On ma, 30 marras 2020, mir mal via FreeIPA-users wrote:
Hi,
I've enabled lvl 9 debug, I've started from 6 to see if there is anything obvious, but I can't see anything. It looks like on lvl 6 the difference between successful and not successful login is that the not successful one is not even triggering SSS_PAM_ACCT_MGMT command. What's interesting is that if I destroy c111111 user ticket from the machine and try login again, it will fail but my current login user can see that the krb ticket has been created. On lvl 9 I can see communication with IPA server is successful as well as it's querying all user info. I've disabled krb5_store_password_if_offline and cleared sssd cache on the host but still the same thing. The symptoms are almost like krb won't check the password and just return OK to ssh.
WHat exact command do you use on the client side? How do you login to ssh server? With Kerberos ticket or with a password?
sshd performs own GSSAPI negotiation. In the case user logs with GSSAPI to sshd server, sshd server does authentication and then, if 'UsePAM yes', does ask PAM stack for an authorization and session.
In the case of using a password, sshd performs PAM stack authentication and then SSSD is involved, indeed, in acquiring a Kerberos ticket by reusing a password given by sshd to the PAM stack.
So you need to see in sshd logs (debug3 at least) what does it see/deal with.
c111111@csc-64:/home/ubuntu$ klist -l Principal name Cache name
c111111@STUXNET.LAB KEYRING:persistent:1938600006:krb_ccache_VaG0P4I
When failing the following is not process at all, it just return OK (Mon Nov 30 07:05:50 2020) [sssd[be[stuxnet.lab]]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.pamHandler: Success (Mon Nov 30 07:05:50 2020) [sssd[be[stuxnet.lab]]] [child_sig_handler] (0x0100): child [602785] finished successfully.
when successful the lvl 6 log continue with: (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [dp_pam_handler_send] (0x0100): Got request with the following data (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): command: SSS_PAM_ACCT_MGMT (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): domain: stuxnet.lab (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): user: c111111@stuxnet.lab (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): service: sshd (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): tty: ssh (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): ruser: (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): rhost: 10.0.0.6 (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): authtok type: 0 (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): newauthtok type: 0 (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): priv: 1 (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): cli_pid: 602527 (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): logon name: not set (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [pam_print_data] (0x0100): flags: 0 (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [dp_attach_req] (0x0400): DP Request [PAM Account #7]: New request. Flags [0000]. (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [sdap_access_send] (0x0400): Performing access check for user [c111111@stuxnet.lab] (Mon Nov 30 07:04:50 2020) [sssd[be[stuxnet.lab]]] [sdap_account_expired_rhds] (0x0400): Performing RHDS _______________________________________________ FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org 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/freeipa-users@lists.fedorahoste...
The ssh command is just ssh c111111@192.168.10.64, the c111111 is an IPA user, local users are working OK. The debug3 on sshd doesn't show anything, at least I can't spot anything. It's a standard IPA roll out and as you said sshd performs PAM and then SSSD is involved, with SSSD I can see new krb ticket being created on the host but ssh password login is denied. Happy to get all the logs just tell me what is needed as each of them is very verbose, I don't think copy/paste to the thread is sensible.
auth.log snippet Nov 27 05:54:32 csc-64 sshd[513083]: debug3: send packet: type 53 [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug1: userauth_send_banner: sent [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug2: input_userauth_request: try method none [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: user_specific_delay: user specific delay 0.000ms [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: ensure_minimum_time_since: elapsed 4.484ms, delaying 0.949ms (requested 5.433ms) [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: userauth_finish: failure partial=0 next methods="publickey,gssapi-keyex,gssapi-with-mic,password,keyboard-interactive" [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: send packet: type 51 [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug3: receive packet: type 50 [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug1: userauth-request for user c111111 service ssh-connection method publickey [preauth] Nov 27 05:54:32 csc-64 sshd[513083]: debug1: attempt 1 failures 0 [preauth]
I've created 6 files, for sssd_<domain>, sssd_pam and auth.log file for both a successful and failed login and pasted in pastebin. successful login https://pastebin.com/G75fv7tk - c111111_successful_login_sssd.log https://pastebin.com/dEqCzyPk - c111111_successful_login_auth.log https://pastebin.com/MrwKiwPe - c111111_successful_login_sssd_pam.log
failed login https://pastebin.com/WWaGFNBS - c111111_failed_login_sssd.log https://pastebin.com/tXejaUn7 - c111111_failed_login_auth.log https://pastebin.com/zHs1cZRj - c111111_failed_login_sssd_pam.log
On ma, 30 marras 2020, mir mal via FreeIPA-users wrote:
I've created 6 files, for sssd_<domain>, sssd_pam and auth.log file for both a successful and failed login and pasted in pastebin. successful login https://pastebin.com/G75fv7tk - c111111_successful_login_sssd.log https://pastebin.com/dEqCzyPk - c111111_successful_login_auth.log https://pastebin.com/MrwKiwPe - c111111_successful_login_sssd_pam.log
failed login https://pastebin.com/WWaGFNBS - c111111_failed_login_sssd.log https://pastebin.com/tXejaUn7 - c111111_failed_login_auth.log https://pastebin.com/zHs1cZRj - c111111_failed_login_sssd_pam.log
sshd log in the 'failed' case covers earlier time period than SSSD log. Please try to co-relate timespan in all logs.
On Mon, Nov 30, 2020 at 10:44:30AM -0000, mir mal via FreeIPA-users wrote:
I've created 6 files, for sssd_<domain>, sssd_pam and auth.log file for both a successful and failed login and pasted in pastebin. successful login https://pastebin.com/G75fv7tk - c111111_successful_login_sssd.log https://pastebin.com/dEqCzyPk - c111111_successful_login_auth.log https://pastebin.com/MrwKiwPe - c111111_successful_login_sssd_pam.log
failed login https://pastebin.com/WWaGFNBS - c111111_failed_login_sssd.log https://pastebin.com/tXejaUn7 - c111111_failed_login_auth.log https://pastebin.com/zHs1cZRj - c111111_failed_login_sssd_pam.log
Hi,
for the failed case sshd logs stop at 'Nov 30 10:15:31' while SSSD logs start at 'Mon Nov 30 10:15:46 2020'. Can you try to get logs with overlappign timestamps?
bye, Sumit
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org 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/freeipa-users@lists.fedorahoste...
Sorry, my bad, please see updated:
https://pastebin.com/0rMkNEWx - c111111_failed_login_auth.log
I'm still struggling to find a clue why it's happening, any help much appriciated.
mir mal via FreeIPA-users wrote:
I'm still struggling to find a clue why it's happening, any help much appriciated.
This stands out:
Nov 30 10:15:46 csc-64 sshd[608090]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.0.0.6 user=c111111 Nov 30 10:15:46 csc-64 sshd[608090]: pam_sss(sshd:auth): authentication success; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.0.0.6 user=c111111 Nov 30 10:15:46 csc-64 sshd[608090]: pam_tally2(sshd:auth): user c111111 (1938600006) tally 52, deny 9
An auth failure immediately followed by an auth success.
But importantly you have pam_tally2 enabled so this failure is incremented and eventually the user is locked out for a time. So it is pam_tally2 that is locking you out.
How/why a failure/success happens like this I don't know.
rob
Hello, Rob Crittenden via FreeIPA-users freeipa-users@lists.fedorahosted.org writes:
mir mal via FreeIPA-users wrote:
I'm still struggling to find a clue why it's happening, any help much appriciated.
This stands out:
Nov 30 10:15:46 csc-64 sshd[608090]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.0.0.6 user=c111111 Nov 30 10:15:46 csc-64 sshd[608090]: pam_sss(sshd:auth): authentication success; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.0.0.6 user=c111111 Nov 30 10:15:46 csc-64 sshd[608090]: pam_tally2(sshd:auth): user c111111 (1938600006) tally 52, deny 9
An auth failure immediately followed by an auth success.
And: failure with pam_unix (local user?) and success with pam_sss. On most Systems we have something like that in /etc/pam.d/password-auth or common-auth:
auth [default=1 ignore=ignore success=ok] pam_usertype.so isregular auth [default=1 ignore=ignore success=ok] pam_localuser.so auth sufficient pam_unix.so nullok try_first_pass auth [default=1 ignore=ignore success=ok] pam_usertype.so isregular auth sufficient pam_sss.so forward_pass auth required pam_deny.so
so, call pam_unix only for local users, not IPA users. Something like that?
Jochen
I know it's been a while but it took me a bit of testing and initially I thought I did a good job but I just found out I had a small flaw in the logic. You were right it's pam module issue not IPA or SSH. What happened is when deploying our harden Ubuntu images we are appending pam_tally2 line to block a user after 9 unsuccessful attempts. So two thing happen, our harden image was lacking account required pam_tally2 so after successful login, the tally is reset and the appended lines from IPA deployment didn't take into consideration there is a counter so it's been basically going line by line in required and therefore counting each failure twice that's why not after 9 but often after 4,5 attempts user got locked out and you couldn't see it with kinit as it's not pam enabled binary. Learning pam syntax and all different modules took me some time but finally, I've settled with the following configuration in common-auth module. Basically, I've used success=5 to do GO TO syntax and you can read it if NOT localuser then do pam_sss and all the other stuff and make sure you do pam_deny if you provided the wrong password to pam_sss module, otherwise the sufficient syntax in pam_tall2 is not enough to break execution. Otherwise, jump next 5 lines and do the same but for pam_unix module.
auth [success=5 default=ignore] pam_localuser.so auth required pam_sss.so forward_pass ignore_unknown_user ignore_authinfo_unavail auth optional pam_faildelay.so delay=2000000 auth optional pam_cap.so auth sufficient pam_tally2.so onerr=fail audit silent deny=9 unlock_time=300 auth requisite pam_deny.so auth required pam_unix.so nullok auth optional pam_faildelay.so delay=2000000 auth optional pam_cap.so auth sufficient pam_tally2.so onerr=fail audit silent deny=9 unlock_time=300 auth requisite pam_deny.so
Thanks everyone in pointing me in the right direction.
freeipa-users@lists.fedorahosted.org