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

IDM deadlocks when it's started before the DS repositories

    XMLWordPrintable

    Details

    • Bug
    • Status: Done
    • Blocker
    • Resolution: Fixed
    • 7.0.0
    • 7.1.0
    • common-repo, devops, rest
    • IDM: 7.0.0-6d1e9f7c08b714d0f4e97c54736a8ac22503b19e
      DS: 7.0.0-68b1cf86ecc3e8740de135bb44338588cd1221a4

      Description

      In case IDM is used in kubernetes environment, sometimes when IDM boots faster than DS, it increases platform loading time due to necessary restart of IDM (Which thanks to kubernetes livechecks is done by killing pod after certain amount of time).

      When looking more deeply into the issue why the pod needs to be restarted we've discovered that if IDM is configured with multiple DS it will deadlock on ACTIVE_NOT_READY and does not attempt to reconnect.

      This is the excecption that occurs:

      INFO: DS bundle starting
      Jul 30, 2020 11:28:23 AM org.forgerock.i18n.slf4j.LocalizedLogger warn
      WARNING: Connection factory 'CachedConnectionPool(size=0[in:0 + out:0 + pending:0], maxSize=50, blocked=0, ldapClient=org.forgerock.opendj.ldap.LdapClientImpl@7f21c608)' is no longer operational: Connect Error: ds-idrepo-0.ds-idrepo
      Jul 30, 2020 11:28:23 AM org.forgerock.i18n.slf4j.LocalizedLogger warn
      WARNING: Connection factory 'CachedConnectionPool(size=0[in:0 + out:0 + pending:0], maxSize=50, blocked=0, ldapClient=org.forgerock.opendj.ldap.LdapClientImpl@7d386bdd)' is no longer operational: Connect Error: ds-idrepo-1.ds-idrepo
      Jul 30, 2020 11:28:23 AM org.forgerock.openidm.config.logging.LogServiceTracker logEntry
      SEVERE: Bundle: org.forgerock.openidm.repo-opendj [24] FrameworkEvent ERROR
      org.apache.felix.log.LogException: org.osgi.framework.BundleException: Activator start error in bundle org.forgerock.openidm.repo-opendj [24].
      	at org.apache.felix.framework.Felix.activateBundle(Felix.java:2452)
      	at org.apache.felix.framework.Felix.startBundle(Felix.java:2308)
      	at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1539)
      	at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308)
      	at java.base/java.lang.Thread.run(Unknown Source)
      Caused by: org.apache.felix.log.LogException: org.forgerock.opendj.ldap.ConnectionException: Connect Error: No operational connection factories available
      	at org.forgerock.opendj.ldap.LdapException.newLdapException(LdapException.java:230)
      	at org.forgerock.opendj.ldap.LdapException.newLdapException(LdapException.java:145)
      	at org.forgerock.opendj.ldap.LdapException.newLdapException(LdapException.java:114)
      	at org.forgerock.opendj.ldap.LdapException.newLdapException(LdapException.java:72)
      	at org.forgerock.opendj.ldap.LoadBalancer.noOperationalConnectionFactoriesException(LoadBalancer.java:760)
      	at org.forgerock.opendj.ldap.LoadBalancer$LdapClientSocketImpl.lambda$executeRequest0$5(LoadBalancer.java:807)
      	at io.reactivex.internal.operators.flowable.FlowableOnErrorNext$OnErrorNextSubscriber.onError(FlowableOnErrorNext.java:103)
      	at io.reactivex.internal.util.HalfSerializer.onError(HalfSerializer.java:70)
      	at io.reactivex.internal.operators.flowable.FlowableTakeUntil$TakeUntilMainSubscriber.onError(FlowableTakeUntil.java:76)
      	at io.reactivex.subscribers.SerializedSubscriber.onError(SerializedSubscriber.java:142)
      	at io.reactivex.internal.operators.flowable.FlowableRepeatWhen$WhenReceiver.onError(FlowableRepeatWhen.java:112)
      	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.checkTerminate(FlowableFlatMap.java:567)
      	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.drainLoop(FlowableFlatMap.java:374)
      	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.drain(FlowableFlatMap.java:366)
      	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.innerError(FlowableFlatMap.java:606)
      	at io.reactivex.internal.operators.flowable.FlowableFlatMap$InnerSubscriber.onError(FlowableFlatMap.java:672)
      	at io.reactivex.internal.subscriptions.EmptySubscription.error(EmptySubscription.java:55)
      	at io.reactivex.internal.operators.flowable.FlowableError.subscribeActual(FlowableError.java:40)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14936)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14883)
      	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onNext(FlowableFlatMap.java:163)
      	at io.reactivex.processors.UnicastProcessor.drainRegular(UnicastProcessor.java:322)
      	at io.reactivex.processors.UnicastProcessor.drain(UnicastProcessor.java:397)
      	at io.reactivex.processors.UnicastProcessor.onNext(UnicastProcessor.java:457)
      	at io.reactivex.processors.SerializedProcessor.onNext(SerializedProcessor.java:103)
      	at io.reactivex.internal.operators.flowable.FlowableRepeatWhen$WhenSourceSubscriber.again(FlowableRepeatWhen.java:171)
      	at io.reactivex.internal.operators.flowable.FlowableRetryWhen$RetryWhenSubscriber.onError(FlowableRetryWhen.java:76)
      	at io.reactivex.internal.operators.flowable.FlowableDoOnEach$DoOnEachSubscriber.onError(FlowableDoOnEach.java:111)
      	at io.reactivex.internal.operators.single.SingleFlatMapPublisher$SingleFlatMapPublisherObserver.onError(SingleFlatMapPublisher.java:122)
      	at io.reactivex.internal.operators.flowable.FlowableSingleSingle$SingleElementSubscriber.onError(FlowableSingleSingle.java:97)
      	at io.reactivex.subscribers.SerializedSubscriber.onError(SerializedSubscriber.java:142)
      	at io.reactivex.internal.operators.flowable.FlowableRepeatWhen$WhenReceiver.onError(FlowableRepeatWhen.java:112)
      	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.checkTerminate(FlowableFlatMap.java:567)
      	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.drainLoop(FlowableFlatMap.java:374)
      	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.drain(FlowableFlatMap.java:366)
      	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.innerError(FlowableFlatMap.java:606)
      	at io.reactivex.internal.operators.flowable.FlowableFlatMap$InnerSubscriber.onError(FlowableFlatMap.java:672)
      	at io.reactivex.internal.subscriptions.EmptySubscription.error(EmptySubscription.java:55)
      	at io.reactivex.internal.operators.flowable.FlowableError.subscribeActual(FlowableError.java:40)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14936)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14883)
      	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onNext(FlowableFlatMap.java:163)
      	at io.reactivex.processors.UnicastProcessor.drainRegular(UnicastProcessor.java:322)
      	at io.reactivex.processors.UnicastProcessor.drain(UnicastProcessor.java:397)
      	at io.reactivex.processors.UnicastProcessor.onNext(UnicastProcessor.java:457)
      	at io.reactivex.processors.SerializedProcessor.onNext(SerializedProcessor.java:103)
      	at io.reactivex.internal.operators.flowable.FlowableRepeatWhen$WhenSourceSubscriber.again(FlowableRepeatWhen.java:171)
      	at io.reactivex.internal.operators.flowable.FlowableRetryWhen$RetryWhenSubscriber.onError(FlowableRetryWhen.java:76)
      	at io.reactivex.internal.operators.single.SingleToFlowable$SingleToFlowableObserver.onError(SingleToFlowable.java:67)
      	at io.reactivex.internal.operators.single.SingleDoOnError$DoOnError.onError(SingleDoOnError.java:63)
      	at io.reactivex.internal.operators.single.SingleMap$MapSingleObserver.onError(SingleMap.java:69)
      	at io.reactivex.internal.operators.single.SingleDoOnError$DoOnError.onError(SingleDoOnError.java:63)
      	at io.reactivex.internal.operators.single.SingleDoOnSuccess$DoOnSuccess.onError(SingleDoOnSuccess.java:65)
      	at io.reactivex.subjects.SingleSubject.subscribeActual(SingleSubject.java:171)
      	at io.reactivex.Single.subscribe(Single.java:3666)
      	at org.forgerock.opendj.ldap.CachedConnectionPool.connect0(CachedConnectionPool.java:522)
      	at org.forgerock.opendj.ldap.CachedConnectionPool$1.subscribeActual(CachedConnectionPool.java:420)
      	at io.reactivex.Single.subscribe(Single.java:3666)
      	at io.reactivex.internal.operators.single.SingleDoOnSuccess.subscribeActual(SingleDoOnSuccess.java:35)
      	at io.reactivex.Single.subscribe(Single.java:3666)
      	at io.reactivex.internal.operators.single.SingleDoOnError.subscribeActual(SingleDoOnError.java:35)
      	at io.reactivex.Single.subscribe(Single.java:3666)
      	at io.reactivex.internal.operators.single.SingleMap.subscribeActual(SingleMap.java:34)
      	at io.reactivex.Single.subscribe(Single.java:3666)
      	at io.reactivex.internal.operators.single.SingleDoOnError.subscribeActual(SingleDoOnError.java:35)
      	at io.reactivex.Single.subscribe(Single.java:3666)
      	at io.reactivex.internal.operators.single.SingleDefer.subscribeActual(SingleDefer.java:43)
      	at io.reactivex.Single.subscribe(Single.java:3666)
      	at io.reactivex.internal.operators.single.SingleToFlowable.subscribeActual(SingleToFlowable.java:37)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14936)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14883)
      	at io.reactivex.internal.operators.flowable.FlowableRepeatWhen$WhenReceiver.onNext(FlowableRepeatWhen.java:100)
      	at io.reactivex.internal.operators.flowable.FlowableRetryWhen.subscribeActual(FlowableRetryWhen.java:62)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14936)
      	at io.reactivex.internal.operators.flowable.FlowableSingleSingle.subscribeActual(FlowableSingleSingle.java:39)
      	at io.reactivex.Single.subscribe(Single.java:3666)
      	at io.reactivex.internal.operators.single.SingleFlatMapPublisher.subscribeActual(SingleFlatMapPublisher.java:66)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14936)
      	at io.reactivex.internal.operators.flowable.FlowableDoOnEach.subscribeActual(FlowableDoOnEach.java:50)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14936)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14883)
      	at io.reactivex.internal.operators.flowable.FlowableRepeatWhen$WhenReceiver.onNext(FlowableRepeatWhen.java:100)
      	at io.reactivex.internal.operators.flowable.FlowableRetryWhen.subscribeActual(FlowableRetryWhen.java:62)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14936)
      	at io.reactivex.internal.operators.flowable.FlowableTakeUntil.subscribeActual(FlowableTakeUntil.java:38)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14936)
      	at io.reactivex.internal.operators.flowable.FlowableOnErrorNext.subscribeActual(FlowableOnErrorNext.java:40)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14936)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14883)
      	at io.reactivex.internal.operators.flowable.FlowableDefer.subscribeActual(FlowableDefer.java:42)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14936)
      	at io.reactivex.internal.operators.flowable.FlowableDoOnEach.subscribeActual(FlowableDoOnEach.java:47)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14936)
      	at io.reactivex.internal.operators.flowable.FlowableDoOnEach.subscribeActual(FlowableDoOnEach.java:47)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14936)
      	at io.reactivex.internal.operators.flowable.FlowableFilter.subscribeActual(FlowableFilter.java:37)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14936)
      	at io.reactivex.internal.operators.flowable.FlowableMap.subscribeActual(FlowableMap.java:37)
      	at io.reactivex.Flowable.subscribe(Flowable.java:14936)
      	at io.reactivex.internal.operators.flowable.FlowableReduceMaybe.subscribeActual(FlowableReduceMaybe.java:57)
      	at io.reactivex.Maybe.subscribe(Maybe.java:4290)
      	at io.reactivex.internal.operators.maybe.MaybeSwitchIfEmptySingle.subscribeActual(MaybeSwitchIfEmptySingle.java:45)
      	at io.reactivex.Single.subscribe(Single.java:3666)
      	at io.reactivex.internal.operators.single.SingleMap.subscribeActual(SingleMap.java:34)
      	at io.reactivex.Single.subscribe(Single.java:3666)
      	at io.reactivex.internal.operators.single.SingleMap.subscribeActual(SingleMap.java:34)
      	at io.reactivex.Single.subscribe(Single.java:3666)
      	at io.reactivex.Single.subscribe(Single.java:3652)
      	at org.forgerock.opendj.ldap.Utils.toPromise(Utils.java:228)
      	at org.forgerock.openidm.repo.opendj.impl.Activator.lambda$start$1(Activator.java:220)
      	at io.reactivex.Single.to(Single.java:3945)
      	at org.forgerock.openidm.repo.opendj.impl.Activator.start(Activator.java:220)
      	at org.apache.felix.framework.util.SecureAction.startActivator(SecureAction.java:698)
      	at org.apache.felix.framework.Felix.activateBundle(Felix.java:2402)
      	... 4 more
      

      More information can be found in CLOUD-2274

      To reproduce the issue:
      1) Configure IDM to start with multiple DS
      2) Start the IDM - it will throw that error above
      3) Start the DS - IDM it should reconnect but if fact it never does

        Attachments

          Issue Links

            Activity

              People

              ylecaillez Yannick Lecaillez
              Ladislav.Folta Ladislav Folta
              Yannick Lecaillez Yannick Lecaillez
              Votes:
              1 Vote for this issue
              Watchers:
              9 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: