[Freeipa-users] 'Preauthentication failed' with SSSD in ipa_server_mode

[Bobby Prins]

>----- Oorspronkelijk bericht -----
>Van: "Alexander Bokovoy" <abokovoy at redhat.com>
>Aan: "Bobby Prins" <bobby.prins at proxy.nl>
>Cc: dpal at redhat.com, freeipa-users at redhat.com
>Verzonden: Dinsdag 24 maart 2015 15:13:38
>Onderwerp: Re: [Freeipa-users] 'Preauthentication failed' with SSSD in ipa_server_mode
>
>On Tue, 24 Mar 2015, Bobby Prins wrote:
>>>----- Oorspronkelijk bericht -----
>>>Van: "Alexander Bokovoy" <abokovoy at redhat.com>
>>>Aan: "Bobby Prins" <bobby.prins at proxy.nl>
>>>Cc: dpal at redhat.com, freeipa-users at redhat.com
>>>Verzonden: Maandag 23 maart 2015 16:44:47
>>>Onderwerp: Re: [Freeipa-users] 'Preauthentication failed' with SSSD in ipa_server_mode
>>>
>>>...
>>>
>>>Can you show relevant parts of /var/log/dirsrv/slapd-EXAMPLE-CORP/access
>>>and sssd logs from IPA master (with debug_level = 10) at least in
>>>[domain], [nss], and [pam] sections.
>>>
>>>You need to filter dirsrv logs by connection coming from AIX IP address
>>>and then by conn=<number> where number is the same number as the one
>>>with IP address line.
>>>
>>>When authenticating, AIX would talk to IPA LDAP server to compat tree
>>>and slapi-nis plugin which serves compat tree would do PAM
>>>authentication as service system-auth where SSSD on IPA master will do
>>>the actual authentication work.
>>>
>>>--
>>>/ Alexander Bokovoy
>>
>>Here you can see the DS connection from AIX:
>>[24/Mar/2015:12:53:19 +0100] conn=96 fd=110 slot=110 connection from 192.168.140.107 to 192.168.140.133
>>[24/Mar/2015:12:53:20 +0100] conn=96 op=0 BIND dn="uid=bprins at example.corp,cn=users,cn=compat,dc=unix,dc=example,dc=corp" method=128 version=3
>>[24/Mar/2015:12:53:43 +0100] conn=96 op=0 RESULT err=0 tag=97 nentries=0 etime=24 dn="uid=bprins at example.corp,cn=users,cn=compat,dc=unix,dc=example,dc=corp"
>>[24/Mar/2015:12:53:43 +0100] conn=96 op=-1 fd=110 closed - B1
>>
>>As you can see it also takes quite some time to process the login.
>>Could that be a problem?
>24 seconds sounds like bprins2example.com is a member of few groups with
>big amount of members. On the other hand, BIND operation result is 0
>(success) and it doesn't look like AIX dropped the connection, at least
>there is no ABANDON within the context of this connection so AIX did not
>cancel the request by itself.
>
>How long does it take on AIX side to report the inability to login? Is
>this time longer or shorter the one reported in etime= value on RESULT
>line above?
>
>>The SSSD log files are a bit large with debug_level set to 10 and it
>>will take me some time to strip all customer data from it. Any log
>>events in particular you would like to see?
>https://fedorahosted.org/sssd/wiki/Troubleshooting has explanation for
>some times of issues you might find in the SSSD logs. I'd be interested
>in "Common AD provider issues", "Troubleshooting authentication,
>password change and access control".
>
>-- 
>/ Alexander Bokovoy

The inability to login is reported in about the same time as the number of seconds you would find in the etime= field of the RESULT line.

I checked the "Common AD provider issues" and "Troubleshooting authentication, password change and access control" sections on the SSSD Troubleshooting page. None of the issues reported there seem to be applicable in my situation.

PAM logging on AIX:
Mar 24 16:23:10 tst01 auth|security:debug /usr/sbin/getty PAM: pam_start(login bprins at example.corp)
Mar 24 16:23:10 tst01 auth|security:debug /usr/sbin/getty PAM: pam_set_item(1)
Mar 24 16:23:10 tst01 auth|security:debug /usr/sbin/getty PAM: pam_set_item(2)
Mar 24 16:23:10 tst01 auth|security:debug /usr/sbin/getty PAM: pam_set_item(5)
Mar 24 16:23:10 tst01 auth|security:debug /usr/sbin/getty PAM: pam_set_item(3)
Mar 24 16:23:10 tst01 auth|security:debug /usr/sbin/getty PAM: pam_set_item(4)
Mar 24 16:23:10 tst01 auth|security:debug /usr/sbin/getty PAM: pam_set_item(8)
Mar 24 16:23:10 tst01 auth|security:debug /usr/sbin/getty PAM: pam_authenticate()
Mar 24 16:23:10 tst01 auth|security:debug /usr/sbin/getty PAM: load_modules: /usr/lib/security/pam_aix
Mar 24 16:23:10 tst01 auth|security:debug /usr/sbin/getty PAM: load_function: successful load of pam_sm_authenticate
Mar 24 16:23:22 tst01 auth|security:debug /usr/sbin/getty PAM: pam_set_item(6)
Mar 24 16:23:37 tst01 auth|security:debug /usr/sbin/getty PAM: pam_authenticate: error Authentication failed
Mar 24 16:23:37 tst01 auth|security:debug /usr/sbin/getty PAM: pam_set_item(6)
Mar 24 16:23:37 tst01 auth|security:debug /usr/sbin/getty PAM: pam_acct_mgmt()
Mar 24 16:23:37 tst01 auth|security:debug /usr/sbin/getty PAM: load_modules: /usr/lib/security/pam_aix
Mar 24 16:23:37 tst01 auth|security:debug /usr/sbin/getty PAM: load_function: successful load of pam_sm_acct_mgmt
Mar 24 16:23:37 tst01 auth|security:debug /usr/sbin/getty PAM: pam_acct_mgmt: error No account present for user
Mar 24 16:23:37 tst01 auth|security:debug /usr/sbin/getty PAM: pam_end(): status = Authentication failed
Mar 24 16:23:37 tst01 auth|security:info syslog: vty0: failed login attempt for UNKNOWN_USER

Doing a ldapsearch with bprins at example.corp as bind user works without any problems.