>> On Mar 24, 2015, at 17:11, Dmitri Pal <d...@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=bpr...@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 [bpr...@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:bpr...@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:bpr...@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:bpr...@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?

-- 
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project

Reply via email to