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

Fri Apr 3 10:28:31 UTC 2015

>> On Mar 24, 2015, at 17:11, Dmitri Pal <dpal at redhat.com> wrote:
>> 
>> Seems like 15 sec timeout on the AIX side.
>> Can you try with a user that does not have that many groups and see if that works?
>> If it does then we should assume it is an AIX side timeout and focus on making sure the data gets over to IPA within this timeout.
>I need to do some more testing.. Did not have a lot of time today, but I tried to authenticate with an AD user against the compact tree using a Linux client with pam_ldap. I was able to log in but this would take up to a minute or so. I’m still waiting for my AD test account with lesser group memberships.
>> 
>> -- 
>> Thank you,
>> Dmitri Pal
>> 
>> Sr. Engineering Manager IdM portfolio
>> Red Hat, Inc.
>> 
So I finally found some time to do extra tests. I now have an AD account with lesser group memberships which seems to speed up the login process (with Linux LDAP auth against the compat tree), but still no success on AIX. Did some more digging and it looks like AIX invalidates the user before it even is authenticated. The output below shows the lookup that is performed after I enter the username en press enter (before entering the password).

access:
[03/Apr/2015:11:58:47 +0200] conn=5950 fd=68 slot=68 connection from 192.168.140.107 to 192.168.140.133
[03/Apr/2015:11:58:47 +0200] conn=5950 op=0 BIND dn="" method=128 version=3
[03/Apr/2015:11:58:47 +0200] conn=5950 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn=""
[03/Apr/2015:11:59:04 +0200] conn=5950 op=1 SRCH base="cn=users,cn=compat,dc=unix,dc=example,dc=corp" scope=2 filter="(&(objectClass=posixaccount)(uid=bprins at example.corp))" attrs=ALL
[03/Apr/2015:11:59:04 +0200] conn=5950 op=1 RESULT err=0 tag=101 nentries=1 etime=0
[03/Apr/2015:11:59:04 +0200] conn=5950 op=2 SRCH base="cn=users,cn=compat,dc=unix,dc=example,dc=corp" scope=2 filter="(&(objectClass=posixaccount)(uid=bprins))" attrs=ALL
[03/Apr/2015:11:59:04 +0200] conn=5950 op=2 RESULT err=0 tag=101 nentries=0 etime=0

sssd_unix.example.corp.log:
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sbus_dispatch] (0x4000): dbus conn: 0x7fae8e331c20
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sbus_handler_got_caller_id] (0x4000): Received SBUS method [getAccountInfo]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=bprins]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [be_req_set_domain] (0x0400): Changing request domain from [unix.example.corp] to [unix.example.corp]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_search_user_next_base] (0x0400): Searching for users with base [cn=accounts,dc=unix,dc=example,dc=corp]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_print_server] (0x2000): Searching 192.168.140.133
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=bprins)(objectclass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=unix,dc=example,dc=corp].
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUniqueID]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaNTSecurityIdentifier]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSshPubKey]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUserAuthType]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 25
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_process_result] (0x2000): Trace: sh[0x7fae91451360], connected[1], ops[0x7fae8f3883b0], ldap[0x7fae8f384e70]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_search_user_process] (0x0400): Search for users, returned 0 results.
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_get_users_done] (0x0040): Failed to retrieve users
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_id_op_done] (0x4000): releasing operation connection
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fae9171c0d0

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fae91459fd0

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Running timer event 0x7fae9171c0d0 "ltdb_callback"

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Destroying timer event 0x7fae91459fd0 "ltdb_timeout"

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Ending timer event 0x7fae9171c0d0 "ltdb_callback"

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sysdb_search_by_name] (0x0400): No such entry
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sysdb_search_groups] (0x2000): Search groups with filter: (&(objectclass=group)(ghost=bprins))
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fae913a30a0

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fae91a6dc30

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Running timer event 0x7fae913a30a0 "ltdb_callback"

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Destroying timer event 0x7fae91a6dc30 "ltdb_timeout"

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Ending timer event 0x7fae913a30a0 "ltdb_callback"

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sysdb_search_groups] (0x2000): No such entry
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sysdb_delete_user] (0x0400): Error: 2 (No such file or directory)
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fae918d7180

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fae8e3512a0

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Running timer event 0x7fae918d7180 "ltdb_callback"

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Destroying timer event 0x7fae8e3512a0 "ltdb_timeout"

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Ending timer event 0x7fae918d7180 "ltdb_callback"

(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sysdb_search_by_name] (0x0400): No such entry
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [ipa_id_get_account_info_orig_done] (0x0080): Object not found, ending request
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [acctinfo_callback] (0x0100): Request processed. Returned 3,0,Account info lookup failed
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_process_result] (0x2000): Trace: sh[0x7fae91451360], connected[1], ops[(nil)], ldap[0x7fae8f384e70]
(Fri Apr  3 11:59:04 2015) [sssd[be[unix.example.corp]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!

sssd_nss.log:
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [get_client_cred] (0x4000): Client creds: euid[997] egid[995] pid[25016].
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f9b8338d3a0][20]
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected!
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f9b8338d3a0][20]
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1].
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1].
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f9b8338d3a0][20]
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f9b8338d3a0][20]
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17] with input [bprins].
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'bprins' matched without domain, user is bprins
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [bprins] from [<ALL>]
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/unix.example.corp/bprins]
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [bprins at unix.example.corp]
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f9b8338df70

(Fri Apr  3 11:59:04 2015) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f9b8338b520

(Fri Apr  3 11:59:04 2015) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f9b8338df70 "ltdb_callback"

(Fri Apr  3 11:59:04 2015) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f9b8338b520 "ltdb_timeout"

(Fri Apr  3 11:59:04 2015) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f9b8338df70 "ltdb_callback"

(Fri Apr  3 11:59:04 2015) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f9b82d9be00:1:bprins at unix.example.corp]
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [unix.example.corp][4097][1][name=bprins]
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x7f9b83388fe0
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f9b82d9be00:1:bprins at unix.example.corp]
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x7f9b83388fe0
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x7f9b83384680
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 3 errno: 0 error message: Account info lookup failed
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [nss_cmd_getby_dp_callback] (0x0040): Unable to get information from Data Provider
Error: 3, 0, Account info lookup failed
Will try to return what we have in cache
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f9b82d9be00:1:bprins at unix.example.corp]
(Fri Apr  3 11:59:04 2015) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f9b8338d3a0][20]

In the end the lookup is performed in unix.example.corp instead of example.corp and thus it cannot find the (aero.corp AD) user object. Any thoughts?