[SSSD-users] Re: Intermittent issues with SSH access possibly due to the HBAC rules error

Sat, 20 Oct 2018 15:02:20 -0700 

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.


--
Cheers,
Tom K.
-------------------------------------------------------------------------------------

Living on earth is expensive, but it includes a free trip around the sun.



On 10/19/2018 12:53 PM, Bart  wrote:

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 u...@win.domain.com
(Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR 
#21495: Checking negative cache for [u...@win.domain.com]
(Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR 
#21495: [u...@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 [u...@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:u...@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=u...@win.domain.com:-]
(Fri Oct 19 15:21:38 2018) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): 
Entering request [0x4158f0:3:u...@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 [u...@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 [u...@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:u...@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 u...@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: 
u...@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=u...@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): [u...@win.domain.com].
(...)
(Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_get_user_done] 
(0x0400): [rule_watcher_developm...@win.domain.com].
(Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_get_user_done] 
(0x0400): [rule_admin_developm...@win.domain.com].
(...)
(Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sysdb_set_entry_attr] 
(0x0200): Entry [name=u...@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=u...@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 [u...@win.domain.com] 
to group [name=u...@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=u...@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: u...@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 [u...@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 
[u...@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 
[u...@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 [u...@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_developm...@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_developm...@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?
_______________________________________________
sssd-users mailing list -- sssd-users@lists.fedorahosted.org
To unsubscribe send an email to sssd-users-le...@lists.fedorahosted.org
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/sssd-users@lists.fedorahosted.org


_______________________________________________
sssd-users mailing list -- sssd-users@lists.fedorahosted.org
To unsubscribe send an email to sssd-users-le...@lists.fedorahosted.org
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/sssd-users@lists.fedorahosted.org






















					Reply via email to