11:53 a.m.
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(a)win.domain.com
(Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #21495:
Checking negative cache for [user(a)win.domain.com]
(Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #21495:
[user(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)win.domain.com].
(...)
(Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_get_user_done] (0x0400):
[rule_watcher_development(a)win.domain.com].
(Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_get_user_done] (0x0400):
[rule_admin_development(a)win.domain.com].
(...)
(Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sysdb_set_entry_attr] (0x0200):
Entry [name=user(a)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(a)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(a)win.domain.com] to group
[name=user(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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?
5:02 p.m.
New subject: Intermittent issues with SSH access possibly due to the HBAC rules error
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 user(a)win.domain.com
(Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #21495:
Checking negative cache for [user(a)win.domain.com]
(Fri Oct 19 15:21:38 2018) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #21495:
[user(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)win.domain.com].
(...)
(Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_get_user_done] (0x0400):
[rule_watcher_development(a)win.domain.com].
(Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [ipa_s2n_get_user_done] (0x0400):
[rule_admin_development(a)win.domain.com].
(...)
(Fri Oct 19 15:21:38 2018) [sssd[be[linux.domain.com]]] [sysdb_set_entry_attr] (0x0200):
Entry [name=user(a)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(a)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(a)win.domain.com] to group
[name=user(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)lists.fedorahosted.org
To unsubscribe send an email to sssd-users-leave(a)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.fedorahoste...
2012
days inactive
2013
days old
sssd-users@lists.fedorahosted.org
1 comments
2 participants
participants (2)
-
Bart -
TomK