Uploaded image for project: 'OpenAM'
  1. OpenAM
  2. OPENAM-11685

Exceptions are thrown in shutdown that cause the application not to shutdown cleanly

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 14.5.0
    • Fix Version/s: 14.5.0
    • Component/s: None
    • Labels:
    • Environment:
      Tomcat 8.0.30
    • Rank:
      1|hzu4xr:

      Description

      Bug description

      Huge numbers of DJ-related thread locals are complained about when the application instance is terminated, then the following exception is seen:

      05-Sep-2017 22:29:40.610 INFO [Worker Thread 6] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load [org.glassfish.grizzly.memory.CompositeBuffer]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
       java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [org.glassfish.grizzly.memory.CompositeBuffer]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
      	at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading(WebappClassLoaderBase.java:1353)
      	at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1341)
      	at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1206)
      	at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1167)
      	at org.glassfish.grizzly.memory.PooledMemoryManager.newCompositeBuffer(PooledMemoryManager.java:452)
      	at org.glassfish.grizzly.memory.PooledMemoryManager.reallocate(PooledMemoryManager.java:317)
      	at org.forgerock.opendj.grizzly.Asn1BufferWriter.ensureAdditionalCapacity(Asn1BufferWriter.java:161)
      	at org.forgerock.opendj.grizzly.Asn1BufferWriter$RootSequenceBuffer.writeByteArray(Asn1BufferWriter.java:118)
      	at org.forgerock.opendj.grizzly.Asn1BufferWriter$ChildSequenceBuffer.endSequence(Asn1BufferWriter.java:46)
      	at org.forgerock.opendj.grizzly.Asn1BufferWriter.writeEndSequence(Asn1BufferWriter.java:210)
      	at org.forgerock.opendj.io.LdapWriter.writeMessageFooter(LdapWriter.java:761)
      	at org.forgerock.opendj.io.LdapWriter.writeSearchResultEntry(LdapWriter.java:671)
      	at org.forgerock.opendj.io.LdapWriter.writeLdapMessage(LdapWriter.java:158)
      	at org.forgerock.opendj.grizzly.Codecs$AbstractCodec.handleWrite(Codecs.java:341)
      	at org.glassfish.grizzly.filterchain.ExecutorResolver$8.execute(ExecutorResolver.java:111)
      	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:284)
      	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:201)
      	at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:133)
      	at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
      	at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
      	at org.glassfish.grizzly.filterchain.DefaultFilterChain.write(DefaultFilterChain.java:414)
      	at org.glassfish.grizzly.nio.NIOConnection.write(NIOConnection.java:431)
      	at org.glassfish.grizzly.nio.NIOConnection.write(NIOConnection.java:405)
      	at org.forgerock.opendj.grizzly.LdapServerFilter$1.onNext(LdapServerFilter.java:229)
      	at org.forgerock.opendj.grizzly.LdapServerFilter$1.onNext(LdapServerFilter.java:199)
      	at io.reactivex.internal.util.HalfSerializer.onNext(HalfSerializer.java:45)
      	at io.reactivex.internal.subscribers.StrictSubscriber.onNext(StrictSubscriber.java:97)
      	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.tryEmit(FlowableFlatMap.java:282)
      	at io.reactivex.internal.operators.flowable.FlowableFlatMap$InnerSubscriber.onNext(FlowableFlatMap.java:657)
      	at io.reactivex.internal.operators.flowable.FlowableMap$MapSubscriber.onNext(FlowableMap.java:69)
      	at io.reactivex.internal.operators.flowable.FlowableOnErrorReturn$OnErrorReturnSubscriber.onNext(FlowableOnErrorReturn.java:50)
      	at io.reactivex.internal.operators.flowable.FlowableDoOnEach$DoOnEachSubscriber.onNext(FlowableDoOnEach.java:91)
      	at io.reactivex.internal.operators.flowable.FlowableDoOnEach$DoOnEachSubscriber.onNext(FlowableDoOnEach.java:91)
      	at io.reactivex.internal.operators.flowable.FlowableOnErrorNext$OnErrorNextSubscriber.onNext(FlowableOnErrorNext.java:69)
      	at io.reactivex.internal.operators.flowable.FlowableDoOnEach$DoOnEachSubscriber.onNext(FlowableDoOnEach.java:91)
      	at io.reactivex.internal.operators.flowable.FlowableDoOnEach$DoOnEachSubscriber.onNext(FlowableDoOnEach.java:91)
      	at com.forgerock.reactive.BlockingBackpressureOperator$BlockingSubscriberWrapper.onNext(BlockingBackpressureOperator.java:119)
      	at io.reactivex.internal.util.HalfSerializer.onNext(HalfSerializer.java:45)
      	at io.reactivex.internal.subscribers.StrictSubscriber.onNext(StrictSubscriber.java:97)
      	at io.reactivex.internal.operators.flowable.FlowableCreate$MissingEmitter.onNext(FlowableCreate.java:338)
      	at io.reactivex.internal.operators.flowable.FlowableCreate$SerializedEmitter.onNext(FlowableCreate.java:114)
      	at org.opends.server.protocols.ldap.LdapClientConnection.sendSearchEntry(LdapClientConnection.java:382)
      	at org.opends.server.core.SearchOperationBasis.sendSearchEntry(SearchOperationBasis.java:727)
      	at org.opends.server.core.SearchOperationBasis.returnEntry(SearchOperationBasis.java:512)
      	at org.opends.server.core.SearchOperationBasis.returnEntry(SearchOperationBasis.java:347)
      	at org.opends.server.core.SearchOperationWrapper.returnEntry(SearchOperationWrapper.java:52)
      	at org.opends.server.backends.pluggable.EntryContainer$3.searchBaseObject(EntryContainer.java:782)
      	at org.opends.server.backends.pluggable.EntryContainer$3.run(EntryContainer.java:630)
      	at org.opends.server.backends.pluggable.EntryContainer$3.run(EntryContainer.java:586)
      	at org.opends.server.backends.jeb.JEStorage.read(JEStorage.java:680)
      	at org.opends.server.backends.pluggable.TracedStorage.read(TracedStorage.java:419)
      	at org.opends.server.backends.pluggable.EntryContainer.search(EntryContainer.java:586)
      	at org.opends.server.backends.pluggable.BackendImpl.search(BackendImpl.java:479)
      	at org.opends.server.workflowelement.localbackend.LocalBackendSearchOperation.processSearch(LocalBackendSearchOperation.java:159)
      	at org.opends.server.workflowelement.localbackend.LocalBackendSearchOperation.processLocalSearch(LocalBackendSearchOperation.java:97)
      	at org.opends.server.workflowelement.localbackend.LocalBackendWorkflowElement.executeOperation(LocalBackendWorkflowElement.java:411)
      	at org.opends.server.workflowelement.localbackend.LocalBackendWorkflowElement.execute(LocalBackendWorkflowElement.java:533)
      	at org.opends.server.core.SearchOperationBasis.run(SearchOperationBasis.java:778)
      	at org.opends.server.extensions.TraditionalWorkerThread.run(TraditionalWorkerThread.java:122)

      How to reproduce the issue

      1. Deploy AM in Tomcat (I'm using 8.0.30)
      2. Restart the AM application, without restarting the container process
      3. Review Tomcat Logs
      Expected behaviour

      No unterminated thread errors, nor thread local errors, and application restarts.

      Current behaviour

      As well as the stack trace above, many thread locals are complained about, for example:

      05-Sep-2017 22:29:30.744 SEVERE [RMI TCP Connection(8)-127.0.0.1] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [openam] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@3fc9fc22]) and a value of type [org.glassfish.grizzly.ThreadCache.ObjectCache] (value [org.glassfish.grizzly.ThreadCache$ObjectCache@4f5d9dab]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
      

      Also, thread complaints are also seen, e.g.:

      05-Sep-2017 22:36:27.572 WARNING [RMI TCP Connection(2)-127.0.0.1] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [openam] appears to have started a thread named [Monitor Provider State Updater] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
       sun.misc.Unsafe.park(Native Method)
       java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
      amUtil:09/05/2017 10:36:27:561 PM BST: Thread[RMI TCP Connection(2)-127.0.0.1,5,RMI Runtime]: TransactionId[ce1a7e71-9765-4972-ad18-2bddb7c28686-0] ERROR: Error during shutdown
      com.sun.identity.log.AMLogException: amSSO.access:Log write authorization failure
       java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
      	at com.sun.identity.log.Logger.validateLogBy(Logger.java:295)
      	at com.sun.identity.log.Logger.log(Logger.java:367)
       java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
      	at com.sun.identity.log.LogManagerUtil.logEndRecords(LogManagerUtil.java:176)
      	at com.sun.identity.log.LogManagerUtil$1.shutdown(LogManagerUtil.java:75)
       java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
      	at com.sun.identity.common.ShutdownManager.shutdown(ShutdownManager.java:211)
       java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
       java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
      	at com.sun.identity.common.ShutdownServletContextListener.contextDestroyed(ShutdownServletContextListener.java:51)
       java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      	at org.apache.catalina.core.StandardContext.listenerStop(StandardContext.java:4859)
       java.lang.Thread.run(Thread.java:745)
      <snip>
      

      The application then does not restart and instead gets stuck in a loop logging more exceptions every 10 seconds or so.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              jamesphillpotts James Phillpotts
              Reporter:
              jamesphillpotts James Phillpotts
              Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: