Hi all,
I have freeipa setup with 2 replicas and a trust relationship with AD.
Occasionally,for periods of time usually less than half an hour all or a subset of my FreeIPA clients are not available via SSH. For the record, I use SSH keys and no password authentication. During these downtimes when I access them via local account I can see that user with his groups is resolved correctly (id, getent passwd). sss_ssh_authorizedkeys returns the correct ssh key. Users in question come from AD, they have ssh keys uploaded to the ID override.
I bumped sssd debug_level to 7.
/var/log/secure contains Permission denied:
Oct 19 17:18:52 hostname sshd[18365]: pam_sss(sshd:account): Access denied for user testuser: 6 (Permission denied) Oct 19 17:18:52 hostname sshd[18366]: fatal: Access denied for user testuser by PAM account configuration
In sssd_pam.log there are entries containing pam_reply called with result [6]: Permission denied.:
Please, consider enabling SELinux in your system. (Fri Oct 19 15:21:38 2018) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe! (Fri Oct 19 15:21:38 2018) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3]. (Fri Oct 19 15:21:38 2018) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3]. (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_cmd_acct_mgmt] (0x0100): entering pam_cmd_acct_mgmt (Fri Oct 19 15:21:38 2018) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'user' matched without domain, user is user (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_ACCT_MGMT (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): domain: not set (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): user: user (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): rhost: 172.16.40.159 (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 19055 (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): logon name: user (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_send] (0x0400): CR #21495: New request 'Initgroups by name' (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_process_input] (0x0400): CR #21495: Parsing input name [user] (Fri Oct 19 15:21:38 2018) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'user' matched without domain, user is user (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_set_name] (0x0400): CR #21495: Setting name [user] (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #21495: Performing a multi-domain search (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #21495: Search will bypass the cache and check the data provider (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #21495: Using domain [win.domain.com] (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #21495: Preparing input data for domain [win.domain.com] rules (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_send] (0x0400): CR #21495: Looking up user@win.domain.com (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #21495: Checking negative cache for [user@win.domain.com] (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #21495: [user@win.domain.com] is not present in negative cache (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #21495: Looking up [user@win.domain.com] in data provider (Fri Oct 19 15:21:38 2018) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4158f0:3:user@win.domain.com@win.domain.com] (Fri Oct 19 15:21:38 2018) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request for [win.domain.com][0x3][BE_REQ_INITGROUPS][name=user@win.domain.com:-] (Fri Oct 19 15:21:38 2018) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x4158f0:3:user@win.domain.com@win.domain.com] (Fri Oct 19 15:21:38 2018) [sssd[pam]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #21495: Looking up [user@win.domain.com] in cache (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400): CR #21495: This request type does not support filtering result by negative cache (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_done] (0x0400): CR #21495: Returning updated object [user@win.domain.com] (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #21495: Found 239 entries in domain win.domain.com (Fri Oct 19 15:21:38 2018) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x4158f0:3:user@win.domain.com@win.domain.com] (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_done] (0x0400): CR #21495: Finished: Success (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is user@win.domain.com (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data: (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_ACCT_MGMT (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): domain: win.domain.com (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): user: user@win.domain.com (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): rhost: 172.16.40.159 (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 19055 (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_print_data] (0x0100): logon name: user (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0 (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [6 (Permission denied)][win.domain.com] (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [6]: Permission denied. (Fri Oct 19 15:21:38 2018) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_reply] (0x0200): blen: 28 (Fri Oct 19 15:21:38 2018) [sssd[pam]] [client_recv] (0x0200): Client disconnected! (Fri Oct 19 15:21:49 2018) [sssd[pam]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available].
Inside of sssd_linux.domain.com.log there are corresponding entries (ellipsized):
(Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=user@win.domain.com] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_attach_req] (0x0400): DP Request [Initgroups #23562]: New request. Flags [0x0001]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=user))][cn=Default Trust View,cn=views,cn=accounts,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_get_acct_info_send] (0x0400): Sending request_type: [REQ_FULL_WITH_MEMBERS] for trust user [user] to IPA server (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_exop_send] (0x0400): Executing extended operation (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_exop_done] (0x0400): ldap_extended_operation result: Success(0), (null). (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_get_user_done] (0x0400): Received [239] groups in group list from IPA Server (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_get_user_done] (0x0400): [user@win.domain.com]. (...) (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_get_user_done] (0x0400): [rule_watcher_development@win.domain.com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_get_user_done] (0x0400): [rule_admin_development@win.domain.com]. (...) (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=user@win.domain.com,cn=users,cn=win.domain.com,cn=sysdb] has set [ts_cache] attrs. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sysdb_mod_group_member] (0x0080): ldb_modify failed: [Attribute or value exists](20)[attribute 'member': value #0 on 'name=user@win.domain.com,cn=users,cn=win.domain.com,cn=sysdb' already exists] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sysdb_mod_group_member] (0x0400): Error: 17 (File exists) (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sysdb_update_members_ex] (0x0020): Could not add member [user@win.domain.com] to group [name=user@win.domain.com,cn=users,cn=win.domain.com,cn=sysdb]. Skipping. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_req_done] (0x0400): DP Request [Initgroups #23562]: Request handler finished [0]: Success (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #23562]: Receiving request data. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_req_initgr_pp_nss_notify] (0x0400): Ordering NSS responder to update memory cache (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #23562]: Finished. Success. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_req_reply_std] (0x1000): DP Request [Initgroups #23562]: Returning [Success]: 0,0,Success (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::win.domain.com:name=user@win.domain.com] from reply table (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #23562]: Request removed. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [pam_print_data] (0x0100): command: SSS_PAM_ACCT_MGMT (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [pam_print_data] (0x0100): domain: win.domain.com (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [pam_print_data] (0x0100): user: user@win.domain.com (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [pam_print_data] (0x0100): service: sshd (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [pam_print_data] (0x0100): tty: ssh (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [pam_print_data] (0x0100): ruser: (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [pam_print_data] (0x0100): rhost: 172.16.40.159 (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [pam_print_data] (0x0100): authtok type: 0 (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [pam_print_data] (0x0100): priv: 1 (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [pam_print_data] (0x0100): cli_pid: 19055 (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [pam_print_data] (0x0100): logon name: not set (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_attach_req] (0x0400): DP Request [PAM Account #23563]: New request. Flags [0000]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_access_send] (0x0400): Performing access check for user [user@win.domain.com] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_account_expired_rhds] (0x0400): Performing RHDS access check for user [user@win.domain.com] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_account_expired] (0x0400): IPA access control succeeded, checking AD access control (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_account_expired_ad] (0x0400): Performing AD access check for user [user@win.domain.com] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaHost)(fqdn=hostname.linux.com))][cn=accounts,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [fqdn] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [serverHostname] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSshPubKey] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUniqueID] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [fqdn=hostname.linux.com,cn=computers,cn=accounts,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_x_deref_search_send] (0x0400): Dereferencing entry [fqdn=hostname.linux.com,cn=computers,cn=accounts,dc=linux,dc=domain,dc=com] using OpenLDAP deref (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_send] (0x0400): WARNING: Disabling paging because scope is set to base. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no filter][fqdn=hostname.linux.com,cn=computers,cn=accounts,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUniqueID] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_x_deref_parse_entry] (0x0400): Got deref control (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_deref] (0x1000): Dereferenced DN: cn=service_development,cn=hostgroups,cn=accounts,dc=linux,dc=domain,dc=com (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_deref] (0x1000): Dereferenced DN: cn=service_development,cn=ng,cn=alt,dc=linux,dc=domain,dc=com (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_deref] (0x1000): Dereferenced DN: ipaUniqueID=600c5bb8-9640-11e8-97b4-02699e009f10,cn=hbac,dc=linux,dc=domain,dc=com (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_deref] (0x1000): Dereferenced DN: ipaUniqueID=63673c38-9640-11e8-b757-02699e009f10,cn=hbac,dc=linux,dc=domain,dc=com (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_deref] (0x1000): Dereferenced DN: ipaUniqueID=a72ca9bc-9640-11e8-b757-02699e009f10,cn=sudorules,cn=sudo,dc=linux,dc=domain,dc=com (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_x_deref_parse_entry] (0x0400): All deref results from a single control parsed (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_hostgroup_info_done] (0x0200): Dereferenced host group: service_development (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_hbac_service_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=linux,dc=domain,dc=com][2][(objectClass=ipaHBACService)] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectClass=ipaHBACService)][cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectclass] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipauniqueid] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [member] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=sshd,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=ftp,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=su,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=login,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=su-l,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=sudo,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=sudo-i,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=gdm,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=gdm-password,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=kdm,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=crond,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=vsftpd,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=proftpd,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=pure-ftpd,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=gssftp,cn=hbacservices,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_hbac_servicegroup_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=linux,dc=domain,dc=com][2][(objectClass=ipaHBACServiceGroup)] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectClass=ipaHBACServiceGroup)][cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectclass] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipauniqueid] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [member] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=Sudo,cn=hbacservicegroups,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=ftp,cn=hbacservicegroups,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_hbac_rule_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=linux,dc=domain,dc=com][2][(&(objectclass=ipaHBACRule)(ipaenabledflag=TRUE)(accessRuleType=allow)(|(hostCategory=all)(memberHost=fqdn=hostname.linux.com,cn=computers,cn=accounts,dc=linux,dc=domain,dc=com)(memberHost=cn=service_development,cn=hostgroups,cn=accounts,dc=linux,dc=domain,dc=com)(memberHost=cn=service_development,cn=ng,cn=alt,dc=linux,dc=domain,dc=com)(memberHost=ipaUniqueID=600c5bb8-9640-11e8-97b4-02699e009f10,cn=hbac,dc=linux,dc=domain,dc=com)(memberHost=ipaUniqueID=63673c38-9640-11e8-b757-02699e009f10,cn=hbac,dc=linux,dc=domain,dc=com)(memberHost=ipaUniqueID=a72ca9bc-9640-11e8-b757-02699e009f10,cn=sudorules,cn=sudo,dc=linux,dc=domain,dc=com)))] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectclass=ipaHBACRule)(ipaenabledflag=TRUE)(accessRuleType=allow)(|(hostCategory=all)(memberHost=fqdn=hostname.linux.com,cn=computers,cn=accounts,dc=linux,dc=domain,dc=com)(memberHost=cn=service_development,cn=hostgroups,cn=accounts,dc=linux,dc=domain,dc=com)(memberHost=cn=service_development,cn=ng,cn=alt,dc=linux,dc=domain,dc=com)(memberHost=ipaUniqueID=600c5bb8-9640-11e8-97b4-02699e009f10,cn=hbac,dc=linux,dc=domain,dc=com)(memberHost=ipaUniqueID=63673c38-9640-11e8-b757-02699e009f10,cn=hbac,dc=linux,dc=domain,dc=com)(memberHost=ipaUniqueID=a72ca9bc-9640-11e8-b757-02699e009f10,cn=sudorules,cn=sudo,dc=linux,dc=domain,dc=com)))][cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectclass] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipauniqueid] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaenabledflag] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accessRuleType] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberUser] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCategory] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberService] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [serviceCategory] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sourceHost] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sourceHostCategory] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [externalHost] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberHost] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [hostCategory] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [ipaUniqueID=600c5bb8-9640-11e8-97b4-02699e009f10,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [ipaUniqueID=63673c38-9640-11e8-b757-02699e009f10,cn=hbac,dc=linux,dc=domain,dc=com]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_attrs_to_rule] (0x1000): Processing rule [rule_watcher_development_hbac_rule] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_user_attrs_to_rule] (0x1000): Processing users for rule [rule_watcher_development_hbac_rule] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_service_attrs_to_rule] (0x1000): Processing PAM services for rule [rule_watcher_development_hbac_rule] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_thost_attrs_to_rule] (0x1000): Processing target hosts for rule [rule_watcher_development_hbac_rule] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_shost_attrs_to_rule] (0x0400): Processing source hosts for rule [rule_watcher_development_hbac_rule] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_attrs_to_rule] (0x1000): Processing rule [rule_admin_development_hbac_rule] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_user_attrs_to_rule] (0x1000): Processing users for rule [rule_admin_development_hbac_rule] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_service_attrs_to_rule] (0x1000): Processing PAM services for rule [rule_admin_development_hbac_rule] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_thost_attrs_to_rule] (0x1000): Processing target hosts for rule [rule_admin_development_hbac_rule] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_shost_attrs_to_rule] (0x0400): Processing source hosts for rule [rule_admin_development_hbac_rule] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_eval_user_element] (0x1000): [238] groups for [user@win.domain.com] (...) (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_eval_user_element] (0x0200): Skipping non-IPA group name=rule_admin_development@win.domain.com,cn=groups,cn=win.domain.com,cn=sysdb (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_eval_user_element] (0x0200): Skipping non-IPA group name=rule_watcher_development@win.domain.com,cn=groups,cn=win.domain.com,cn=sysdb (...) (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_evaluate] (0x0100): [< hbac_evaluate() (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_evaluate] (0x0100): The rule [rule_watcher_development_hbac_rule] did not match. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_evaluate] (0x0100): The rule [rule_admin_development_hbac_rule] did not match. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_evaluate] (0x0100): hbac_evaluate() >] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_hbac_evaluate_rules] (0x0080): Access denied by HBAC rules (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_req_done] (0x0400): DP Request [PAM Account #23563]: Request handler finished [0]: Success (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Account #23563]: Receiving request data. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Account #23563]: Request removed. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_method_enabled] (0x0400): Target selinux is not configured (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [dp_pam_reply] (0x1000): DP Request [PAM Account #23563]: Sending result [6][win.domain.com]
The thing is that on the server, when I test hbacrule it shows me that this user should be able to acces this client host with either rule_watcher_development_hbac_rule or rule_admin_development_hbac_rule. Moreover, without any reconfiguration, situation seems to come back to normal after a couple of minutes, usually in less than an hour.
sssd version is 1.16.1, ipa version 4.6.4-2.
What could be a reason for this not working?
Hey Bart,
(Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_dp_process_reply]
(0x0200): received: [6 (Permission denied)][win.domain.com]
(Fri Oct 19 15:21:38 2018) [sssd[pam]] [pam_reply] (0x0200):
pam_reply called with result [6]: Permission denied.
I can't see more of your log but I can share with you under what circumstances I got the same errors since your setup seems similar to mine.
I had setup my IPA hosts as authoritative on unix.domain.com. And my Windows AD DC's were authoritative on domain.com. The windows AD servers forwarded to the IPA hosts on unix.domain.com and the IPA servers forward to the AD DC servers on domain.com. Having said that, here are the two scenarios:
1) My domain_realm was missing the the two entries below:
DOMAIN.COM = { kdc = ad.domain.com default_domain = domain.com }
[domain_realm] . . . .domain.com = DOMAIN.COM domain.com = DOMAIN.COM
2) I had setup my IPA hosts as Forward First to the AD DC servers when dealing with domain.com. But that didn't work from hosts under unix.domain.com UNTIL I configured my IPA to Forward Only on domain.com. That also resolved the above two issues. This issue was also followed by the following error in the SSSD logs (I used debug_level = 10).
[-1765328228][Cannot contact any KDC for realm 'DOMAIN.COM'
I also had a delay with things not working for a period of time till I resolved this. It included not being able to login to servers, sudo not working, etc. until a certain amount of time expired.
sssd-users@lists.fedorahosted.org
-
Bart -
TomK