[OPENAM-14175] CTS updates on multivalue attributes may throws Duplicate values exception Created: 27/Dec/18  Updated: 03/Nov/19  Resolved: 22/Feb/19

Status: Resolved
Project: OpenAM
Component/s: CTS, session
Affects Version/s: 5.5.1, 6.0.0, 6.0.0.1, 6.0.0.2, 6.0.0.3, 6.0.0.4, 6.0.0.5, 6.5.0, 6.0.0.6
Fix Version/s: 6.5.1, 6.0.1, 5.5.2, 7.0.0

Type: Bug Priority: Major
Reporter: C-Weng C Assignee: Lawrence Yarham
Resolution: Fixed Votes: 0
Labels: EDISON
Remaining Estimate: 0h
Time Spent: 8h
Original Estimate: Not Specified
Environment:

AM not sticky and possibly concurrent access happens to register agent notification on 2 AM at the same time. (This issues requires updates to the CoreTokenMultiString* happening)


Issue Links:
Relates
relates to OPENAM-14409 CTS Entry Already Exists errors witho... Resolved
is related to OPENAM-14409 CTS Entry Already Exists errors witho... Resolved
Sprint: AM Sustaining Sprint 59, AM Sustaining Sprint 60
Story Points: 5
Needs backport:
No
Support Ticket IDs:
Needs QA verification:
No
Functional tests:
No
Are the reproduction steps defined?:
Yes and I used the same an in the description

 Description   

Bug description

As user is firing requests in parallel to the protected application, more than one agent gets the request and they reach openam server for validating the request through sessionservice call. As request goes to two AM servers in parallel, both of them tries to update the SSO session in CTS at the same time and the following happens:

 

org.forgerock.openam.sm.datalayer.api.LdapOperationFailedException:
CTS: Operation failed:
Result Code: Attribute or Value Exists
Diagnostic Message: Entry coreTokenId=.....,ou=famrecords,ou=openam-session,ou=tokens,dc=openam,dc=forgerock,dc=com cannot be modified because it would have resulted in one or more duplicate values for attribute coreTokenMultiString01: d73f9fca-5772-404e-a159-c8e93af50729
Matched DN:
at org.forgerock.openam.cts.impl.LdapAdapter.update(LdapAdapter.java:168)
at org.forgerock.openam.sm.datalayer.impl.tasks.UpdateTask.performTask(UpdateTask.java:59)
at org.forgerock.openam.sm.datalayer.api.AbstractTask.execute(AbstractTask.java:53)
at org.forgerock.openam.sm.datalayer.impl.SeriesTaskExecutor$TaskDecorator.execute(SeriesTaskExecutor.java:231)
at org.forgerock.openam.sm.datalayer.impl.SimpleTaskExecutor.execute(SimpleTaskExecutor.java:59)
at org.forgerock.openam.sm.datalayer.impl.SeriesTaskExecutorThread.run(SeriesTaskExecutorThread.java:86)
at org.forgerock.openam.audit.context.AuditRequestContextPropagatingRunnable.run(AuditRequestContextPropagatingRunnable.java:34)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Wrapped by: org.forgerock.openam.cts.exceptions.CoreTokenException:
CTS:
CTS: Operation failed:
Result Code: Attribute or Value Exists
Diagnostic Message: Entry coreTokenId=....=,ou=famrecords,ou=openam-session,ou=tokens,dc=openam,dc=forgerock,dc=org cannot be modified because it would have resulted in one or more duplicate values for attribute coreTokenMultiString01: d73f9fca-5772-404e-a159-c8e93af50729
Matched DN:
at org.forgerock.openam.cts.impl.queue.AsyncResultHandler.getResults(AsyncResultHandler.java:95)
at org.forgerock.openam.cts.monitoring.impl.queue.TokenMonitoringResultHandler.getResults(TokenMonitoringResultHandler.java:42)
at org.forgerock.openam.cts.monitoring.impl.queue.TokenMonitoringResultHandler.getResults(TokenMonitoringResultHandler.java:19)
at org.forgerock.openam.cts.CTSPersistentStoreImpl.update(CTSPersistentStoreImpl.java:162)
at org.forgerock.openam.cts.CTSPersistentStoreImpl.update(CTSPersistentStoreImpl.java:155)
at org.forgerock.openam.session.cts.SessionPersistenceStore.update(SessionPersistenceStore.java:119)
at org.forgerock.openam.session.cts.CtsSessionPersistenceStore.store(CtsSessionPersistenceStore.java:53)
at org.forgerock.openam.session.cts.CtsSessionStoreChain$ChainIterator.store(CtsSessionStoreChain.java:64)
at org.forgerock.openam.session.cts.SessionPersistenceManagerStep.store(SessionPersistenceManagerStep.java:44)
at org.forgerock.openam.session.cts.CtsSessionStoreChain$ChainIterator.store(CtsSessionStoreChain.java:62)
at org.forgerock.openam.session.cts.DsameSessionInterceptorStep.store(DsameSessionInterceptorStep.java:59)
at org.forgerock.openam.session.cts.CtsSessionStoreChain$ChainIterator.store(CtsSessionStoreChain.java:62)
at org.forgerock.openam.session.cts.InMemoryCtsSessionCacheStep.store(InMemoryCtsSessionCacheStep.java:108)
at org.forgerock.openam.session.cts.CtsSessionStoreChain$ChainIterator.store(CtsSessionStoreChain.java:62)
at org.forgerock.openam.session.cts.AbstractCtsSessionStoreStep.store(AbstractCtsSessionStoreStep.java:29)
at org.forgerock.openam.session.cts.CtsSessionStoreChain$ChainIterator.store(CtsSessionStoreChain.java:62)
at org.forgerock.openam.session.cts.CtsSessionStoreChain.store(CtsSessionStoreChain.java:38)
at org.forgerock.openam.session.cts.SessionPersistenceManagerStep.notifyUpdate(SessionPersistenceManagerStep.java:62)
at org.forgerock.openam.session.cts.CtsSession.notifyPersistenceManager(CtsSession.java:865)
at org.forgerock.openam.session.cts.CtsOperations.notifyListenerFor(CtsOperations.java:373)
at com.iplanet.dpro.session.monitoring.MonitoredOperations.lambda$notifyListenerFor$7(MonitoredOperations.java:132)
at com.iplanet.dpro.session.monitoring.MonitoredOperations.time(MonitoredOperations.java:200)
at com.iplanet.dpro.session.monitoring.MonitoredOperations.notifyListenerFor(MonitoredOperations.java:132)
at com.iplanet.dpro.session.service.SessionService.notifyListenerFor(SessionService.java:317)
at com.sun.identity.policy.plugins.AMIdentitySubject.isMember(AMIdentitySubject.java:407)
at com.sun.identity.entitlement.opensso.PolicySubject.evaluate(PolicySubject.java:220)
at com.sun.identity.entitlement.Privilege.doesSubjectMatch(Privilege.java:669)
at com.sun.identity.entitlement.opensso.OpenSSOPrivilege.internalEvaluate(OpenSSOPrivilege.java:140)
at com.sun.identity.entitlement.opensso.OpenSSOPrivilege.access$000(OpenSSOPrivilege.java:63)
at com.sun.identity.entitlement.opensso.OpenSSOPrivilege$1.run(OpenSSOPrivilege.java:105)
at com.sun.identity.entitlement.opensso.OpenSSOPrivilege$1.run(OpenSSOPrivilege.java:99)
at com.sun.identity.session.util.RestrictedTokenContext.doUsing(RestrictedTokenContext.java:81)
at com.sun.identity.entitlement.opensso.OpenSSOPrivilege.evaluate(OpenSSOPrivilege.java:98)
at com.sun.identity.entitlement.PrivilegeEvaluator$PrivilegeTask.run(PrivilegeEvaluator.java:421)
at com.sun.identity.entitlement.ThreadPool$WorkerThread.run(ThreadPool.java:166)

 

 

