[SSSD-users] ldap_access_filter ignored for some users

[Sajesh Singh]

CentOS 7.8
SSSD 1.16.4

Having a strange issue where the ldap_access_filter seems to be applied to some users and
not others when they are both logging into the same application that is using the
underlying OS PAM configuration. Below are the excerpts from the logs:

USERA log entires:
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sdap_get_primary_name] (0x0400):
Processing object USERA
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Processing user
USERA@default
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Original
memberOf is not available for [USERA@default].
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): User principal
is not available for [USERA@default].
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Storing info for
user USERA@default
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=USERA@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(memberuid=USERA)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=DOMAIN,dc=SUFFIX].
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=USERA@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [dp_table_value_destructor] (0x0400):
Removing [0:1:0x0001:3::default:name=USERA@default] from reply table
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
USERA@default
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sdap_access_send] (0x0400): Performing
access check for user [USERA@default]
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sdap_access_filter_send] (0x0400):
Performing access filter check for user [USERA@default]
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(uid=USERA)(objectclass=posixAccount)(objectClass=posixAccount)(accountActive=TRUE)(|(allowedService=unixAdmin)(allowedService=USERA)(allowedService=USERAAdmin)))][uid=USERA,ou=posixAccounts,ou=Apps,dc=DOMAIN,dc=SUFFIX].
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=USERA@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
USERA@default
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [dp_get_account_info_handler] (0x0200): Got
request for [0x2][BE_REQ_GROUP][name=USERAadmin@default]
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(cn=USERAadmin)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=DOMAIN,dc=SUFFIX].
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sdap_get_primary_name] (0x0400):
Processing object USERAadmin
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sdap_save_group] (0x0400): Processing
group USERAadmin@default
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [sdap_save_group] (0x0400): Storing info
for group USERAadmin@default
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [dp_table_value_destructor] (0x0400):
Removing [0:1:0x0001:2::default:name=USERAadmin@default] from reply table
(Fri May 15 12:35:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
USERA@default
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [dp_get_account_info_handler] (0x0200): Got
request for [0x3][BE_REQ_INITGROUPS][name=USERA@default]
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(uid=USERA)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][dc=DOMAIN,dc=SUFFIX].
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [sdap_get_primary_name] (0x0400):
Processing object USERA
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Processing user
USERA@default
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Original
memberOf is not available for [USERA@default].
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): User principal
is not available for [USERA@default].
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Storing info for
user USERA@default
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=USERA@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(memberuid=USERA)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=DOMAIN,dc=SUFFIX].
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=USERA@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [dp_table_value_destructor] (0x0400):
Removing [0:1:0x0001:3::default:name=USERA@default] from reply table
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
USERA@default
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [sdap_access_send] (0x0400): Performing
access check for user [USERA@default]
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [sdap_access_filter_send] (0x0400):
Performing access filter check for user [USERA@default]
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(uid=USERA)(objectclass=posixAccount)(objectClass=posixAccount)(accountActive=TRUE)(|(allowedService=unixAdmin)(allowedService=USERA)(allowedService=USERAAdmin)))][uid=USERA,ou=posixAccounts,ou=Apps,dc=DOMAIN,dc=SUFFIX].
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=USERA@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
USERA@default
(Fri May 15 12:40:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
USERA@default
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [dp_get_account_info_handler] (0x0200): Got
request for [0x3][BE_REQ_INITGROUPS][name=USERA@default]
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(uid=USERA)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][dc=DOMAIN,dc=SUFFIX].
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [sdap_get_primary_name] (0x0400):
Processing object USERA
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Processing user
USERA@default
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Original
memberOf is not available for [USERA@default].
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): User principal
is not available for [USERA@default].
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Storing info for
user USERA@default
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=USERA@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(memberuid=USERA)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=DOMAIN,dc=SUFFIX].
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=USERA@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [dp_table_value_destructor] (0x0400):
Removing [0:1:0x0001:3::default:name=USERA@default] from reply table
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
USERA@default
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [sdap_access_send] (0x0400): Performing
access check for user [USERA@default]
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [sdap_access_filter_send] (0x0400):
Performing access filter check for user [USERA@default]
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(uid=USERA)(objectclass=posixAccount)(objectClass=posixAccount)(accountActive=TRUE)(|(allowedService=unixAdmin)(allowedService=USERA)(allowedService=USERAAdmin)))][uid=USERA,ou=posixAccounts,ou=Apps,dc=DOMAIN,dc=SUFFIX].
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=USERA@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
USERA@default
(Fri May 15 12:45:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
USERA@default
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [dp_get_account_info_handler] (0x0200): Got
request for [0x3][BE_REQ_INITGROUPS][name=USERA@default]
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(uid=USERA)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][dc=DOMAIN,dc=SUFFIX].
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [sdap_get_primary_name] (0x0400):
Processing object USERA
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Processing user
USERA@default
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Original
memberOf is not available for [USERA@default].
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): User principal
is not available for [USERA@default].
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Storing info for
user USERA@default
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=USERA@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(memberuid=USERA)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=DOMAIN,dc=SUFFIX].
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=USERA@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [dp_table_value_destructor] (0x0400):
Removing [0:1:0x0001:3::default:name=USERA@default] from reply table
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
USERA@default
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [sdap_access_send] (0x0400): Performing
access check for user [USERA@default]
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [sdap_access_filter_send] (0x0400):
Performing access filter check for user [USERA@default]
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(uid=USERA)(objectclass=ObjectClassA)(objectClass=ObjectClassB)(AttributeA=TRUE)(|(AttributeB=ServiceC)(AttributeC=ServiceA)(AttributeC=ServiceB)))][uid=USERA,ou=OUA,ou=OUB,dc=DOMAIN,dc=SUFFIX].
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=USERA@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 12:50:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
USERA@default
(Fri May 15 12:50:02 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
USERA@default


USERB log entries:

(Fri May 15 10:35:01 2020) [sssd[be[default]]] [sdap_get_primary_name] (0x0400):
Processing object emu
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Processing user
emu@default
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Original
memberOf is not available for [emu@default].
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): User principal
is not available for [emu@default].
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Storing info for
user emu@default
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=emu@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(memberuid=emu)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=DOMAIN,dc=SUFFIX].
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=emu@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [dp_table_value_destructor] (0x0400):
Removing [0:1:0x0001:3::default:name=emu@default] from reply table
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
emu@default
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [sdap_access_send] (0x0400): Performing
access check for user [emu@default]
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [sdap_access_filter_send] (0x0400):
Performing access filter check for user [emu@default]
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(uid=emu)(objectclass=posixAccount)(objectClass=posixAccount)(accountActive=TRUE)(|(allowedService=unixAdmin)(allowedService=EMU)(allowedService=EMUAdmin)))][uid=emu,ou=posixAccounts,ou=Apps,dc=DOMAIN,dc=SUFFIX].
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=emu@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
emu@default
(Fri May 15 10:35:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
emu@default
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [dp_get_account_info_handler] (0x0200): Got
request for [0x3][BE_REQ_INITGROUPS][name=emu@default]
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(uid=emu)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][dc=DOMAIN,dc=SUFFIX].
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [sdap_get_primary_name] (0x0400):
Processing object emu
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Processing user
emu@default
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Original
memberOf is not available for [emu@default].
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): User principal
is not available for [emu@default].
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Storing info for
user emu@default
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=emu@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(memberuid=emu)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=DOMAIN,dc=SUFFIX].
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=emu@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [dp_table_value_destructor] (0x0400):
Removing [0:1:0x0001:3::default:name=emu@default] from reply table
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
emu@default
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [sdap_access_send] (0x0400): Performing
access check for user [emu@default]
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [sdap_access_filter_send] (0x0400):
Performing access filter check for user [emu@default]
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(uid=emu)(objectclass=posixAccount)(objectClass=posixAccount)(accountActive=TRUE)(|(allowedService=unixAdmin)(allowedService=EMU)(allowedService=EMUAdmin)))][uid=emu,ou=posixAccounts,ou=Apps,dc=DOMAIN,dc=SUFFIX].
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=emu@default,cn=users,cn=default,cn=sysdb] has set [ts_cache] attrs.
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
emu@default
(Fri May 15 10:40:01 2020) [sssd[be[default]]] [pam_print_data] (0x0100): user:
emu@default
(Fri May 15 10:40:10 2020) [sssd[be[default]]] [sdap_get_primary_name] (0x0400):
Processing object emu
(Fri May 15 10:40:10 2020) [sssd[be[default]]] [sdap_save_group] (0x0400): Processing
group emu@default
(Fri May 15 10:40:10 2020) [sssd[be[default]]] [sdap_save_group] (0x0400): Storing info
for group emu@default
(Fri May 15 10:40:53 2020) [sssd[be[default]]] [dp_get_account_info_handler] (0x0200): Got
request for [0x3][BE_REQ_INITGROUPS][name=emu@default]
(Fri May 15 10:40:53 2020) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(uid=emu)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][dc=DOMAIN,dc=SUFFIX].
(Fri May 15 10:40:53 2020) [sssd[be[default]]] [sdap_get_primary_name] (0x0400):
Processing object emu
(Fri May 15 10:40:53 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Processing user
emu@default
(Fri May 15 10:40:53 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): Original
memberOf is not available for [emu@default].
(Fri May 15 10:40:53 2020) [sssd[be[default]]] [sdap_save_user] (0x0400): User principal
is not available for [emu@default].

As you can see from the 2 log excerpts USERB never has the ldap_access_filter check
applied while it is done for USERA. Has anyone encounted this before?

Thank you,

Sajesh