IdCachedServicesImpl member cache may incorrectly cache member set upon login

[sp193]

Describe the bug Upon login, the first calls to evaluate policies may fail, due to functions like AMIdentity.isMember() getting an empty set from IdCachedServicesImpl.getMemberships(). This is a rare occurrance, but somehow happens nearly all the time on one server I have in the cloud.

If I waited for a while, policy evaluations within the session start working correctly. What seems to be making this issue larger, is that the (incorrect) policy evaluation result is also cached by AM for a while.

To Reproduce Steps to reproduce the behavior:

1. Log in.
2. Immediately call some API via IG, which will cause a policy evaluation. In my app, this would be triggered by APIs/pages getting accessed via IG, after a redirection from the login page.
3. The result to IG's request is an empty set for allowed actions.
4. HTTP 403 is returned.

Expected behavior The memberships should always be correctly returned.

Desktop (please complete the following information):

• OS: Windows 10 64-bit, 22H2
• Browser Firefox 118.0.2
• Version 14.7.5 Snapshot

Additional context It may be related to fff7834f (#605), when this cache was added. I attempted to rollback this commit and the problem went away.

But I do not know enough about why it was added or the expected behaviour of IdCachedServicesImpl after login, to really know what's wrong. @maximthomas, would you be able to advise?

Thanks!

EDIT: clarified on the 2nd step for replication.

[sp193]

Just maybe: if there are no IdRepo plugins (aside from the "special" plugin) that support the membersType at the moment, an empty set is returned and this is cached. I don't know why this may happen, but I think there are signs of it.

Given this in IdServicesImpl:

           if (!idRepo.getSupportedTypes().contains(membersType) ||
               idRepo.getClass().getName().equals(IdConstants.SPECIAL_PLUGIN)) {
               // IdRepo plugin does not support the idType for
               // memberships
               noOfSuccess--;
               continue;
           }
...
       if (noOfSuccess == 0) {
           if (DEBUG.warningEnabled()) {
               DEBUG.warning(
                   "IdServicesImpl.getMembers: "
                   + "Unable to get members for identity " + type.getName()
                   + "::" + name + " in any configured data store", origEx);
           }
           if (origEx != null) {
               throw origEx;
           } else {
               return (Collections.EMPTY_SET);
           }
       } else {

In IdRepo log:

amIdm:10/12/2023 11:19:56:729 pm SGT: Thread[http-nio-9090-exec-16,5,main]: TransactionId[d7046390-39a8-47de-89f6-1a3d03dfcef4-17795]
IdCachedServicesImpl.getMemberships(): NO entry found in Cache for key = id=admin,ou=user,o=iot_platform,o=wisx,ou=services,dc=openam,dc=forgerock,dc=org. Getting members from DS: 
...
amIdm:10/12/2023 11:19:56:745 pm SGT: Thread[http-nio-9090-exec-16,5,main]: TransactionId[d7046390-39a8-47de-89f6-1a3d03dfcef4-17795]
IdRepoPluginsCache.getIdRepoPlugins for OrgName: o=IOT_PLATFORM,o=WISX,ou=services,dc=openam,dc=forgerock,dc=org Op: Operation: read Type: IdType: user
DJLDAPv3Repo:10/12/2023 11:19:56:745 pm SGT: Thread[http-nio-9090-exec-16,5,main]: TransactionId[d7046390-39a8-47de-89f6-1a3d03dfcef4-17795]
getSupportedTypes invoked
amIdm:10/12/2023 11:19:56:745 pm SGT: Thread[http-nio-9090-exec-16,5,main]: TransactionId[d7046390-39a8-47de-89f6-1a3d03dfcef4-17795]
WARNING: IdServicesImpl.getMemberships: Unable to get members for identity user::admin in any configured data store

And then in the Policy log, without any case of "getMemberships(): NO entry found in Cache for key" (implies a cache hit):

amPolicy:10/12/2023 11:20:05:703 pm SGT: Thread[http-nio-9090-exec-10,5,main]: TransactionId[d7046390-39a8-47de-89f6-1a3d03dfcef4-17865]
IdentitySubject.isMember():userIdentity type IdType: user can be a member of subjectIdentityType IdType: group:membership=false

The next case of "getMemberships(): NO entry found in Cache for key" is at 10/12/2023 11:20:12:241 pm SGT.