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:
(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
(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?