I noticed that when login to IPA server (mripa1) itself, the only PAM
process is PAM_OPEN_SESSION,
whereas for mripadm it goes through 5: PAM_AUTHENTICATE, PAM_ACCT_MGMT,
PAM_SETCRED,
PAM_OPEN_SESSION, PAM_SETCRED in that order. I have virtually identical
SSSD and PAM config
for both servers...
Microsecond enabled:
----- sssd_mr.ric.log -----
On 04/15/2015 02:08 PM, Lukas Slebodnik wrote:(Wed Apr 15
14:19:44:106338 2015) [sssd[be[mr.ric]]] [be_get_account_info] (0x0200):
Got request for [0x3][1][name=qchang]
(Wed Apr 15 14:19:44:106368 2015) [sssd[be[mr.ric]]] [be_req_set_domain]
(0x0400): Changing request domain from [mr.ric] to [mr.ric]
(Wed Apr 15 14:19:44:106657 2015) [sssd[be[mr.ric]]]
[sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
domain SID from [(null)]
(Wed Apr 15 14:19:44:106713 2015) [sssd[be[mr.ric]]]
[sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
domain SID from [(null)]
(Wed Apr 15 14:19:44:106761 2015) [sssd[be[mr.ric]]]
[sdap_get_initgr_next_base] (0x0400): Searching for users with base
[cn=accounts,dc=mr,dc=ric]
(Wed Apr 15 14:19:44:106789 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(uid=qchang)(objectclass=po
sixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=mr,dc=ric].
(Wed Apr 15 14:19:44:110469 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
(Wed Apr 15 14:19:44:110561 2015) [sssd[be[mr.ric]]] [sdap_save_user]
(0x0400): Save user
(Wed Apr 15 14:19:44:110596 2015) [sssd[be[mr.ric]]]
[sdap_get_primary_name] (0x0400): Processing object qchang
(Wed Apr 15 14:19:44:110610 2015) [sssd[be[mr.ric]]] [sdap_save_user]
(0x0400): Processing user qchang
(Wed Apr 15 14:19:44:110623 2015) [sssd[be[mr.ric]]]
[sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
domain SID from [(null)]
(Wed Apr 15 14:19:44:110639 2015) [sssd[be[mr.ric]]] [sdap_save_user]
(0x0400): Adding original memberOf attributes to [qchang].
(Wed Apr 15 14:19:44:110656 2015) [sssd[be[mr.ric]]] [sdap_save_user]
(0x0400): Adding user principal [qchang(a)MR.RIC] to attributes of [qchang].
(Wed Apr 15 14:19:44:110730 2015) [sssd[be[mr.ric]]] [sdap_save_user]
(0x0400): Storing info for user qchang
(Wed Apr 15 14:19:44:113458 2015) [sssd[be[mr.ric]]]
[sdap_get_primary_name] (0x0400): Processing object qchang
(Wed Apr 15 14:19:44:113493 2015) [sssd[be[mr.ric]]]
[sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP
(Wed Apr 15 14:19:44:113515 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(|(objectClass=ipaUserGroup
)(objectClass=posixGroup))(cn=*))][cn=ipausers,cn=groups,cn=accounts,dc=mr,dc=ric].
(Wed Apr 15 14:19:44:114852 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
(Wed Apr 15 14:19:44:114889 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(|(objectClass=ipaUserGroup
)(objectClass=posixGroup))(cn=*))][ipaUniqueID=34bb1bba-de25-11e4-b4e1-000c29f4de6e,cn=sudorules,cn=sudo,dc=mr,dc=ric].
(Wed Apr 15 14:19:44:115455 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
(Wed Apr 15 14:19:44:115484 2015) [sssd[be[mr.ric]]]
[sdap_initgr_nested_search] (0x0040): Search for group
ipaUniqueID=34bb1bba-de25-11e4-b4e1-000c29
f4de6e,cn=sudorules,cn=sudo,dc=mr,dc=ric, returned 0 results. Skipping
(Wed Apr 15 14:19:44:115662 2015) [sssd[be[mr.ric]]]
[sdap_get_primary_name] (0x0400): Processing object ipausers
(Wed Apr 15 14:19:44:115854 2015) [sssd[be[mr.ric]]]
[sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
domain SID from [(null)]
(Wed Apr 15 14:19:44:115891 2015) [sssd[be[mr.ric]]]
[sdap_get_groups_next_base] (0x0400): Searching for groups with base
[cn=accounts,dc=mr,dc=ric]
(Wed Apr 15 14:19:44:115916 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(gidNumber=10001)(|(objectC
lass=ipaUserGroup)(objectClass=posixGroup))(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][cn=accounts,dc=mr,dc=ric].
(Wed Apr 15 14:19:44:117467 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
(Wed Apr 15 14:19:44:117500 2015) [sssd[be[mr.ric]]]
[sdap_get_groups_process] (0x0400): Search for groups, returned 1 results.
(Wed Apr 15 14:19:44:117529 2015) [sssd[be[mr.ric]]]
[sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP
(Wed Apr 15 14:19:44:117543 2015) [sssd[be[mr.ric]]]
[sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
domain SID from [(null)]
(Wed Apr 15 14:19:44:117571 2015) [sssd[be[mr.ric]]]
[sdap_nested_group_recv] (0x0400): 0 users found in the hash table
(Wed Apr 15 14:19:44:117587 2015) [sssd[be[mr.ric]]]
[sdap_nested_group_recv] (0x0400): 1 groups found in the hash table
(Wed Apr 15 14:19:44:117654 2015) [sssd[be[mr.ric]]]
[sdap_get_primary_name] (0x0400): Processing object qchang
(Wed Apr 15 14:19:44:117672 2015) [sssd[be[mr.ric]]] [sdap_save_group]
(0x0400): Processing group qchang
(Wed Apr 15 14:19:44:117683 2015) [sssd[be[mr.ric]]]
[sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
domain SID from [(null)]
(Wed Apr 15 14:19:44:117720 2015) [sssd[be[mr.ric]]]
[sdap_process_ghost_members] (0x0400): The group has 0 members
(Wed Apr 15 14:19:44:117745 2015) [sssd[be[mr.ric]]]
[sdap_process_ghost_members] (0x0400): Group has 0 members
(Wed Apr 15 14:19:44:117759 2015) [sssd[be[mr.ric]]] [sdap_save_group]
(0x0400): Storing info for group qchang
(Wed Apr 15 14:19:44:118029 2015) [sssd[be[mr.ric]]]
[sdap_get_primary_name] (0x0400): Processing object qchang
(Wed Apr 15 14:19:44:118049 2015) [sssd[be[mr.ric]]] [sdap_save_grpmem]
(0x0400): Processing group qchang
(Wed Apr 15 14:19:44:118060 2015) [sssd[be[mr.ric]]] [sdap_save_grpmem]
(0x0400): Failed to get group sid
(Wed Apr 15 14:19:44:118071 2015) [sssd[be[mr.ric]]] [sdap_save_grpmem]
(0x0400): No members for group [qchang]
(Wed Apr 15 14:19:44:120176 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(objectClass=ipaOverrideAnc
hor)(ipaAnchorUUID=:IPA:mr.ric:4b2724aa-d87d-11e4-93fa-000c29f4de6e))][cn=Default
Trust View,cn=views,cn=accounts,dc=mr,dc=ric].
(Wed Apr 15 14:19:44:120787 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_op_finished] (0x0400): Search result: No such
object(32), no errmsg set
(Wed Apr 15 14:19:44:121356 2015) [sssd[be[mr.ric]]] [acctinfo_callback]
(0x0100): Request processed. Returned 0,0,Success
(Wed Apr 15 14:19:44:122127 2015) [sssd[be[mr.ric]]] [be_req_set_domain]
(0x0400): Changing request domain from [mr.ric] to [mr.ric]
(Wed Apr 15 14:19:44:122152 2015) [sssd[be[mr.ric]]] [be_pam_handler]
(0x0100): Got request with the following data
(Wed Apr 15 14:19:44:122163 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): command: PAM_AUTHENTICATE
(Wed Apr 15 14:19:44:122173 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): domain: mr.ric
(Wed Apr 15 14:19:44:122183 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): user: qchang
(Wed Apr 15 14:19:44:122193 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): service: sshd
(Wed Apr 15 14:19:44:122202 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): tty: ssh
(Wed Apr 15 14:19:44:122212 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): ruser:
(Wed Apr 15 14:19:44:122221 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): rhost: 172.25.12.157
(Wed Apr 15 14:19:44:122232 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): authtok type: 1
(Wed Apr 15 14:19:44:122242 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): newauthtok type: 0
(Wed Apr 15 14:19:44:122251 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): priv: 1
(Wed Apr 15 14:19:44:122261 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): cli_pid: 28330
(Wed Apr 15 14:19:44:122271 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): logon name: not set
(Wed Apr 15 14:19:44:122399 2015) [sssd[be[mr.ric]]]
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
(Wed Apr 15 14:19:44:122422 2015) [sssd[be[mr.ric]]] [resolve_srv_send]
(0x0200): The status of SRV lookup is resolved
(Wed Apr 15 14:19:44:122443 2015) [sssd[be[mr.ric]]]
[be_resolve_server_process] (0x0200): Found address for server
mripa1.mr.ric: [172.25.12.153] TTL
1200
(Wed Apr 15 14:19:44:122460 2015) [sssd[be[mr.ric]]]
[ipa_resolve_callback] (0x0400): Constructed uri 'ldap://mripa1.mr.ric'
(Wed Apr 15 14:19:44:123509 2015) [sssd[be[mr.ric]]]
[write_pipe_handler] (0x0400): All data has been sent!
(Wed Apr 15 14:19:45:169789 2015) [sssd[be[mr.ric]]] [child_sig_handler]
(0x0100): child [28332] finished successfully.
(Wed Apr 15 14:19:45:169853 2015) [sssd[be[mr.ric]]] [read_pipe_handler]
(0x0400): EOF received, client finished
(Wed Apr 15 14:19:45:169926 2015) [sssd[be[mr.ric]]]
[fo_set_port_status] (0x0100): Marking port 389 of server
'mripa1.mr.ric' as 'working'
(Wed Apr 15 14:19:45:169953 2015) [sssd[be[mr.ric]]]
[set_server_common_status] (0x0100): Marking server 'mripa1.mr.ric' as
'working'
(Wed Apr 15 14:19:45:169973 2015) [sssd[be[mr.ric]]]
[fo_set_port_status] (0x0400): Marking port 389 of duplicate server
'mripa1.mr.ric' as 'working'
(Wed Apr 15 14:19:45:221211 2015) [sssd[be[mr.ric]]]
[be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>)
[Success]
(Wed Apr 15 14:19:45:221242 2015) [sssd[be[mr.ric]]]
[be_pam_handler_callback] (0x0100): Sending result [0][mr.ric]
(Wed Apr 15 14:19:45:221325 2015) [sssd[be[mr.ric]]]
[be_pam_handler_callback] (0x0100): Sent result [0][mr.ric]
(Wed Apr 15 14:19:45:225865 2015) [sssd[be[mr.ric]]] [be_req_set_domain]
(0x0400): Changing request domain from [mr.ric] to [mr.ric]
(Wed Apr 15 14:19:45:225894 2015) [sssd[be[mr.ric]]] [be_pam_handler]
(0x0100): Got request with the following data
(Wed Apr 15 14:19:45:225905 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): command: PAM_ACCT_MGMT
(Wed Apr 15 14:19:45:225915 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): domain: mr.ric
(Wed Apr 15 14:19:45:225925 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): user: qchang
(Wed Apr 15 14:19:45:225934 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): service: sshd
(Wed Apr 15 14:19:45:225944 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): tty: ssh
(Wed Apr 15 14:19:45:225954 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): ruser:
(Wed Apr 15 14:19:45:225963 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): rhost: 172.25.12.157
(Wed Apr 15 14:19:45:225973 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): authtok type: 0
(Wed Apr 15 14:19:45:225983 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): newauthtok type: 0
(Wed Apr 15 14:19:45:225992 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): priv: 1
(Wed Apr 15 14:19:45:226002 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): cli_pid: 28330
(Wed Apr 15 14:19:45:226012 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): logon name: not set
(Wed Apr 15 14:19:45:226030 2015) [sssd[be[mr.ric]]] [sdap_access_send]
(0x0400): Performing access check for user [qchang]
(Wed Apr 15 14:19:45:226168 2015) [sssd[be[mr.ric]]]
[sdap_account_expired_rhds] (0x0400): Performing RHDS access check for
user [qchang]
(Wed Apr 15 14:19:45:226213 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(objectClass=ipaHost)(fqdn=
mripadm.mr.ric))][cn=accounts,dc=mr,dc=ric].
(Wed Apr 15 14:19:45:228995 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
(Wed Apr 15 14:19:45:229039 2015) [sssd[be[mr.ric]]]
[sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP
(Wed Apr 15 14:19:45:229063 2015) [sssd[be[mr.ric]]]
[sdap_x_deref_search_send] (0x0400): Dereferencing entry
[fqdn=mripadm.mr.ric,cn=computers,cn=acc
ounts,dc=mr,dc=ric] using OpenLDAP deref
(Wed Apr 15 14:19:45:229077 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no
filter][fqdn=mripadm.mr.ri
c,cn=computers,cn=accounts,dc=mr,dc=ric].
(Wed Apr 15 14:19:46:175840 2015) [sssd[be[mr.ric]]]
[sdap_x_deref_parse_entry] (0x0400): Got deref control
(Wed Apr 15 14:19:46:175969 2015) [sssd[be[mr.ric]]]
[sdap_x_deref_parse_entry] (0x0400): All deref results from a single
control parsed
(Wed Apr 15 14:19:46:176072 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
(Wed Apr 15 14:19:46:176128 2015) [sssd[be[mr.ric]]]
[ipa_hostgroup_info_done] (0x0200): Dereferenced host group:
mr-server-centos
(Wed Apr 15 14:19:46:176152 2015) [sssd[be[mr.ric]]]
[ipa_hostgroup_info_done] (0x0200): Dereferenced host group: mr-nix
(Wed Apr 15 14:19:46:176201 2015) [sssd[be[mr.ric]]]
[ipa_hbac_service_info_next] (0x0400): Sending request for next search
base: [cn=hbac,dc=mr,dc=ri
c][2][(objectClass=ipaHBACService)]
(Wed Apr 15 14:19:46:176230 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(objectClass=ipaHBACService)]
[cn=hbac,dc=mr,dc=ric].
(Wed Apr 15 14:19:46:184539 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
(Wed Apr 15 14:19:46:184615 2015) [sssd[be[mr.ric]]]
[ipa_hbac_servicegroup_info_next] (0x0400): Sending request for next
search base: [cn=hbac,dc=mr,
dc=ric][2][(objectClass=ipaHBACServiceGroup)]
(Wed Apr 15 14:19:46:184644 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(objectClass=ipaHBACServiceGr
oup)][cn=hbac,dc=mr,dc=ric].
(Wed Apr 15 14:19:46:186319 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
(Wed Apr 15 14:19:46:186443 2015) [sssd[be[mr.ric]]]
[ipa_hbac_rule_info_next] (0x0400): Sending request for next search
base: [cn=hbac,dc=mr,dc=ric][
2][(&(objectclass=ipaHBACRule)(ipaenabledflag=TRUE)(|(hostCategory=all)(memberHost=fqdn=mripadm.mr.ric,cn=computers,cn=accounts,dc=mr,dc=ric)(memberHo
st=cn=mr-server-centos,cn=hostgroups,cn=accounts,dc=mr,dc=ric)(memberHost=cn=mr-server-centos,cn=ng,cn=alt,dc=mr,dc=ric)(memberHost=cn=mr-nix,cn=hostg
roups,cn=accounts,dc=mr,dc=ric)(memberHost=cn=mr-nix,cn=ng,cn=alt,dc=mr,dc=ric)(memberHost=ipaUniqueID=34bb1bba-de25-11e4-b4e1-000c29f4de6e,cn=sudorul
es,cn=sudo,dc=mr,dc=ric)))]
(Wed Apr 15 14:19:46:186478 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(objectclass=ipaHBACRule)(i
paenabledflag=TRUE)(|(hostCategory=all)(memberHost=fqdn=mripadm.mr.ric,cn=computers,cn=accounts,dc=mr,dc=ric)(memberHost=cn=mr-server-centos,cn=hostgr
oups,cn=accounts,dc=mr,dc=ric)(memberHost=cn=mr-server-centos,cn=ng,cn=alt,dc=mr,dc=ric)(memberHost=cn=mr-nix,cn=hostgroups,cn=accounts,dc=mr,dc=ric)(
memberHost=cn=mr-nix,cn=ng,cn=alt,dc=mr,dc=ric)(memberHost=ipaUniqueID=34bb1bba-de25-11e4-b4e1-000c29f4de6e,cn=sudorules,cn=sudo,dc=mr,dc=ric)))][cn=h
bac,dc=mr,dc=ric].
(Wed Apr 15 14:19:46:189436 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
(Wed Apr 15 14:19:46:204453 2015) [sssd[be[mr.ric]]] [hbac_get_category]
(0x0200): Category is set to 'all'.
(Wed Apr 15 14:19:46:204485 2015) [sssd[be[mr.ric]]] [hbac_get_category]
(0x0200): Category is set to 'all'.
(Wed Apr 15 14:19:46:204499 2015) [sssd[be[mr.ric]]] [hbac_get_category]
(0x0200): Category is set to 'all'.
(Wed Apr 15 14:19:46:204511 2015) [sssd[be[mr.ric]]]
[hbac_shost_attrs_to_rule] (0x0400): Processing source hosts for rule
[allow_all]
(Wed Apr 15 14:19:46:204716 2015) [sssd[be[mr.ric]]]
[ipa_hbac_evaluate_rules] (0x0080): Access granted by HBAC rule [allow_all]
(Wed Apr 15 14:19:46:204747 2015) [sssd[be[mr.ric]]]
[be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>)
[Success]
(Wed Apr 15 14:19:46:204860 2015) [sssd[be[mr.ric]]]
[ipa_get_selinux_send] (0x0400): Retrieving SELinux user mapping
(Wed Apr 15 14:19:46:204893 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(cn=ipaConfig)(objectClass=
ipaGuiConfig))][cn=etc,dc=mr,dc=ric].
(Wed Apr 15 14:19:46:206852 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
(Wed Apr 15 14:19:46:206899 2015) [sssd[be[mr.ric]]]
[ipa_selinux_get_maps_next] (0x0400): Trying to fetch SELinux maps with
following parameters: [2]
[(&(objectclass=ipaselinuxusermap)(ipaEnabledFlag=TRUE))][cn=selinux,dc=mr,dc=ric]
(Wed Apr 15 14:19:46:206917 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(objectclass=ipaselinuxuser
map)(ipaEnabledFlag=TRUE))][cn=selinux,dc=mr,dc=ric].
(Wed Apr 15 14:19:46:207979 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
(Wed Apr 15 14:19:46:208011 2015) [sssd[be[mr.ric]]]
[ipa_selinux_get_maps_done] (0x0400): No SELinux user maps found!
(Wed Apr 15 14:19:46:210900 2015) [sssd[be[mr.ric]]]
[write_pipe_handler] (0x0400): All data has been sent!
(Wed Apr 15 14:19:47:557404 2015) [sssd[be[mr.ric]]]
[be_get_account_info] (0x0200): Got request for [0x1003][1][name=avahi]
(Wed Apr 15 14:19:47:557429 2015) [sssd[be[mr.ric]]] [be_req_set_domain]
(0x0400): Changing request domain from [mr.ric] to [mr.ric]
(Wed Apr 15 14:19:47:557553 2015) [sssd[be[mr.ric]]]
[sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
domain SID from [(null)]
(Wed Apr 15 14:19:47:557575 2015) [sssd[be[mr.ric]]]
[sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
domain SID from [(null)]
(Wed Apr 15 14:19:47:557592 2015) [sssd[be[mr.ric]]]
[sdap_get_initgr_next_base] (0x0400): Searching for users with base
[cn=accounts,dc=mr,dc=ric]
(Wed Apr 15 14:19:47:557604 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(uid=avahi)(objectclass=pos
ixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=mr,dc=ric].
(Wed Apr 15 14:19:47:568772 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
(Wed Apr 15 14:19:47:568858 2015) [sssd[be[mr.ric]]]
[sysdb_search_by_name] (0x0400): No such entry
(Wed Apr 15 14:19:47:568979 2015) [sssd[be[mr.ric]]] [sysdb_delete_user]
(0x0400): Error: 2 (No such file or directory)
(Wed Apr 15 14:19:47:569042 2015) [sssd[be[mr.ric]]]
[sysdb_search_by_name] (0x0400): No such entry
(Wed Apr 15 14:19:47:569055 2015) [sssd[be[mr.ric]]]
[ipa_id_get_account_info_orig_done] (0x0080): Object not found, ending
request
(Wed Apr 15 14:19:47:569093 2015) [sssd[be[mr.ric]]] [acctinfo_callback]
(0x0100): Request processed. Returned 3,0,Account info lookup failed
(Wed Apr 15 14:19:47:570494 2015) [sssd[be[mr.ric]]]
[be_get_account_info] (0x0200): Got request for [0x1003][1][name=polkitd]
(Wed Apr 15 14:19:47:570512 2015) [sssd[be[mr.ric]]] [be_req_set_domain]
(0x0400): Changing request domain from [mr.ric] to [mr.ric]
(Wed Apr 15 14:19:47:570590 2015) [sssd[be[mr.ric]]]
[sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
domain SID from [(null)]
(Wed Apr 15 14:19:47:570608 2015) [sssd[be[mr.ric]]]
[sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
domain SID from [(null)]
(Wed Apr 15 14:19:47:570617 2015) [sssd[be[mr.ric]]]
[sdap_get_initgr_next_base] (0x0400): Searching for users with base
[cn=accounts,dc=mr,dc=ric]
(Wed Apr 15 14:19:47:570626 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(uid=polkitd)(objectclass=p
osixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=mr,dc=ric].
(Wed Apr 15 14:19:47:581734 2015) [sssd[be[mr.ric]]]
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
(Wed Apr 15 14:19:47:581814 2015) [sssd[be[mr.ric]]]
[sysdb_search_by_name] (0x0400): No such entry
(Wed Apr 15 14:19:47:581873 2015) [sssd[be[mr.ric]]] [sysdb_delete_user]
(0x0400): Error: 2 (No such file or directory)
(Wed Apr 15 14:19:47:581929 2015) [sssd[be[mr.ric]]]
[sysdb_search_by_name] (0x0400): No such entry
(Wed Apr 15 14:19:47:581941 2015) [sssd[be[mr.ric]]]
[ipa_id_get_account_info_orig_done] (0x0080): Object not found, ending
request
(Wed Apr 15 14:19:47:581975 2015) [sssd[be[mr.ric]]] [acctinfo_callback]
(0x0100): Request processed. Returned 3,0,Account info lookup failed
(Wed Apr 15 14:19:47:801991 2015) [sssd[be[mr.ric]]] [child_sig_handler]
(0x0100): child [28333] finished successfully.
(Wed Apr 15 14:19:47:802026 2015) [sssd[be[mr.ric]]] [read_pipe_handler]
(0x0400): EOF received, client finished
(Wed Apr 15 14:19:47:802052 2015) [sssd[be[mr.ric]]]
[be_pam_handler_callback] (0x0100): Backend returned: (0, 0, Success)
[Success]
(Wed Apr 15 14:19:47:802063 2015) [sssd[be[mr.ric]]]
[be_pam_handler_callback] (0x0100): Sending result [0][mr.ric]
(Wed Apr 15 14:19:47:802120 2015) [sssd[be[mr.ric]]]
[be_pam_handler_callback] (0x0100): Sent result [0][mr.ric]
(Wed Apr 15 14:19:47:809548 2015) [sssd[be[mr.ric]]] [be_req_set_domain]
(0x0400): Changing request domain from [mr.ric] to [mr.ric]
(Wed Apr 15 14:19:47:809567 2015) [sssd[be[mr.ric]]] [be_pam_handler]
(0x0100): Got request with the following data
(Wed Apr 15 14:19:47:809576 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): command: PAM_SETCRED
(Wed Apr 15 14:19:47:809583 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): domain: mr.ric
(Wed Apr 15 14:19:47:809590 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): user: qchang
(Wed Apr 15 14:19:47:809598 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): service: sshd
(Wed Apr 15 14:19:47:809605 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): tty: ssh
(Wed Apr 15 14:19:47:809618 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): ruser:
(Wed Apr 15 14:19:47:809627 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): rhost: 172.25.12.157
(Wed Apr 15 14:19:47:809634 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): authtok type: 0
(Wed Apr 15 14:19:47:809641 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): newauthtok type: 0
(Wed Apr 15 14:19:47:809649 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): priv: 1
(Wed Apr 15 14:19:47:809656 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): cli_pid: 28330
(Wed Apr 15 14:19:47:809663 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): logon name: not set
(Wed Apr 15 14:19:47:809671 2015) [sssd[be[mr.ric]]] [be_pam_handler]
(0x0100): Sending result [0][mr.ric]
(Wed Apr 15 14:19:47:922194 2015) [sssd[be[mr.ric]]] [be_req_set_domain]
(0x0400): Changing request domain from [mr.ric] to [mr.ric]
(Wed Apr 15 14:19:47:922216 2015) [sssd[be[mr.ric]]] [be_pam_handler]
(0x0100): Got request with the following data
(Wed Apr 15 14:19:47:922225 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): command: PAM_OPEN_SESSION
(Wed Apr 15 14:19:47:922233 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): domain: mr.ric
(Wed Apr 15 14:19:47:922241 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): user: qchang
(Wed Apr 15 14:19:47:922249 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): service: sshd
(Wed Apr 15 14:19:47:922257 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): tty: ssh
(Wed Apr 15 14:19:47:922265 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): ruser:
(Wed Apr 15 14:19:47:922273 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): rhost: 172.25.12.157
(Wed Apr 15 14:19:47:922281 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): authtok type: 0
(Wed Apr 15 14:19:47:922289 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): newauthtok type: 0
(Wed Apr 15 14:19:47:922297 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): priv: 1
(Wed Apr 15 14:19:47:922305 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): cli_pid: 28330
(Wed Apr 15 14:19:47:922313 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): logon name: not set
(Wed Apr 15 14:19:47:922321 2015) [sssd[be[mr.ric]]] [be_pam_handler]
(0x0100): Sending result [0][mr.ric]
(Wed Apr 15 14:19:47:926678 2015) [sssd[be[mr.ric]]] [be_req_set_domain]
(0x0400): Changing request domain from [mr.ric] to [mr.ric]
(Wed Apr 15 14:19:47:926712 2015) [sssd[be[mr.ric]]] [be_pam_handler]
(0x0100): Got request with the following data
(Wed Apr 15 14:19:47:926746 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): command: PAM_SETCRED
(Wed Apr 15 14:19:47:926757 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): domain: mr.ric
(Wed Apr 15 14:19:47:926765 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): user: qchang
(Wed Apr 15 14:19:47:926773 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): service: sshd
(Wed Apr 15 14:19:47:926781 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): tty: ssh
(Wed Apr 15 14:19:47:926788 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): ruser:
(Wed Apr 15 14:19:47:926796 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): rhost: 172.25.12.157
(Wed Apr 15 14:19:47:926804 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): authtok type: 0
(Wed Apr 15 14:19:47:926812 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): newauthtok type: 0
(Wed Apr 15 14:19:47:926820 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): priv: 0
(Wed Apr 15 14:19:47:926827 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): cli_pid: 28339
(Wed Apr 15 14:19:47:926835 2015) [sssd[be[mr.ric]]] [pam_print_data]
(0x0100): logon name: not set
(Wed Apr 15 14:19:47:926843 2015) [sssd[be[mr.ric]]] [be_pam_handler]
(0x0100): Sending result [0][mr.ric]
-----
On (15/04/15 10:37), tmpchq wrote:
> It was my mistake, I missed [domain] section. Below is at log level 6:
>
> It spent time on checking for SELinux mapping, avahi and polkitd.
SELinux mapping should not be checked if you set "selinux_provider=none"
Some patches which improve speed caused by SELinux integration in ipa provider
were pushed to upstream.
You can test with snapshot of 1.12 branch
https://copr.fedoraproject.org/coprs/lslebodn/sssd-1-12-latest/
The initgroups was called for avahi and polkitd.
It cannot be filtered out with options filter_users, filter_groups
but it should not take a long time unless there is a problem with network.
It would be good to add add microseconds to the timestamp.
add "debug_microseconds = true" to domain section.
LS
_______________________________________________
sssd-users mailing list
sssd-users(a)lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-users