Uploaded image for project: 'OpenDJ'
  1. OpenDJ
  2. OPENDJ-7733

Under load IDM Recon may fail on some user when external DJ is used as repo

    XMLWordPrintable

    Details

    • Bug
    • Status: Dev backlog
    • Major
    • Resolution: Unresolved
    • 7.1.0
    • None
    • common-repo, rest
    • IDM/DJ 7.1.0-SNAPSHOT runs on a CentOS7, IDM uses external dj as repo, Java 11.

      Description

      The test runs a recon from IDM to DJ, IDM has some roles in place and the users with different role will be reconed to different org in DJ. Under load, recon may fail on some user. See error below in IDM log:

      WARNING: Unexpected failure during source reconciliation 171a2763-4449-4bad-8aa1-0310ed37ff35-200024
      org.forgerock.openidm.sync.SynchronizationException: The request cannot be processed because the resource '220ea73f-01a8-43ef-9fd6-4486dca6a4c3' referenced in field '/_meta' does not exist
              at org.forgerock.openidm.sync.SyncOperation.execScript(SyncOperation.java:837)
              at org.forgerock.openidm.sync.SyncOperation.execScript(SyncOperation.java:786)
              at org.forgerock.openidm.sync.SyncOperation.performAction(SyncOperation.java:509)
              at org.forgerock.openidm.metrics.MetricsCollector.time(MetricsCollector.java:83)
              at org.forgerock.openidm.sync.SourceSyncOperation.sync(SourceSyncOperation.java:142)
              at org.forgerock.openidm.sync.SourceRecon.recon(SourceRecon.java:101)
              at org.forgerock.openidm.sync.ReconTask.call(ReconTask.java:53)
              at org.forgerock.openidm.sync.ReconTask.call(ReconTask.java:22)
              at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
              at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
              at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
              at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
              at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
              at java.base/java.lang.Thread.run(Thread.java:834)
      Caused by: org.forgerock.json.resource.BadRequestException: The request cannot be processed because the resource '220ea73f-01a8-43ef-9fd6-4486dca6a4c3' referenced in field '/_meta' does not exist
              at org.forgerock.opendj.rest2ldap.Utils.newBadRequestException(Utils.java:153)
              at org.forgerock.opendj.rest2ldap.Utils.newBadRequestException(Utils.java:149)
              at org.forgerock.opendj.rest2ldap.AbstractReferencePropertyMapper.convertError(AbstractReferencePropertyMapper.java:486)
              at org.forgerock.opendj.rest2ldap.AbstractReferencePropertyMapper.lambda$fetchReferencedEntry$11(AbstractReferencePropertyMapper.java:457)
              at io.reactivex.rxjava3.internal.operators.single.SingleResumeNext$ResumeMainSingleObserver.onError(SingleResumeNext.java:73)
              at io.reactivex.rxjava3.internal.operators.single.SingleMap$MapSingleObserver.onError(SingleMap.java:70)
              at io.reactivex.rxjava3.internal.operators.maybe.MaybeSwitchIfEmptySingle$SwitchIfEmptyMaybeObserver$OtherSingleObserver.onError(MaybeSwitchIfEmptySingle.java:122)
              at io.reactivex.rxjava3.internal.disposables.EmptyDisposable.error(EmptyDisposable.java:78)
              at io.reactivex.rxjava3.internal.operators.single.SingleError.subscribeActual(SingleError.java:41)
              at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4813)
              at io.reactivex.rxjava3.internal.operators.maybe.MaybeSwitchIfEmptySingle$SwitchIfEmptyMaybeObserver.onComplete(MaybeSwitchIfEmptySingle.java:95)
              at io.reactivex.rxjava3.internal.operators.flowable.FlowableReduceMaybe$ReduceSubscriber.onComplete(FlowableReduceMaybe.java:139)
              at io.reactivex.rxjava3.internal.subscribers.BasicFuseableSubscriber.onComplete(BasicFuseableSubscriber.java:120)
              at io.reactivex.rxjava3.internal.subscribers.BasicFuseableSubscriber.onComplete(BasicFuseableSubscriber.java:120)
              at io.reactivex.rxjava3.internal.operators.flowable.FlowableDoOnLifecycle$SubscriptionLambdaSubscriber.onComplete(FlowableDoOnLifecycle.java:94)
              at io.reactivex.rxjava3.internal.operators.flowable.FlowableOnErrorNext$OnErrorNextSubscriber.onComplete(FlowableOnErrorNext.java:116)
              at io.reactivex.rxjava3.internal.subscribers.BasicFuseableSubscriber.onComplete(BasicFuseableSubscriber.java:120)
              at io.reactivex.rxjava3.internal.operators.flowable.FlowableTakeUntilPredicate$InnerSubscriber.onNext(FlowableTakeUntilPredicate.java:70)
              at io.reactivex.rxjava3.internal.operators.flowable.FlowableTakeWhile$TakeWhileSubscriber.onNext(FlowableTakeWhile.java:79)
              at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.tryEmit(FlowableFlatMap.java:271)
              at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMap$InnerSubscriber.onNext(FlowableFlatMap.java:628)
              at io.reactivex.rxjava3.internal.operators.flowable.FlowableGroupBy$State.drainNormal(FlowableGroupBy.java:555)
              at io.reactivex.rxjava3.internal.operators.flowable.FlowableGroupBy$State.drain(FlowableGroupBy.java:474)
              at io.reactivex.rxjava3.internal.operators.flowable.FlowableGroupBy$State.subscribe(FlowableGroupBy.java:424)
              at io.reactivex.rxjava3.internal.operators.flowable.FlowableGroupBy$GroupedUnicast.subscribeActual(FlowableGroupBy.java:341)
              at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15753)
              at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15699)
              at org.forgerock.opendj.ldap.LdapClientImpl$LdapClientSocketImpl$1.lambda$subscribeActual$0(LdapClientImpl.java:524)
              at org.forgerock.opendj.ldap.LdapClientImpl$LdapClientSocketImpl.setResponseStream(LdapClientImpl.java:385)
              at io.reactivex.rxjava3.internal.subscribers.LambdaSubscriber.onNext(LambdaSubscriber.java:65)
      
      
      

      The complete idm log file is attached, I can send the DJ logs over if needed(they are too big to attach to the JIRA.)

      To reproduce it with Pyforge:
      1. Use the config file attached, this is from my Mac, the total number of users to be reconed is 30*600 under Stress section, it may need to be increased to reproduce the symptom. 

      2. Run the test:

      ./run-pybot.py -c stress -s idm.regular_recon.ReconManUsersWithRolesToLDAP OpenIDM 

      and see the recon progress file in debug.txt in the result folder. In my case, I have:

      20210107 15:28:42.180 - INFO - # failures        : 1
      20210107 15:28:42.180 - INFO - # success         : 7168
      20210107 15:28:42.180 - INFO - # current duration: 1028.71
      20210107 15:28:42.180 - INFO - # current tps     : 6.967950 

       

      I used the following product versions in my test:

      Products Full Version
      DjSdk: 7.1.0-SNAPSHOT ddb7aa8ec3d
      OpenDJ: 7.1.0-SNAPSHOT ddb7aa8ec3d
      OpenIDM: 7.1.0-SNAPSHOT 52e911d
      IDMExternalDJ: 7.1.0-SNAPSHOT ddb7aa8ec3d 

      When I used the same IDM version but replaced DJ with 7.0.0 released version, no problem was seen.

      Also the test started fail on Dec.19 2000.

        Attachments

        1. config.cfg
          11 kB
        2. debug.txt
          504 kB
        3. openidm0.log.0.gz
          35 kB

          Activity

            People

            Unassigned Unassigned
            Tinghua.Xu Tinghua Xu [X] (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Dates

              Created:
              Updated: