[Freeipa-users] RHEL 7 beta trust - slow domain user authentication to Linux hosts

Mon Feb 10 15:55:33 UTC 2014

I've setup RHEL 7 beta IPA with a trust to an AD domain.

When I use an AD domain login it takes roughly 9-14 seconds to get to a
shell after entering a password. Is there any way to speed this process up?
I thought supplemental logins would be quicker, but the login time is the
same. This is either via console, or via ssh at localhost or ssh over the
network.

IPA realm = miolinux.corp
DC domain/forest = miovision.corp

/etc/sssd/sssd_miolinux.corp.log it looks like there is a 5-6 second delay
when checking for subdomains:

(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [be_pam_handler]
(0x0100): Got request with the following data
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): command: PAM_AUTHENTICATE
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): domain: miovision.corp
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): user: sdainard at miovision.corp
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): service: login
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): tty: tty1
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): ruser:
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): rhost:
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): authtok type: 1
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): authtok size: 9
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): newauthtok type: 0
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): newauthtok size: 0
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): priv: 1
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): cli_pid: 9988
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [cc_residual_is_used]
(0x1000): User [799001323] is still active, reusing ccache
[/tmp/krb5cc_799001323_zWaW2Z].
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [check_for_valid_tgt]
(0x0020): krb5_cc_retrieve_cred failed.
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]]
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [get_server_status]
(0x1000): Status of server 'ipa1.miolinux.corp' is 'working'
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [get_port_status]
(0x1000): Port status of port 389 for server 'ipa1.miolinux.corp' is
'working'
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [resolve_srv_send]
(0x0200): The status of SRV lookup is resolved
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [get_server_status]
(0x1000): Status of server 'ipa1.miolinux.corp' is 'working'
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]]
[be_resolve_server_process] (0x1000): Saving the first resolved server
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]]
[be_resolve_server_process] (0x0200): Found address for server
ipa1.miolinux.corp: [10.0.6.3] TTL 508
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [ipa_resolve_callback]
(0x0400): Constructed uri 'ldap://ipa1.miolinux.corp'
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]]
[krb5_find_ccache_step] (0x0080): Saved ccache
FILE:/tmp/krb5cc_799001323_zWaW2Z if of different type than ccache in
configuration file, reusing the old ccache
(Mon Feb 10 10:17:29 2014) [sssd[be[miolinux.corp]]] [write_pipe_handler]
(0x0400): All data has been sent!
(Mon Feb 10 10:17:30 2014) [sssd[be[miolinux.corp]]] [be_get_subdomains]
(0x0400): Got get subdomains [forced][MIOVISION]
*(Mon Feb 10 10:17:30 2014) [sssd[be[miolinux.corp]]]
[get_subdomains_callback] (0x0400): Backend returned: (0, 0, <NULL>)
[Success]*
*(Mon Feb 10 10:17:35 2014) [sssd[be[miolinux.corp]]] [read_pipe_handler]
(0x0400): EOF received, client finished*

It then looks to take another 3-4 seconds to resolve group membership. I've
highlighted an error as well 'user lookup failed':

(Mon Feb 10 10:17:35 2014) [sssd[be[miolinux.corp]]]
[parse_krb5_child_response] (0x1000): child response [0][3][45].
(Mon Feb 10 10:17:35 2014) [sssd[be[miolinux.corp]]]
[parse_krb5_child_response] (0x1000): child response [0][-1073741822][24].
(Mon Feb 10 10:17:35 2014) [sssd[be[miolinux.corp]]]
[parse_krb5_child_response] (0x1000): child response [0][-1073741823][32].
(Mon Feb 10 10:17:35 2014) [sssd[be[miolinux.corp]]]
[parse_krb5_child_response] (0x1000): TGT times are
[1392045449][1392045449][1392081449][1392131849].
(Mon Feb 10 10:17:35 2014) [sssd[be[miolinux.corp]]]
[parse_krb5_child_response] (0x1000): child response [0][6][8].
(Mon Feb 10 10:17:35 2014) [sssd[be[miolinux.corp]]] [fo_set_port_status]
(0x0100): Marking port 389 of server 'ipa1.miolinux.corp' as 'working'
(Mon Feb 10 10:17:35 2014) [sssd[be[miolinux.corp]]]
[set_server_common_status] (0x0100): Marking server 'ipa1.miolinux.corp' as
'working'
(Mon Feb 10 10:17:35 2014) [sssd[be[miolinux.corp]]]
[safe_remove_old_ccache_file] (0x0400): New and old ccache file are the
same, no one will be deleted.
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>)
[Success]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[be_pam_handler_callback] (0x0100): Sending result [0][miovision.corp]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[be_pam_handler_callback] (0x0100): Sent result [0][miovision.corp]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [child_sig_handler]
(0x1000): Waiting for child [10018].
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [child_sig_handler]
(0x0100): child [10018] finished successfully.
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [be_get_account_info]
(0x0100): Got request for [3][1][name=sdainard]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[ipa_get_subdomain_account_info_send] (0x0400): Initgroups requests are not
handled by the IPA provider but are resolved by the responder directly from
the cache.
*(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [acctinfo_callback]
(0x0100): Request processed. Returned 3,95,User lookup failed*
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [be_pam_handler]
(0x0100): Got request with the following data
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): command: PAM_ACCT_MGMT
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): domain: miovision.corp
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): user: sdainard at miovision.corp
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): service: login
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): tty: tty1
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): ruser:
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): rhost:
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): authtok type: 0
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): authtok size: 0
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): newauthtok type: 0
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): newauthtok size: 0
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): priv: 1
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): cli_pid: 9988
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]] [sdap_access_send]
(0x0400): Performing access check for user [sdainard at miovision.corp]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_account_expired_rhds] (0x0400): Performing RHDS access check for user
[sdainard at miovision.corp]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(objectClass=ipaHost)(fqdn=snapshot-test.miolinux.corp))][cn=accounts,dc=miolinux,dc=corp].
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [fqdn]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [serverHostname]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSshPubKey]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUniqueID]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg
set
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_done] (0x1000): Total count [0]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_x_deref_search_send] (0x0400): Dereferencing entry
[fqdn=snapshot-test.miolinux.corp,cn=computers,cn=accounts,dc=miolinux,dc=corp]
using OpenLDAP deref
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no
filter][fqdn=snapshot-test.miolinux.corp,cn=computers,cn=accounts,dc=miolinux,dc=corp].
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUniqueID]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_x_deref_parse_entry] (0x0400): Got deref control
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_x_deref_parse_entry] (0x0400): All deref results from a single
control parsed
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg
set
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_done] (0x1000): Total count [0]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[ipa_hostgroup_info_done] (0x0200): No host groups were dereferenced
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[ipa_hbac_service_info_next] (0x0400): Sending request for next search
base: [cn=hbac,dc=miolinux,dc=corp][2][(objectClass=ipaHBACService)]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(objectClass=ipaHBACService)][cn=hbac,dc=miolinux,dc=corp].
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectclass]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipauniqueid]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [member]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg
set
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_done] (0x1000): Total count [0]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[ipa_hbac_servicegroup_info_next] (0x0400): Sending request for next search
base: [cn=hbac,dc=miolinux,dc=corp][2][(objectClass=ipaHBACServiceGroup)]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(objectClass=ipaHBACServiceGroup)][cn=hbac,dc=miolinux,dc=corp].
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectclass]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipauniqueid]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [member]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg
set
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_done] (0x1000): Total count [0]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[ipa_hbac_rule_info_next] (0x0400): Sending request for next search base:
[cn=hbac,dc=miolinux,dc=corp][2][(&(objectclass=ipaHBACRule)(ipaenabledflag=TRUE)(|(hostCategory=all)(memberHost=fqdn=snapshot-test.miolinux.corp,cn=computers,cn=accounts,dc=miolinux,dc=corp)))]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(objectclass=ipaHBACRule)(ipaenabledflag=TRUE)(|(hostCategory=all)(memberHost=fqdn=snapshot-test.miolinux.corp,cn=computers,cn=accounts,dc=miolinux,dc=corp)))][cn=hbac,dc=miolinux,dc=corp].
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectclass]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipauniqueid]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaenabledflag]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accessRuleType]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberUser]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCategory]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberService]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [serviceCategory]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sourceHost]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sourceHostCategory]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [externalHost]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberHost]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [hostCategory]
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg
set
(Mon Feb 10 10:17:36 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_done] (0x1000): Total count [0]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]] [hbac_attrs_to_rule]
(0x1000): Processing rule [allow_all]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[hbac_user_attrs_to_rule] (0x1000): Processing users for rule [allow_all]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]] [hbac_get_category]
(0x0200): Category is set to 'all'.
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[hbac_service_attrs_to_rule] (0x1000): Processing PAM services for rule
[allow_all]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]] [hbac_get_category]
(0x0200): Category is set to 'all'.
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[hbac_thost_attrs_to_rule] (0x1000): Processing target hosts for rule
[allow_all]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]] [hbac_get_category]
(0x0200): Category is set to 'all'.
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[hbac_shost_attrs_to_rule] (0x0400): Processing source hosts for rule
[allow_all]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[hbac_eval_user_element] (0x1000): No groups for [sdainard at miovision.corp]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[ipa_hbac_evaluate_rules] (0x0080): Access granted by HBAC rule [allow_all]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>)
[Success]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]] [ipa_get_selinux_send]
(0x0400): Retrieving SELinux user mapping
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(cn=ipaConfig)(objectClass=ipaGuiConfig))][cn=etc,dc=miolinux,dc=corp].
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[ipaMigrationEnabled]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[ipaSELinuxUserMapDefault]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[ipaSELinuxUserMapOrder]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg
set
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[ipa_selinux_get_maps_next] (0x0400): Trying to fetch SELinux maps with
following parameters:
[2][(&(objectclass=ipaselinuxusermap)(ipaEnabledFlag=TRUE))][cn=selinux,dc=miolinux,dc=corp]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(objectclass=ipaselinuxusermap)(ipaEnabledFlag=TRUE))][cn=selinux,dc=miolinux,dc=corp].
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberUser]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberHost]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [seeAlso]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSELinuxUser]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaEnabledFlag]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCategory]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [hostCategory]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUniqueID]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg
set
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_done] (0x1000): Total count [0]
(Mon Feb 10 10:17:37 2014) [sssd[be[miolinux.corp]]]
[ipa_selinux_get_maps_done] (0x0400): No SELinux user maps found!
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[be_pam_handler_callback] (0x0100): Backend returned: (0, 0, Success)
[Success]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[be_pam_handler_callback] (0x0100): Sending result [0][miovision.corp]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[be_pam_handler_callback] (0x0100): Sent result [0][miovision.corp]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [be_get_account_info]
(0x0100): Got request for [4099][1][name=sdainard]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[ipa_get_subdomain_account_info_send] (0x0400): Initgroups requests are not
handled by the IPA provider but are resolved by the responder directly from
the cache.
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [acctinfo_callback]
(0x0100): Request processed. Returned 3,95,User lookup failed
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [be_get_account_info]
(0x0100): Got request for [3][1][name=sdainard]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[ipa_get_subdomain_account_info_send] (0x0400): Initgroups requests are not
handled by the IPA provider but are resolved by the responder directly from
the cache.
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [acctinfo_callback]
(0x0100): Request processed. Returned 3,95,User lookup failed
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [be_pam_handler]
(0x0100): Got request with the following data
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): command: PAM_OPEN_SESSION
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): domain: miovision.corp
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): user: sdainard at miovision.corp
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): service: login
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): tty: tty1
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): ruser:
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): rhost:
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): authtok type: 0
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): authtok size: 0
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): newauthtok type: 0
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): newauthtok size: 0
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): priv: 1
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): cli_pid: 9988
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [be_pam_handler]
(0x0100): Sending result [0][miovision.corp]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [be_get_account_info]
(0x0100): Got request for [3][1][name=sdainard]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[ipa_get_subdomain_account_info_send] (0x0400): Initgroups requests are not
handled by the IPA provider but are resolved by the responder directly from
the cache.
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [acctinfo_callback]
(0x0100): Request processed. Returned 3,95,User lookup failed
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [be_pam_handler]
(0x0100): Got request with the following data
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): command: PAM_SETCRED
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): domain: miovision.corp
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): user: sdainard at miovision.corp
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): service: login
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): tty: tty1
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): ruser:
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): rhost:
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): authtok type: 0
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): authtok size: 0
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): newauthtok type: 0
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): newauthtok size: 0
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): priv: 1
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [pam_print_data]
(0x0100): cli_pid: 9988
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [be_pam_handler]
(0x0100): Sending result [0][miovision.corp]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [be_get_account_info]
(0x0100): Got request for [4098][1][idnumber=799001323]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[sdap_get_groups_next_base] (0x0400): Searching for groups with base
[cn=accounts,dc=miolinux,dc=corp]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(gidNumber=799001323)(objectclass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][cn=accounts,dc=miolinux,dc=corp].
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [member]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsUniqueId]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN]
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg
set
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[sdap_get_groups_process] (0x0400): Search for groups, returned 0 results.
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]]
[sysdb_search_group_by_gid] (0x0400): No such entry
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [sysdb_delete_group]
(0x0400): Error: 2 (No such file or directory)
(Mon Feb 10 10:17:38 2014) [sssd[be[miolinux.corp]]] [acctinfo_callback]
(0x0100): Request processed. Returned 0,0,Success

I've read that the method of determining AD group membership is expected to
take a while, but is this normal?

Thanks,

*Steve *
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20140210/810ff0c5/attachment.htm>