GPO Access Control denies access due to incomplete User group SID Resolution on first login

[Schlizor]

Hello,

On RHEL 9, after joining an Active Directory domain using realm join, I configured SSSD (2.9.7) with ad_gpo_access_control = enforcing to use GPOs for granting access. However, access is denied on the first login attempt, even though the user is a member of a group allowed by the GPO (“Allow log on through Remote Interactive”).
On the second login attempt, access succeeds because the group SIDs are fully resolved. This suggests that SID resolution takes too long.

Observed behavior:

On first login, the user SID is resolved, but the group SID list is incomplete (only primary group and a few defaults like “Domain Users”).
As a result, access_granted = 0 and login fails with Host Access Denied.
On second login, the group SID list mostly is complete and access is granted and everything works like intended.

Expected behavior:
SSSD should resolve all relevant group SIDs before enforcing GPO access control, even with performance penalty.

First Login Attempt:

   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9] RESULTANT POLICY:
   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9] gpo_map_type: Remote Interactive
   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9] allowed_size = 2
   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9] allowed_sids[0] = S-1-5-21-1930873976-2164.....
   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9] allowed_sids[1] = S-1-5-21-1930873976-2164.....
   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9] denied_size = 0
   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_get_sids] (0x2000): [RID#9] SID of the primary group with gid '0' is '(null)'
   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9] CURRENT USER:
   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9]        user_sid = S-1-5-21-1930873976-2164.....
   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9]   group_sids[0] = S-1-5-21-1930873976-2164.....
   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9]   group_sids[1] = S-1-5-11
   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9] POLICY DECISION:
   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9]  access_granted = 0
   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9]   access_denied = 0
   *  (2025-11-25 10:34:56): [be[example.com]] [ad_gpo_perform_hbac_processing] (0x0040): [RID#9] GPO access check failed: [1432158236](Host Access Denied)

Second Login Attempt:

(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13] RESULTANT POLICY:
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13] gpo_map_type: Remote Interactive
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13] allowed_size = 2
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13] allowed_sids[0] = S-1-5-21-1930873976-216.....
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13] allowed_sids[1] = S-1-5-21-1930873976-216.....
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13] denied_size = 0
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13] CURRENT USER:
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13]        user_sid = S-1-5-21-1930873976-2164.....
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13]   group_sids[0] = S-1-5-21-1930873976-2164.....
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13]   group_sids[1] = S-1-5-21-1930873976-2164.....
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13]   group_sids[2] = S-1-5-21-1930873976-2164.....
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13]   group_sids[3] = S-1-5-21-1930873976-2164.....
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13]   group_sids[4] = S-1-5-21-1930873976-2164.....
.
.
.
.
.
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13]   group_sids[56] = S-......
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13] POLICY DECISION:
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13]  access_granted = 1
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#13]   access_denied = 0
(2025-11-25 10:35:07): [be[example.com]] [ad_gpo_access_done] (0x0400): [RID#13] GPO-based access control successful.

As you can see there is about 11 Seconds between the login attempts.

Here is my sssd.conf:

[sssd]
config_file_version = 20
services = nss, pam, sudo
domains = example.com

[pam]
offline_credentials_expiration = 14
offline_failed_login_attempts = 3
offline_failed_login_delay = 5

[sudo]

[domain/example.com]
default_shell = /bin/bash

krb5_realm = example.com
krb5_store_password_if_offline = True

cache_credentials = False
enumerate = False
cached_auth_timeout = 0
entry_cache_timeout = 300
refresh_expired_interval = 225

realmd_tags = manages-system joined-with-adcli

fallback_homedir = /home/%u
ad_domain = example.com
ad_server = ad1.example.com
ad_backup_server = ad2.example.com
ad_hostname = XY.example.com
ad_gpo_access_control = enforcing
ad_gpo_cache_timeout = 300
ad_use_ldaps = True

use_fully_qualified_names = False
ldap_id_mapping = True
ldap_sudo_search_base = <working Filter>
ldap_tls_reqcert = demand
ldap_tls_cacert = /etc/ssl/certs/ca-bundle.crt

id_provider = ad
access_provider = ad
auth_provider = ad
chpass_provider = ad
sudo_provider = ad
dyndns_update = False
ad_enable_gc = True
ldap_group_nesting_level = 5

Is there a solution for my problem? I would take a few seconds penalty instead of an instant connection refused message....

Thanks,

Thomas

[sumit-bose]

Hi,

the lookup of the group memberships already happens before the access control evaluation. Would it be possible to send the full log file "sssd_your.domain.log"?

bye,
Sumit

[Schlizor]

Hi Sumit,

while preparing the Log (obfuscating) I noticed something:

When attempting to login:

(2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9] RESULTANT POLICY:
(2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9] gpo_map_type: Remote Interactive
(2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9] allowed_size = 2
(2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9] allowed_sids[0] = S-1-5-21-1930873976-2164.....
(2025-11-25 10:34:56): [be[example.com]] [ad_gpo_access_check] (0x0400): [RID#9] allowed_sids[1] = S-1-5-21-1930873

allowed_sids[0] refers to a group (OU) that is granted Remote Login.
allowed_sids[1] refers to a user who is also granted Remote Login.

If I log in with the user (allowed_sids[1]), the login works as expected.
However, if I try to log in with a user who is a member of the group (allowed_sids[0]), the login fails as previously described.

This suggests that SSSD or the Active Directory environment cannot resolve the user's group membership in time, or there is a delay in processing nested group memberships during the login attempt.

I added you a Log File with Debug Level = 0x400. I tried my best to obfuscate everything without remove important Information.

Thanks,
Thomas

Edit: Removed Log File

[sumit-bose]

Hi,

thank you for the logs. The important part for the group memberships is between:

(2025-11-25 14:34:59): [be[example.com]] [dp_comtach_req] (0x0400): [RID#5] DP Request [Initgroups #5]: REQ_TRACE: New request. [sssd.pam CID #1] Flags [0x0001].

and

(2025-11-25 14:34:59): [be[example.com]] [dp_req_destructor] (0x0400): [RID#5] DP Request [Initgroups #5]: Request removed.

Unfortunately in this logs level I see no reason why only one group is processed. Can you run with debug_level = 9 again? Only Initgroups part of the log is needed.

bye,
Sumit

[Schlizor]

Hey,

here the log of the Initgroups 5 sequence with debug_level = 9. (anonymized, changed SIDs,...)

sssd_example.com_Initgroups5.log

Is there anything we should verify on the Active Directory side, such as permissions?
Could hardened system settings be contributing to the problem?

Thanks,
Thomas

[sumit-bose]

Hi,

thank you for the logs. The important part is

(2025-11-26  7:58:14): [be[example.com]] [sdap_get_generic_ext_step] (0x0400): [RID#5] calling ldap_search_ext with [no filter][CN=<Username>,OU=<OU>,OU=<OU>,OU=<OU>,DC=example,DC=com].
(2025-11-26  7:58:14): [be[example.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5] Requesting attrs: [tokenGroups]
(2025-11-26  7:58:14): [be[example.com]] [sdap_get_generic_ext_step] (0x2000): [RID#5] ldap_search_ext called, msgid = 12
(2025-11-26  7:58:14): [be[example.com]] [sdap_op_add] (0x2000): [RID#5] New operation 12 timeout 6
(2025-11-26  7:58:14): [be[example.com]] [sdap_process_result] (0x2000): Trace: sh[0x55f35de6a860], connected[1], ops[0x55f35e018840], ldap[0x55f35de62c30]
(2025-11-26  7:58:14): [be[example.com]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(2025-11-26  7:58:14): [be[example.com]] [sdap_process_result] (0x2000): Trace: sh[0x55f35de6a860], connected[1], ops[0x55f35e018840], ldap[0x55f35de62c30]
(2025-11-26  7:58:14): [be[example.com]] [sdap_process_message] (0x4000): [RID#5] Message type: [LDAP_RES_SEARCH_ENTRY]
(2025-11-26  7:58:14): [be[example.com]] [sdap_call_op_callback] (0x20000): [RID#5] Handling LDAP operation [12][server: [<AD IP>:636] filter: [(null)] base: [CN=<Username>,OU=<OU>,OU=<OU>,OU=<OU>,DC=example,DC=
com]] took [1.257] milliseconds.
(2025-11-26  7:58:14): [be[example.com]] [sdap_parse_entry] (0x1000): [RID#5] OriginalDN: [CN=<Username>,OU=<OU>,OU=<OU>,OU=<OU>,DC=example,DC=com].
(2025-11-26  7:58:14): [be[example.com]] [sdap_parse_entry] (0x1000): [RID#5] Entry has no attributes [0(Success)]!?
(2025-11-26  7:58:14): [be[example.com]] [sdap_process_result] (0x2000): Trace: sh[0x55f35de6a860], connected[1], ops[0x55f35e018840], ldap[0x55f35de62c30]
(2025-11-26  7:58:14): [be[example.com]] [sdap_process_message] (0x4000): [RID#5] Message type: [LDAP_RES_SEARCH_RESULT]
(2025-11-26  7:58:14): [be[example.com]] [sdap_get_generic_op_finished] (0x0400): [RID#5] Search result: Success(0), no errmsg set
(2025-11-26  7:58:14): [be[example.com]] [sdap_op_destructor] (0x2000): [RID#5] Operation 12 finished
(2025-11-26  7:58:14): [be[example.com]] [sdap_get_ad_tokengroups_done] (0x1000): [RID#5] No tokenGroups entries for [<MyUser>@example.com]

The LDAP base search with the user's DN does not return any tokenGroups attribute. Which is surprising because according to the first log the tokenGroups attribute is returned for the host object only about a second later. The tokenGroups attribute lists the SIDs of all groups the object (user or host) is a member of and is used by SSSD's AD provider as default way to lookup group-memberships.

There are permissions on the AD side related to this kind of LDAP searches, but since looking up the group memberships for the user is successful only a few seconds later I currently do not assume an issue with the permissions.

Did you run a second try when running with debug_level = 9? In this case you should see a list of SIDs in the log after the tokenGroups search (in the first logs it is request number 9, RID#1).

You can disable the tokenGroups search and tell SSSD to follow the group hierarchy by following LDAP member attributes by setting ldap_use_tokengroups = False in the [domain/...] section of sssd.conf.

bye,
Sumit

[Schlizor]

Hey,

first of all -> ldap_use_tokengroups = False worked and the first login attempt is now working everytime (also after sssctl cache-remove). Thanks!

However, it is (atleast to me) kind of a strange. I switched back to ldap_use_tokengroup = True and debug_level = 9 to get log data again. Here ist what I got:

First Login Attempt (Failed):

(2025-11-27 13:53:22): [be[example.com]] [sdap_get_generic_ext_step] (0x0400): [RID#2] calling ldap_search_ext with [no filter][CN=<OU>,OU=<OU>,OU=<OU>,OU=Structure,DC=example,DC=com].
(2025-11-27 13:53:22): [be[example.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [tokenGroups]
(2025-11-27 13:53:22): [be[example.com]] [sdap_get_generic_ext_step] (0x2000): [RID#2] ldap_search_ext called, msgid = 8
(2025-11-27 13:53:22): [be[example.com]] [sdap_op_add] (0x2000): [RID#2] New operation 8 timeout 6
(2025-11-27 13:53:22): [be[example.com]] [sdap_process_result] (0x2000): Trace: sh[0x55dc2fba0510], connected[1], ops[0x55dc2fd8fe40], ldap[0x55dc2fba0140]
(2025-11-27 13:53:22): [be[example.com]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(2025-11-27 13:53:22): [be[example.com]] [sdap_process_result] (0x2000): Trace: sh[0x55dc2fba0510], connected[1], ops[0x55dc2fd8fe40], ldap[0x55dc2fba0140]
(2025-11-27 13:53:22): [be[example.com]] [sdap_process_message] (0x4000): [RID#2] Message type: [LDAP_RES_SEARCH_ENTRY]
(2025-11-27 13:53:22): [be[example.com]] [sdap_call_op_callback] (0x20000): [RID#2] Handling LDAP Operation [8][server: [<IP>:636] filter: [(null)] base: [CN=<OU>,OU=<OU>,OU=<OU>,OU=Structure,DC=example,DC=com]] took [1.637] milliseconds.
(2025-11-27 13:53:22): [be[example.com]] [sdap_parse_entry] (0x1000): [RID#2] OriginalDN: [CN=<OU>,OU=<OU>,OU=<OU>,OU=Structure,DC=example,DC=com].
(2025-11-27 13:53:22): [be[example.com]] [sdap_parse_entry] (0x1000): [RID#2] Entry has no attributes [0(Success)]!?
(2025-11-27 13:53:22): [be[example.com]] [sdap_process_result] (0x2000): Trace: sh[0x55dc2fba0510], connected[1], ops[0x55dc2fd8fe40], ldap[0x55dc2fba0140]
(2025-11-27 13:53:22): [be[example.com]] [sdap_process_message] (0x4000): [RID#2] Message type: [LDAP_RES_SEARCH_RESULT]
(2025-11-27 13:53:22): [be[example.com]] [sdap_get_generic_op_finished] (0x0400): [RID#2] Search result: Success(0), no errmsg set

Second Login Attempt (Successfull):

(2025-11-27 13:53:40): [be[example.com]] [sdap_get_generic_ext_step] (0x0400): [RID#13] calling ldap_search_ext with [no filter][CN=<CN>,OU=<OU>,OU=<OU>,OU=<OU>,OU=<OU>,DC=example,DC=com].
(2025-11-27 13:53:40): [be[example.com]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [tokenGroups]
(2025-11-27 13:53:40): [be[example.com]] [sdap_get_generic_ext_step] (0x2000): [RID#13] ldap_search_ext called, msgid = 35
(2025-11-27 13:53:40): [be[example.com]] [sdap_op_add] (0x2000): [RID#13] New operation 35 timeout 6
(2025-11-27 13:53:40): [be[example.com]] [sdap_process_result] (0x2000): Trace: sh[0x55dc2fba0510], connected[1], ops[0x55dc2fe40480], ldap[0x55dc2fba0140]
(2025-11-27 13:53:40): [be[example.com]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(2025-11-27 13:53:40): [be[example.com]] [sdap_process_result] (0x2000): Trace: sh[0x55dc2fba0510], connected[1], ops[0x55dc2fe40480], ldap[0x55dc2fba0140]
(2025-11-27 13:53:40): [be[example.com]] [sdap_process_message] (0x4000): [RID#13] Message type: [LDAP_RES_SEARCH_ENTRY]
(2025-11-27 13:53:40): [be[example.com]] [sdap_call_op_callback] (0x20000): [RID#13] Handling LDAP operation [35][server: [<IP>:636] filter: [(null)] base: [CN=<CN>,OU=<OU>,OU=<OU>,OU=<OU>,OU=<OU>,DC=example,DC=com]] took [1.855] milliseconds.
(2025-11-27 13:53:40): [be[example.com]] [sdap_parse_entry] (0x1000): [RID#13] OriginalDN: [CN=<CN>,OU=<OU>,OU=<OU>,OU=<OU>,OU=<OU>,DC=example,DC=com].
(2025-11-27 13:53:40): [be[example.com]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [tokenGroups]
(2025-11-27 13:53:40): [be[example.com]] [sdap_process_result] (0x2000): Trace: sh[0x55dc2fba0510], connected[1], ops[0x55dc2fe40480], ldap[0x55dc2fba0140]
(2025-11-27 13:53:40): [be[example.com]] [sdap_process_message] (0x4000): [RID#13] Message type: [LDAP_RES_SEARCH_RESULT]
(2025-11-27 13:53:40): [be[example.com]] [sdap_get_generic_op_finished] (0x0400): [RID#13] Search result: Success(0), no errmsg set
(2025-11-27 13:53:40): [be[example.com]] [sdap_op_destructor] (0x2000): [RID#13] Operation 35 finished
(2025-11-27 13:53:40): [be[example.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): [RID#13] Processing membership SID [S-1-5-32-574]
(2025-11-27 13:53:40): [be[example.com]] [sdap_idmap_sid_to_unix] (0x0400): [RID#13] Object SID [S-1-5-32-574] is a built-in one.
(2025-11-27 13:53:40): [be[example.com]] [sdap_ad_save_group_membership_with_idmapping] (0x0400): [RID#13] Skipping built-in object.
(2025-11-27 13:53:40): [be[example.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): [RID#13] Processing membership SID [<SID>]
(2025-11-27 13:53:40): [be[example.com]] [sss_domain_get_stcome] (0x2000): [RID#13] Domain example.com is Active
(2025-11-27 13:53:40): [be[example.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): [RID#13] SID [<SID>] maps to GID [<GID>]
(2025-11-27 13:53:40): [be[example.com]] [sdap_ad_tokengroups_updcome_members] (0x1000): [RID#13] Updating memberships for [<pc>$@example.com]

Thank you very much!

Thomas

[sumit-bose]

Hi,

thank you for verifying that the second tokenGroups attempt really works as expected. It is strange to me as well. I assue the sanitized IP address in the "Handling LDAP operation" line is the same in both cases.

I wonder is this might be related to the use of LDAPS? Would it be possible to check with ad_use_ldaps = False or is the plain LDAP port (389) block for your AD DCs? Even without LDAPS the connection will be encrypted on the SASL/GSSAPI level. Using LDAPS is a bit special because we are still using SASL/GSSAPI for authentication but SSL for encryption which requires channel-binding on the AD side. Not sure if this might case some delays in evaluating the permissions on the connection.

bye,
Sumit

[Schlizor]

Hey,

yes the IP address is the same in both cases.

I tried using ad_use_ldaps = False but unfortunately it is the same result.

Here some information about the process of joining the AD, maybe it helps:

• /etc/krb5.conf.d/crypto-policies: Set encryptions (AES-256, 4096 Bit DH,...) -> Otherwise AD will not let us join
• /etc/openldap/ldap.conf: Add SASL_CBINDING = tls-endpoint -> Otherwise join over ldaps will not work
• realm join -U <User> example.com --use-ldaps (join without ldaps does not change the tokenGroup issue)
• Configure sssd.conf
• Configure authselect

Nevertheless, I am satisfied with the solution of setting token groups to false. It now seems to work really well.

Thanks,
Thomas