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

Occasional shutdown error for AM

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 6.0.0
    • Fix Version/s: 13.5.3, 6.0.0.1, 6.5.0, 6.0.1, 5.5.2
    • Component/s: None
    • Labels:
    • Environment:
      Linux CentOS, selinux enabled (enforcing), two AM server instances as a site, communicating to local external DS config store and separate backend in same DS for user repo.
    • Needs backport:
      Yes
    • Needs QA verification:
      No
    • Functional tests:
      No
    • Are the reproduction steps defined?:
      Yes but I used my own steps. (If so, please add them in a new comment)

      Description

      Bug description

      On performing shutdown of a site of two A instances, one of the tomcat instance still showing as a running process. 'Error during shutdown' message appears in debug CoreSystem log.

      How to reproduce the issue

      1. Deployed two AM instances, latest master 6.0.0 build git fetched as of Apr 26th, approx 7.30am PDT
      2. Setup first server as a site, cookie domain amtest2.com, server url instance http://idp.amtest2.com:9080/access, site url instance http://site.amtest2.com:80/access and site name of testsite (served by HAProxy, running on same machine)
      3. Setup second server as a site, cookie domain as above, server url of http://sp.amtest2.com:7080/access
      4. In top level realm, added policyset TestApplication01, and Policy TestPolicy01 with resource http://web.amtest2.com:80/test1/. .  Created a user, testuser100, granted allow access for GETs and POSTs.
      5. Used curl command policy evaluation query (see example below) to query policy and verify I saw actions GET and POST in response.
        • curl -k --request POST --header "Content-Type: application/json" --header 'Accept-API-Version: protocol=1.0,resource=2.0' --header "iPlanetDirectoryPro: _jwRa4qE7HiwmWgwTrwZVrH4QW0.AAJTSQACMDIAAlNLABxXcUs3ZTNrSlpXSGpOMlBxQzd0bHIrWjZhdzA9AAR0eXBlAANDVFMAAlMxAAIwMw.." --data '{"resources":["http://web.amtest2.com:80/test1/index.html"],"subject": {"ssoToken": "2kzNHOkmPZMMLvkN9IuYU1KKG50.AAJTSQACMDIAAlNLABxYdUZzOEZvcWIrbnZLZ0VtcTJQTGlsQmR5d3c9AAR0eXBlAANDVFMAAlMxAAIwMw.."},"application":"TestApplication01"}' 'http://sp.amtest2.com:7080/access/json/policies?_action=evaluate'
      6. Stop the external DJ server hosting the config.  Restart it and then repeat the above.
      7. From server 1 (idp) add an additional resource http://web.amtest2:80/test2/. and save changes and then perform policy evaluation for that.  I repeat the original reported issue for OPENAM-12419 by doing so.
      8. Shutdown both tomcat instances using /opt/tomcat-idp/apache-tomcat-7.0.82/bin/shutdown.sh, then /opt/tomcat-sp/apache-tomcat-7.0.82/bin/shutdown.sh.  Always the same order.
      9. Run ps -ef | grep tomcat.

      Note have also seen same behaviour when just starting servers, leaving running for a period of time, no activity and then performing shutdown command.  This is less reliable though, doesn't always result in one server being left as a process.  Above detailed process seems to be more reliable in producing the current behaviour for one of the servers each time I stop them (and it can be either server).   From additional testing, reliability of reproducing issue seems to increase if changes are made to a policy (adding or removing more than one resource rule) and then saving.

      Have also seen same behaviour once for just a single server deployed with an external config store.  Have not tried to reproduce with an embedded config store.

      Expected behaviour
      Shutdown should halt the tomcat process
      Current behaviour
      One of the server instances (idp or sp) seems to remain (at least partly) running.  ps -ef | grep tomcat still shows it present.  
      
      In CoreSystem debug logs, see the following:
      
      SystemTimer:04/26/2018 10:16:08:705 AM PDT: Thread[localhost-startStop-2,5,main]: TransactionId[48438c16-2b42-4394-b601-881facdc28c3-108]
      ERROR: TimerPool:shutdown() terminating remaining worker thread[28]
      amUtil:04/26/2018 10:16:08:726 AM PDT: Thread[localhost-startStop-2,5,main]: TransactionId[48438c16-2b42-4394-b601-881facdc28c3-108]
      ERROR: Error during shutdown
      java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@1768875f rejected from java.util.concurrent.ThreadPoolExecutor@50cf0f16[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 2042]
      at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063)
      at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830)
      at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379)
      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:5157)
      at org.apache.catalina.core.StandardContext.stopInternal(StandardContext.java:5830)
      at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:221)
      at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1716)
      at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1705)
      at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
      at java.lang.Thread.run(Thread.java:748)

      Work around

      kill -9 <pid> removes the process so that I can then restart the server instance.

       

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                ken.stubbings Ken Stubbings
                Reporter:
                lawrence.yarham Lawrence Yarham
              • Votes:
                0 Vote for this issue
                Watchers:
                8 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: