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 [email protected] (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #21495: Checking negative cache for [[email protected]] (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #21495: [[email protected]] is not present in negative cache (Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #21495: Looking up [[email protected]] in data provider (Fri Oct 19 15:21:38 2018) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4158f0:3:[email protected]@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][[email protected]:-] (Fri Oct 19 15:21:38 2018) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x4158f0:3:[email protected]@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 [[email protected]] 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 [[email protected]] (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:[email protected]@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 [email protected] (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: [email protected] (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][[email protected]] (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): [[email protected]]. (...) (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_get_user_done] (0x0400): [[email protected]]. (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_get_user_done] (0x0400): [[email protected]]. (...) (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sysdb_set_entry_attr] (0x0200): Entry [[email protected],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 '[email protected],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 [[email protected]] to group [[email protected],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:[email protected]] 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: [email protected] (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 [[email protected]] (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sdap_account_expired_rhds] (0x0400): Performing RHDS access check for user [[email protected]] (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 [[email protected]] (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 [[email protected]] (...) (Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [hbac_eval_user_element] (0x0200): Skipping non-IPA group [email protected],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 [email protected],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? _______________________________________________ sssd-users mailing list -- [email protected] To unsubscribe send an email to [email protected] Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/[email protected]