How to reproduce the issue

Customer reported. However code analysis does indicate that this is plausible on the way the LDAP update on CoreTokenAdapter and LdapAdapter since if there on an update it read the value from LDAP and then try to merge the update using a "add". For multiple value attributes this is BAD and the same exception will expected to be see say using a sample ldapmodify ldif.

Conditon:

  • Must have non-sticy AM and a few AM getting concurrent access.

Impact:

  • For exception on multi-value attributes (for this is on the Notification listener id). this means there is a duplicate so not issue other than some other attributes possibly say idletimout may not be updated.
Expected behaviour
Concurrently request for session adding notification not trigger exception
Current behaviour
Exception happens if there

Work around

  • Depending on the context of the error, as it is a duplicate, this may not be a serious issue (as the other request may probably have identical value) and so not an issue other than the ERROR exception
  • But based on analysis, the best solution is still to ensure AM stickiness (or some form of affinity to AM session)

Code analysis

UpdateTask.java
    public Optional<TokenType> performTask(TokenStorageAdapter adapter) throws DataLayerException {
        Token previous = adapter.read(token.getTokenId(), options);
        Token updated;
        if (previous == null) {
            updated = adapter.create(token, options);
        } else {
            updated = adapter.update(previous, token, options);
        }
        handler.processResults(updated);
        return Optional.ofNullable(updated).map(Token::getType);
    }
LdapAdapter.java
    public Token update(Token previous, Token updated, Options options) throws DataLayerException {
        Entry currentEntry = conversion.getEntry(updated);
        LdapTokenAttributeConversion.stripObjectClass(currentEntry);

        Entry previousEntry = conversion.getEntry(previous);
        LdapTokenAttributeConversion.stripObjectClass(previousEntry);

        ModifyRequest request = Entries.diffEntries(previousEntry, currentEntry,
                Entries.diffOptions().replaceSingleValuedAttributes());

        if (request.getModifications().isEmpty()) {
            return previous;
        }

This piece of code takes an copy (at the time is valid) and the value that it needs to updated on and use Entries.diffEntries to create the change modification (ala LDIF)
The LDIF to be made to LDAP are then run. Notice that it generated a ldif like this when the value is not there originally:

add: coreTokenMultiString01
coreTokenMultiString01: d73f9fca-5772-404e-a159-c8e93af50729

So if there is an update is made to directory after that time the "previous" value is taken, this may be a bit inconsistent.

The above seems to by synthetic testing to happen if say SessionService.notifyListenerFor update the session for listeners. it seems at least for MT on same AM the issue does not happen as updates seems to be sequential-ised to the same worker thread (based on tokenId) and the concurrent issue is not seen (due to the same Worker thread works on only the same tokenId). However it seems if concurrent updates on two AM as in the reported case can happen like the following case the exception may happen

  1. Login to AM1
  2. Now access AM1 with a call to (SessionService.notifyListenerFor(thissession, somelistener)
    (for good measure say UpdateTask is a bit slow (ie it read the previous value) but have not updated
    #. Now at the same time AM2 is issues the same command but run quickly to update DJ with new values
  3. Then exception happens

Maybe the code should use Entries.diffOptions().alwaysReplaceAttributes()
instead so all updates uses replace. (But this is a bit dangerous due to lost update.).
In fact one wonder for if all these multi-valued should use permissive modify control

 

 



 Comments   
Comment by Andrew Vinall [ 02/Jan/19 ]

Bug Triage: C-Weng C Could you attach the customer ticket?

Generated at Wed Nov 25 05:18:22 UTC 2020 using Jira 7.13.12#713012-sha1:6e07c38070d5191bbf7353952ed38f111754533a.