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

Mon Mar 23 15:44:47 UTC 2015

On Mon, 23 Mar 2015, Bobby Prins wrote:
>>On 03/20/2015 08:05 AM, Alexander Bokovoy wrote:
>>> On Fri, 20 Mar 2015, Bobby Prins wrote:
>>>>> On Fri, 20 Mar 2015, Sumit Bose wrote:
>>>>>> On Fri, Mar 20, 2015 at 11:44:43AM +0100, Bobby Prins wrote:
>>>>>>> On Thu, Mar 19, 2015 at 04:46:44PM +0100, Bobby Prins wrote:
>>>>>>> >> Hi there,
>>>>>>> >>
>>>>>>> >> I'm currently trying to use the 'AD Trust for Legacy Clients'
>>>>>>> >> freeIPA setup (described here:
>>>>>>> >> http://www.freeipa.org/images/0/0d/FreeIPA33-legacy-clients.pdf)
>>>>>>> >> to be able to autenticate AIX 7.1 clients against an AD domain
>>>>>>> >> using LDAP. After the trust was created all seems to work well
>>>>>>> >> on the freeIPA server. I can also do a lookup of AD users and
>>>>>>> >> groups on an AIX test server.
>>>>>>> >>
>>>>>>> >> But as soon as I want to log in on the AIX system I get an SSSD
>>>>>>> error on the freeIPA server in krb5_child.log (debug_level = 10):
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [sss_child_krb5_trace_cb] (0x4000): [12775] 1426778442.590260: AS
>>>>>>> key obtained for encrypted timestamp: aes256-cts/2F5D
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [sss_child_krb5_trace_cb] (0x4000): [12775] 1426778442.590326:
>>>>>>> Encrypted timestamp (for 1426778442.525165): plain
>>>>>>> 301AA011180F32303135303331393135323034325AA105020308036D,
>>>>>>> encrypted
>>>>>>> 9B3299264F09E50D63D84B385A09A4C64D44116A02B58FFF12830B39F88722CD9B792F5ABA0653578DE9138B91D29C17C197453D8B8A5E7A
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [sss_child_krb5_trace_cb] (0x4000): [12775] 1426778442.590349:
>>>>>>> Preauth module encrypted_timestamp (2) (flags=1) returned: 0/Success
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [sss_child_krb5_trace_cb] (0x4000): [12775] 1426778442.590360:
>>>>>>> Produced preauth for next request: 2
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [sss_child_krb5_trace_cb] (0x4000): [12775] 1426778442.590384:
>>>>>>> Sending request (238 bytes) to EXAMPLE.CORP
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [sss_child_krb5_trace_cb] (0x4000): [12775] 1426778442.591325:
>>>>>>> Resolving hostname dct020.example.corp.
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [sss_child_krb5_trace_cb] (0x4000): [12775] 1426778442.591889:
>>>>>>> Sending initial UDP request to dgram 192.168.143.1:88
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [sss_child_krb5_trace_cb] (0x4000): [12775] 1426778442.636127:
>>>>>>> Received answer from dgram 192.168.143.1:88
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [sss_child_krb5_trace_cb] (0x4000): [12775] 1426778442.636626:
>>>>>>> Response was not from master KDC
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [sss_child_krb5_trace_cb] (0x4000): [12775] 1426778442.636667:
>>>>>>> Received error from KDC: -1765328360/Preauthentication failed
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [sss_child_krb5_trace_cb] (0x4000): [12775] 1426778442.636698:
>>>>>>> Preauth tryagain input types: 16, 14, 19, 2
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [sss_child_krb5_trace_cb] (0x4000): [12775] 1426778442.636728:
>>>>>>> Retrying AS request with master KDC
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [sss_child_krb5_trace_cb] (0x4000): [12775] 1426778442.636741:
>>>>>>> Getting initial credentials for BPrins at EXAMPLE.CORP
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [sss_child_krb5_trace_cb] (0x4000): [12775] 1426778442.636787:
>>>>>>> Sending request (160 bytes) to EXAMPLE.CORP (master)
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [get_and_save_tgt] (0x0020): 979: [-1765328360][Preauthentication
>>>>>>> failed]
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [map_krb5_error] (0x0020): 1040: [-1765328360][Preauthentication
>>>>>>> failed]
>>>>>>> >> (Thu Mar 19 16:20:42 2015) [[sssd[krb5_child[12775]]]]
>>>>>>> [k5c_send_data] (0x0200): Received error code 1432158214
>>>>>>> >>
>>>>>>> >> If I do the same with 'KRB5_TRACE=/dev/stderr kinit
>>>>>>> BPrins at EXAMPLE.CORP':
>>>>>>> >> [12299] 1426773524.361785: AS key obtained for encrypted
>>>>>>> timestamp: aes256-cts/B997
>>>>>>> >> [12299] 1426773524.361850: Encrypted timestamp (for
>>>>>>> 1426773524.277583): plain
>>>>>>> 301AA011180F32303135303331393133353834345AA1050203043C4F,
>>>>>>> encrypted
>>>>>>> ED9CF995617740C4B14DB9CC84187E3505B664FE5C0AD16D19477E912F5400FB2C4665A090E3A37CD749535B3C80595809E14D15CB3527C0
>>>>>>> >> [12299] 1426773524.361876: Preauth module encrypted_timestamp
>>>>>>> (2) (flags=1) returned: 0/Success
>>>>>>> >> [12299] 1426773524.361880: Produced preauth for next request: 2
>>>>>>> >> [12299] 1426773524.361901: Sending request (238 bytes) to
>>>>>>> EXAMPLE.CORP
>>>>>>> >> [12299] 1426773524.363002: Resolving hostname dct020.EXAMPLE.corp.
>>>>>>> >> [12299] 1426773524.363841: Sending initial UDP request to dgram
>>>>>>> 192.168.141.1:88
>>>>>>> >> [12299] 1426773524.368089: Received answer from dgram
>>>>>>> 192.168.141.1:88
>>>>>>> >> [12299] 1426773524.368482: Response was not from master KDC
>>>>>>> >> [12299] 1426773524.368500: Received error from KDC:
>>>>>>> -1765328332/Response too big for UDP, retry with TCP
>>>>>>> >> [12299] 1426773524.368506: Request or response is too big for
>>>>>>> UDP; retrying with TCP
>>>>>>> >> [12299] 1426773524.368511: Sending request (238 bytes) to
>>>>>>> EXAMPLE.CORP (tcp only)
>>>>>>> >> [12299] 1426773524.368953: Resolving hostname dct030.EXAMPLE.corp.
>>>>>>> >> [12299] 1426773524.370056: Initiating TCP connection to stream
>>>>>>> 192.168.143.5:88
>>>>>>> >> [12299] 1426773524.375140: Sending TCP request to stream
>>>>>>> 192.168.143.5:88
>>>>>>> >> [12299] 1426773524.383801: Received answer from stream
>>>>>>> 192.168.143.5:88
>>>>>>> >> [12299] 1426773524.384237: Response was not from master KDC
>>>>>>> >> [12299] 1426773524.384263: Processing preauth types: 19
>>>>>>> >> [12299] 1426773524.384271: Selected etype info: etype
>>>>>>> aes256-cts, salt "EXAMPLE.CORPBPrins", params ""
>>>>>>> >> [12299] 1426773524.384275: Produced preauth for next request:
>>>>>>> (empty)
>>>>>>> >> [12299] 1426773524.384282: AS key determined by preauth:
>>>>>>> aes256-cts/B997
>>>>>>> >> [12299] 1426773524.384329: Decrypted AS reply; session key is:
>>>>>>> rc4-hmac/39AB
>>>>>>> >> [12299] 1426773524.384333: FAST negotiation: unavailable
>>>>>>> >> [12299] 1426773524.384357: Initializing
>>>>>>> KEYRING:persistent:0:krb_ccache_rhX3V4v with default princ
>>>>>>> BPrins at EXAMPLE.CORP
>>>>>>> >> [12299] 1426773524.384400: Removing BPrins at EXAMPLE.CORP ->
>>>>>>> krbtgt/EXAMPLE.CORP at EXAMPLE.CORP from
>>>>>>> KEYRING:persistent:0:krb_ccache_rhX3V4v
>>>>>>> >> [12299] 1426773524.384407: Storing BPrins at EXAMPLE.CORP ->
>>>>>>> krbtgt/EXAMPLE.CORP at EXAMPLE.CORP in
>>>>>>> KEYRING:persistent:0:krb_ccache_rhX3V4v
>>>>>>> >> [12299] 1426773524.384469: Storing config in
>>>>>>> KEYRING:persistent:0:krb_ccache_rhX3V4v for
>>>>>>> krbtgt/EXAMPLE.CORP at EXAMPLE.CORP: pa_type: 2
>>>>>>> >> [12299] 1426773524.384484: Removing BPrins at EXAMPLE.CORP ->
>>>>>>> krb5_ccache_conf_data/pa_type/krbtgt\/EXAMPLE.CORP\@EXAMPLE.CORP at X-CACHECONF:
>>>>>>> from KEYRING:persistent:0:krb_ccache_rhX3V4v
>>>>>>> >> [12299] 1426773524.384492: Storing BPrins at EXAMPLE.CORP ->
>>>>>>> krb5_ccache_conf_data/pa_type/krbtgt\/EXAMPLE.CORP\@EXAMPLE.CORP at X-CACHECONF:
>>>>>>> in KEYRING:persistent:0:krb_ccache_rhX3V4v
>>>>>>> >>
>>>>>>> >> Any ideas?
>>>>>>> >
>>>>>>> >Can you log in to the IPA server as this user? If yes I would assume
>>>>>>> >that the password gets garbled somewhere on the way from AIX
>>>>>>> through the
>>>>>>> >IPA machinery to SSSD. Does the password contain some special
>>>>>>> characters
>>>>>>> >which some LDAP processing calls might want the escape?
>>>>>>> >
>>>>>>> >bye,
>>>>>>> >Sumit
>>>>>>> >
>>>>>>> Yes, I can login with the account on the IPA server without any
>>>>>>> problems. I tried it with different password to rule out problems
>>>>>>> with special characters. Finally I did a tcpdump on the IPA server.
>>>>>>> The AIX server sends the word 'INCORRECT' to the IPA server instead
>>>>>>> of the password. So I guess I have to do some more configuration
>>>>>>> checks on the AIX server.
>>>>>>
>>>>>> Thank you for the feedback.
>>>>>>
>>>>>> Just a wild guess, since you were able to see anything in the
>>>>>> tcpdump I
>>>>>> guess an unencrypted connection is used. Maybe AIX prevents that the
>>>>>> password is send via a clear text connection?
>>>>> It is openssh behavior. It sends INCORRECT line as part of the password
>>>>> when there is no valid shell for that user to login.
>>>>>
>>>>> OpenSSH validates content of 'struct passwd' returned for the user,
>>>>> including checks on whether shell is there as an executable file. This
>>>>> check fails and user is considered 'invalid'. Still, OpenSSH competes
>>>>> PAM authentication, making sure the password field is filled with
>>>>> specially constructed string "\b\n\r\177INCORRECT", to ensure there is
>>>>> registered failed login attempt.
>>>> Wow, thanks for that! If I do a lsuser/ldapsearch on the AIX host the
>>>> shell/loginShell is missing for AD users. The admin IPA user has this
>>>> attribute set and I can log in with that account. Can this be solved on
>>>> the IPA server?
>>> In FreeIPA 4.1 (Fedora 21+ or RHEL7.1) you can do set shell separately
>>> for each AD user using ID Views:
>>>
>>> ipa idoverrideuser-add 'Default Trust View' 'AD\User' --shell /bin/ksh
>>>
>>> Compat tree and SSSD on RHEL7.1/Fedora21 should take default trust view
>>> into account for AD users.
>>>
>>Once we are out of the woods here it would be really nice to have a blog
>>or a wiki page about how to configure AIX clients properly to leverage
>>trusts including this interesting aspect related to the shell.
>>Bobby would you be able to share this information?
>>
>>--
>>Thank you,
>>Dmitri Pal
>
>No problem Dmitri. Would love to help with that!
>
>At the moment I'm still getting 'invalid user' messages on the AIX side even though the shell is set using an ID view.
>
>SSH server logging:
>debug3: AIX/loginrestrictions returned -1 msg 3004-300 You entered an invalid login name or password.
>Login restricted for bprins at aero.corp: 3004-300 You entered an invalid login name or password.
>
>Console logging:
>AIX Version 7
>Copyright IBM Corporation, 1982, 2013.
>Console login: bprins at example.corp
>bprins at example.corp's Password:
>3004-300 You entered an invalid login name or password.
>
>'max_logname' in AIX is set to '50' (default is 9(?)). The only account
>attribute differences with a valid AIX user are the rather high id/UID
>and the pgrp/primary group and user name which contain a . and @-sign
>for the AD user. A local user on the AIX server with a high UID and
>symbols in the username can login (did some testing with different user
>names).
>
>For now, SSSD seems to handle the authentication request against AD
>without any problems if I try a console login.
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