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

Last updated Jan 12, 2023

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 (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 AM admin UI.

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

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
End the process using the following command and the identified process ID, for example: $ kill -9 2240
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).

End the process if it is still running using the steps above (identify process ID and use kill -9).
Add the following line to the setenv.sh file: CATALINA_PID="$CATALINA_BASE/bin/catalina.pid"
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

Related Training

N/A

Related Issue Tracker IDs

OPENAM-13008 (Occasional shutdown error for AM)