Finn Fysj via FreeIPA-users wrote:
If SSSD doesn't have the rules it can't grant access.
You might try enabling replication debugging on your misbehaving server.
It could tell you what is wrong.
rob
I tried to setup a another test IPA server just to verify. Here I created a dummy user
"test_alice" I added a public key to this user, added a hbac rule:
Rule name: allow_alice
Host category: all
Service category: all
Enabled: True
Users: test_alice
accessruletype: allow
systemctl status sssd
Oct 25 15:18:10
ipa-test.example.com sssd_be[34484]: dereference processing failed :
Invalid argument
systemctl status sshd
Oct 25 15:18:10
ipa-test.example.com sshd[34496]: pam_sss(sshd:account): Access denied for
user test_alice: 4 (System error)
Oct 25 15:18:10
ipa-test.example.com sshd[34496]: fatal: Access denied for user test_alice
by PAM account configuration [preauth]
/var/log/sssd/sssd_example.com.log
(2023-10-25 15:18:10): [be[example.com]] [ldb] (0x10000): [RID#4] commit ldb transaction
(nesting: 0)
(2023-10-25 15:18:10): [be[example.com]] [sysdb_set_entry_attr] (0x0200): [RID#4] Entry
[name=test_alice(a)example.com,cn=users,cn=example.com,cn=sysdb] has set [ts_cache] attrs.
(2023-10-25 15:18:10): [be[example.com]] [dp_get_account_info_initgroups_resolv_done]
(0x0400): [RID#4] Ordering NSS responder to update memory cache
(2023-10-25 15:18:10): [be[example.com]] [sdap_process_result] (0x2000): Trace:
sh[0x5632f31d8560], connected[1], ops[(nil)], ldap[0x5632f31da1c0]
(2023-10-25 15:18:10): [be[example.com]] [sdap_process_result] (0x2000): Trace: end of
ldap_result list
(2023-10-25 15:18:10): [be[example.com]] [sbus_dispatch] (0x4000): Dispatching.
(2023-10-25 15:18:10): [be[example.com]] [sbus_dispatch] (0x4000): Dispatching.
(2023-10-25 15:18:10): [be[example.com]] [sbus_method_handler] (0x2000): Received D-Bus
method org.freedesktop.DBus.GetConnectionUnixUser on /org/freedesktop/DBus
(2023-10-25 15:18:10): [be[example.com]] [sbus_issue_request_done] (0x0400):
org.freedesktop.DBus.GetConnectionUnixUser: Success
(2023-10-25 15:18:10): [be[example.com]] [sbus_dispatch] (0x4000): Dispatching.
(2023-10-25 15:18:10): [be[example.com]] [sbus_dispatch] (0x4000): Dispatching.
(2023-10-25 15:18:10): [be[example.com]] [dp_req_reply_std] (0x1000): [RID#4] DP Request
[Initgroups #4]: Returning [Success]: 0,0,Success
(2023-10-25 15:18:10): [be[example.com]] [sbus_issue_request_done] (0x0400):
sssd.dataprovider.getAccountInfo: Success
(2023-10-25 15:18:10): [be[example.com]] [sbus_dispatch] (0x4000): Dispatching.
(2023-10-25 15:18:10): [be[example.com]] [sbus_dispatch] (0x4000): Dispatching.
(2023-10-25 15:18:10): [be[example.com]] [sbus_dispatch] (0x4000): Dispatching.
(2023-10-25 15:18:10): [be[example.com]] [sbus_method_handler] (0x2000): Received D-Bus
method sssd.dataprovider.pamHandler on /sssd
(2023-10-25 15:18:10): [be[example.com]] [sbus_senders_lookup] (0x2000): Looking for
identity of sender [sssd.pam]
(2023-10-25 15:18:10): [be[example.com]] [dp_pam_handler_send] (0x0100): Got request with
the following data
(2023-10-25 15:18:10): [be[example.com]] [pam_print_data] (0x0100): command:
SSS_PAM_ACCT_MGMT
(2023-10-25 15:18:10): [be[example.com]] [pam_print_data] (0x0100): domain:
example.com
(2023-10-25 15:18:10): [be[example.com]] [pam_print_data] (0x0100): user:
test_alice(a)example.com
(2023-10-25 15:18:10): [be[example.com]] [pam_print_data] (0x0100): service: sshd
(2023-10-25 15:18:10): [be[example.com]] [pam_print_data] (0x0100): tty: ssh
(2023-10-25 15:18:10): [be[example.com]] [pam_print_data] (0x0100): ruser:
(2023-10-25 15:18:10): [be[example.com]] [pam_print_data] (0x0100): rhost: 192.168.10.66
(2023-10-25 15:18:10): [be[example.com]] [pam_print_data] (0x0100): authtok type: 0 (No
authentication token available)
(2023-10-25 15:18:10): [be[example.com]] [pam_print_data] (0x0100): newauthtok type: 0 (No
authentication token available)
(2023-10-25 15:18:10): [be[example.com]] [pam_print_data] (0x0100): priv: 1
(2023-10-25 15:18:10): [be[example.com]] [pam_print_data] (0x0100): cli_pid: 34496
(2023-10-25 15:18:10): [be[example.com]] [pam_print_data] (0x0100): child_pid: 0
(2023-10-25 15:18:10): [be[example.com]] [pam_print_data] (0x0100): logon name: not set
(2023-10-25 15:18:10): [be[example.com]] [pam_print_data] (0x0100): flags: 0
(2023-10-25 15:18:10): [be[example.com]] [dp_attach_req] (0x0400): [RID#5] DP Request [PAM
Account #5]: REQ_TRACE: New request. [sssd.pam CID #1] Flags [0000].
(2023-10-25 15:18:10): [be[example.com]] [dp_attach_req] (0x0400): [RID#5] Number of
active DP request: 1
(2023-10-25 15:18:10): [be[example.com]] [sss_domain_get_state] (0x1000): [RID#5] Domain
example.com is Active
(2023-10-25 15:18:10): [be[example.com]] [sdap_access_send] (0x0400): [RID#5] Performing
access check for user [test_alice(a)example.com]
(2023-10-25 15:18:10): [be[example.com]] [ldb] (0x10000): [RID#5] Added timed event
"ldb_kv_callback": 0x5632f31b7100
(2023-10-25 15:18:10): [be[example.com]] [ldb] (0x10000): [RID#5] Added timed event
"ldb_kv_timeout": 0x5632f3202bf0
(2023-10-25 15:18:10): [be[example.com]] [ldb] (0x10000): [RID#5] Running timer event
0x5632f31b7100 "ldb_kv_callback"
(2023-10-25 15:18:10): [be[example.com]] [ldb] (0x10000): [RID#5] Destroying timer event
0x5632f3202bf0 "ldb_kv_timeout"
(2023-10-25 15:18:10): [be[example.com]] [ldb] (0x10000): [RID#5] Destroying timer event
0x5632f31b7100 "ldb_kv_callback"
(2023-10-25 15:18:10): [be[example.com]] [ldb] (0x10000): [RID#5] Added timed event
"ldb_kv_callback": 0x5632f32579f0
(2023-10-25 15:18:10): [be[example.com]] [ldb] (0x10000): [RID#5] Added timed event
"ldb_kv_timeout": 0x5632f3202bf0
(2023-10-25 15:18:10): [be[example.com]] [ldb] (0x10000): [RID#5] Running timer event
0x5632f32579f0 "ldb_kv_callback"
(2023-10-25 15:18:10): [be[example.com]] [ldb] (0x10000): [RID#5] Destroying timer event
0x5632f3202bf0 "ldb_kv_timeout"
(2023-10-25 15:18:10): [be[example.com]] [ldb] (0x10000): [RID#5] Destroying timer event
0x5632f32579f0 "ldb_kv_callback"
(2023-10-25 15:18:10): [be[example.com]] [sdap_account_expired_rhds] (0x0400): [RID#5]
Performing RHDS access check for user [test_alice(a)example.com]
(2023-10-25 15:18:10): [be[example.com]] [sdap_account_expired_rhds] (0x4000): [RID#5]
Account for user [test_alice(a)example.com] is not locked.
(2023-10-25 15:18:10): [be[example.com]] [sdap_account_expired] (0x0400): [RID#5] IPA
access control succeeded, checking AD access control
(2023-10-25 15:18:10): [be[example.com]] [sdap_account_expired_ad] (0x0400): [RID#5]
Performing AD access check for user [test_alice(a)example.com]
(2023-10-25 15:18:10): [be[example.com]] [sdap_account_expired_ad] (0x4000): [RID#5] User
account control for user [test_alice(a)example.com] is [0].
(2023-10-25 15:18:10): [be[example.com]] [sdap_account_expired_ad] (0x4000): [RID#5]
Expiration time for user [test_alice(a)example.com] is [0].
(2023-10-25 15:18:10): [be[example.com]] [ipa_fetch_hbac_send] (0x4000): [RID#5]
Connection status is [online].
(2023-10-25 15:18:10): [be[example.com]] [sdap_id_op_connect_step] (0x4000): [RID#5]
reusing cached connection
(2023-10-25 15:18:10): [be[example.com]] [sdap_id_conn_data_not_idle] (0x4000): [RID#5]
Marking connection as not idle
(2023-10-25 15:18:10): [be[example.com]] [sdap_print_server] (0x2000): [RID#5] Searching
10.141.4.21:389
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_step] (0x0400): [RID#5]
calling ldap_search_ext with
[(&(objectClass=ipaHost)(fqdn=ipa-test.example.com))][cn=accounts,dc=example,dc=com].
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5]
Requesting attrs: [objectClass]
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5]
Requesting attrs: [cn]
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5]
Requesting attrs: [fqdn]
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5]
Requesting attrs: [serverHostname]
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5]
Requesting attrs: [memberOf]
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5]
Requesting attrs: [ipaSshPubKey]
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5]
Requesting attrs: [ipaUniqueID]
(2023-10-25 15:18:10): [be[example.com]] [sdap_op_add] (0x2000): [RID#5] New operation 18
timeout 60
(2023-10-25 15:18:10): [be[example.com]] [sdap_process_result] (0x2000): Trace:
sh[0x5632f31d8560], connected[1], ops[0x5632f312ec50], ldap[0x5632f31da1c0]
(2023-10-25 15:18:10): [be[example.com]] [sdap_process_message] (0x4000): [RID#5] Message
type: [LDAP_RES_SEARCH_ENTRY]
(2023-10-25 15:18:10): [be[example.com]] [sdap_call_op_callback] (0x20000): [RID#5]
Handling LDAP operation [18][server: [10.141.4.21:389] filter:
[(&(objectClass=ipaHost)(fqdn=ipa-test.example.com))] base:
[cn=accounts,dc=example,dc=com]] took [0.412] milliseconds.
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_entry] (0x1000): [RID#5] OriginalDN:
[fqdn=ipa-test.example.com,cn=computers,cn=accounts,dc=example,dc=com].
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_range] (0x2000): [RID#5] No
sub-attributes for [objectClass]
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_range] (0x2000): [RID#5] No
sub-attributes for [cn]
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_range] (0x2000): [RID#5] No
sub-attributes for [fqdn]
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_range] (0x2000): [RID#5] No
sub-attributes for [serverHostname]
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_range] (0x2000): [RID#5] No
sub-attributes for [memberOf]
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_range] (0x2000): [RID#5] No
sub-attributes for [ipaSshPubKey]
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_range] (0x2000): [RID#5] No
sub-attributes for [ipaUniqueID]
(2023-10-25 15:18:10): [be[example.com]] [sdap_process_result] (0x2000): Trace:
sh[0x5632f31d8560], connected[1], ops[0x5632f312ec50], ldap[0x5632f31da1c0]
(2023-10-25 15:18:10): [be[example.com]] [sdap_process_message] (0x4000): [RID#5] Message
type: [LDAP_RES_SEARCH_RESULT]
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_op_finished] (0x0400): [RID#5]
Search result: Success(0), no errmsg set
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_op_finished] (0x2000): [RID#5]
Total count [0]
(2023-10-25 15:18:10): [be[example.com]] [sdap_op_destructor] (0x2000): [RID#5] Operation
18 finished
(2023-10-25 15:18:10): [be[example.com]] [sdap_has_deref_support_ex] (0x0400): [RID#5] The
server supports deref method OpenLDAP
(2023-10-25 15:18:10): [be[example.com]] [sdap_deref_search_send] (0x2000): [RID#5] Server
supports OpenLDAP deref
(2023-10-25 15:18:10): [be[example.com]] [sdap_x_deref_search_send] (0x0400): [RID#5]
Dereferencing entry [fqdn=ipa-test.example.com,cn=computers,cn=accounts,dc=example,dc=com]
using OpenLDAP deref
(2023-10-25 15:18:10): [be[example.com]] [sdap_print_server] (0x2000): [RID#5] Searching
10.141.4.21:389
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_send] (0x0400): [RID#5]
WARNING: Disabling paging because scope is set to base.
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_step] (0x0400): [RID#5]
calling ldap_search_ext with [no
filter][fqdn=ipa-test.example.com,cn=computers,cn=accounts,dc=example,dc=com].
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5]
Requesting attrs: [objectClass]
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5]
Requesting attrs: [cn]
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5]
Requesting attrs: [memberOf]
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5]
Requesting attrs: [ipaUniqueID]
(2023-10-25 15:18:10): [be[example.com]] [sdap_get_generic_ext_step] (0x2000): [RID#5]
ldap_search_ext called, msgid = 19
(2023-10-25 15:18:10): [be[example.com]] [sdap_op_add] (0x2000): [RID#5] New operation 19
timeout 60
(2023-10-25 15:18:10): [be[example.com]] [sdap_process_result] (0x2000): Trace:
sh[0x5632f31d8560], connected[1], ops[0x5632f312ec50], ldap[0x5632f31da1c0]
(2023-10-25 15:18:10): [be[example.com]] [sdap_process_result] (0x2000): Trace: end of
ldap_result list
(2023-10-25 15:18:10): [be[example.com]] [sdap_process_result] (0x2000): Trace:
sh[0x5632f31d8560], connected[1], ops[0x5632f312ec50], ldap[0x5632f31da1c0]
(2023-10-25 15:18:10): [be[example.com]] [sdap_process_message] (0x4000): [RID#5] Message
type: [LDAP_RES_SEARCH_ENTRY]
(2023-10-25 15:18:10): [be[example.com]] [sdap_call_op_callback] (0x20000): [RID#5]
Handling LDAP operation [19][server: [10.141.4.21:389] filter: [(null)] base:
[fqdn=ipa-test.example.com,cn=computers,cn=accounts,dc=example,dc=com]] took [1.636]
milliseconds.
(2023-10-25 15:18:10): [be[example.com]] [sdap_x_deref_parse_entry] (0x0400): [RID#5] Got
deref control
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x1000): [RID#5] Dereferenced
DN: cn=ipaservers,cn=hostgroups,cn=accounts,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
objectClass value: top
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
objectClass value: groupOfNames
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
objectClass value: nestedGroup
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
objectClass value: ipaobject
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
objectClass value: ipahostgroup
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Found map
for objectclass 'ipahostgroup'
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x2000): [RID#5] Dereferenced
attribute: objectClass
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x2000): [RID#5] Dereferenced
attribute: cn
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: ipaservers
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x2000): [RID#5] Dereferenced
attribute: memberOf
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: cn=Replication Administrators,cn=privileges,cn=pbac,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: cn=Add Replication Agreements,cn=permissions,cn=pbac,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: cn=Modify Replication
Agreements,cn=permissions,cn=pbac,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: cn=Read Replication Agreements,cn=permissions,cn=pbac,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: cn=Remove Replication
Agreements,cn=permissions,cn=pbac,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: cn=Modify DNA Range,cn=permissions,cn=pbac,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: cn=Read PassSync Managers
Configuration,cn=permissions,cn=pbac,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: cn=Read Replication Changelog
Configuration,cn=permissions,cn=pbac,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: cn=Write Replication Changelog
Configuration,cn=permissions,cn=pbac,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: cn=Modify PassSync Managers
Configuration,cn=permissions,cn=pbac,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: cn=Read LDBM Database
Configuration,cn=permissions,cn=pbac,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: cn=Add Configuration
Sub-Entries,cn=permissions,cn=pbac,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: cn=Read DNA Range,cn=permissions,cn=pbac,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x2000): [RID#5] Dereferenced
attribute: ipaUniqueID
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x4000): [RID#5] Dereferenced
attribute value: d2694b3c-7347-11ee-bd25-000017024d7a
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x1000): [RID#5] Dereferenced
DN: cn=Replication Administrators,cn=privileges,cn=pbac,dc=example,dc=com
(2023-10-25 15:18:10): [be[example.com]] [sdap_parse_deref] (0x0020): [RID#5] Unknown
entry type, no objectClasses found!
(2023-10-25 15:18:10): [be[example.com]] [sdap_x_deref_parse_entry] (0x0040): [RID#5]
sdap_parse_deref failed [22]: Invalid argument
Is it considered a practice to always restart sssd when a HBAC rule is added and to empty
the cache?