Solutions

Error during shutdown message when stopping an AM 6 instance running on Apache Tomcat

Last updated Jul 9, 2018

The purpose of this article is to provide assistance if you encounter an "Error during shutdown" message when stopping an AM instance running on Apache Tomcat™. This is an intermittent issue.


Symptoms

The AM instance is not fully shut down after issuing the shutdown command. You can observe this using the ps command, which will show the process is still running. See How do I check if AM/OpenAM (All versions) is up and running? for further information.

The following error is shown in the CoreSystem debug log when this happens:

SystemTimer:05/08/2018 11:50:07:525 PM BST: Thread[localhost-startStop-2,5,main]: TransactionId[ec243db4-0458-4907-a387-9ef923cf96d0-1188]
ERROR: TimerPool:shutdown() terminating remaining worker thread[189]
amUtil:05/08/2018 11:50:08:461 PM BST: Thread[localhost-startStop-2,5,main]: TransactionId[ec243db4-0458-4907-a387-9ef923cf96d0-1188]
ERROR: Error during shutdown
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@6566ca14 rejected from java.util.concurrent.ThreadPoolExecutor@146e55b4[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 2446]
   at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2047)
   at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:823)
   at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1369)
   at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112)
   at org.forgerock.openam.audit.context.AuditRequestContextPropagatingExecutorService.submit(AuditRequestContextPropagatingExecutorService.java:111)
   at com.iplanet.dpro.session.monitoring.SessionMonitoringStore.storeRefreshTime(SessionMonitoringStore.java:90)
   at com.iplanet.dpro.session.monitoring.MonitoredOperations.refresh(MonitoredOperations.java:84)
   at com.iplanet.dpro.session.service.SessionService.refresh(SessionService.java:339)
   at com.iplanet.sso.providers.dpro.SSOProviderImpl.isValidToken(SSOProviderImpl.java:264)
   at com.iplanet.sso.SSOTokenManager.isValidToken(SSOTokenManager.java:459)
   at com.iplanet.sso.SSOTokenManager.isValidToken(SSOTokenManager.java:444)
   at com.sun.identity.security.AdminTokenAction.run(AdminTokenAction.java:186)
   at com.sun.identity.security.AdminTokenAction.run(AdminTokenAction.java:67)
   at java.security.AccessController.doPrivileged(Native Method)
   at com.sun.identity.idm.plugins.internal.SpecialRepo.removeListener(SpecialRepo.java:526)
   at com.sun.identity.idm.server.IdRepoPluginsCache.clearIdRepoPluginsCache(IdRepoPluginsCache.java:318)
   at com.sun.identity.idm.server.IdServicesImpl.clearIdRepoPlugins(IdServicesImpl.java:2592)
   at com.sun.identity.idm.server.IdCachedServicesImpl$1.shutdown(IdCachedServicesImpl.java:153)
   at com.sun.identity.common.ShutdownManager.shutdown(ShutdownManager.java:217)
   at com.sun.identity.common.ShutdownServletContextListener.contextDestroyed(ShutdownServletContextListener.java:51)
   at org.apache.catalina.core.StandardContext.listenerStop(StandardContext.java:4837)
   at org.apache.catalina.core.StandardContext.stopInternal(StandardContext.java:5484)
   at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:232)
   at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1575)
   at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1564)
   at java.util.concurrent.FutureTask.run(FutureTask.java:266)
   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
   at java.lang.Thread.run(Thread.java:745)

The following messages are shown in catalina.out:

May 08, 2018 11:50:07 PM org.apache.catalina.core.StandardServer await
INFO: A valid shutdown command was received via the shutdown port. Stopping the Server instance.
May 08, 2018 11:50:07 PM org.apache.coyote.AbstractProtocol pause
INFO: Pausing ProtocolHandler ["http-bio-28080"]
May 08, 2018 11:50:07 PM org.apache.coyote.AbstractProtocol pause
INFO: Pausing ProtocolHandler ["ajp-bio-28009"]
May 08, 2018 11:50:07 PM org.apache.catalina.core.StandardService stopInternal
INFO: Stopping service Catalina
May 08, 2018 11:50:08 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [/openam] appears to have started a thread named [RxSchedulerPurge-1] but has failed to stop it. This is very likely to create a memory leak.
May 08, 2018 11:50:08 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [/openam] appears to have started a thread named [RxCachedWorkerPoolEvictor-1] but has failed to stop it. This is very likely to create a memory leak.
May 08, 2018 11:50:08 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [/openam] appears to have started a thread named [OpenDJ LDAP SDK Default Scheduler] but has failed to stop it. This is very likely to create a memory leak.
...

If you restart the instance, the browser will show a Loading... message and you will be unable to use the console.

Recent Changes

Shut down an AM 6 instance.

Causes

Threads not being terminated upon shutdown is a known issue: OPENAM-13008 (Occasional shutdown error for AM).

Solution

This issue can be resolved by upgrading to AM 6.0.0.1 or later; you can download this from BackStage.

Workaround

You can workaround this issue using one of the following options:

  • Forcibly end process using kill -9
  • Define CATALINA_PID environment variable to issue kill -9  only if needed

Forcibly end process

  1. Identify the process ID using the following command:
    $ ps –ef |grep tomcat
    Example response, where process ID is 2240:
    forgero+  2240     1  3 10:34 pts/1    00:01:31 /usr/lib/jvm/java-8-oracle/bin/java -Djava.util.logging.config.file=/opt/tomcat/am6/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Xms2048m -Xmx2048m -XX:MaxPermSize=512m -Xss256k -XX:+UseParallelGC -XX:MaxGCPauseMillis=1500 -XX:GCTimeRatio=9 -server -XX:+DisableExplicitGC -Djava.endorsed.dirs=/opt/tomcat/am6/endorsed -classpath /opt/tomcat/am6/bin/bootstrap.jar:/opt/tomcat/am6/bin/tomcat-juli.jar -Dcatalina.base=/opt/tomcat/am6 -Dcatalina.home=/opt/tomcat/am6 -Djava.io.tmpdir=/opt/tomcat/am6/temp org.apache.catalina.startup.Bootstrap start
    forgero+  2966  2193  0 11:14 pts/1    00:00:00 grep --color=auto tomcat
  2. End the process using the following command and the identified process ID, for example:
    $ kill -9 2240 
  3. Repeat step 2 if more than one process is running for the AM instance you are trying to shut down (this can happen if you started and stopped the instance again).

You can now restart the AM instance successfully.

Define CATALINA_PID environment variable

You can configure Tomcat to mitigate this issue in the future by defining the CATALINA_PID environment variable in the setenv.sh file (typically located in the /tomcat/bin/ directory). If this file doesn't exist, you should create it in the same directory as the catalina.sh file (also typically located in the /tomcat/bin/ directory). 

  1. End the process if it is still running using the steps above (identify process ID and use kill -9).
  2. Add the following line to the setenv.sh file:
    CATALINA_PID="$CATALINA_BASE/bin/catalina.pid"
  3. Restart the web container.

You can now shut down AM 6 instances by appending the shutdown command with -force, which issues a kill -9 command for the relevant process after 5 seconds if it has not shutdown cleanly. For example:

$ ./shutdown.sh -force

See Also

Best practice for upgrading to AM 6.x

Related Training

N/A

Related Issue Tracker IDs

OPENAM-13008 (Occasional shutdown error for AM)



Copyright and TrademarksCopyright © 2018 ForgeRock, all rights reserved.
Loading...