Uploaded image for project: 'camunda BPM'
  1. camunda BPM
  2. CAM-9459

Camunda Hangs Indefinitely on Tomcat Shutdown

XMLWordPrintable

    • Icon: Bug Report Bug Report
    • Resolution: Won't Fix
    • Icon: L3 - Default L3 - Default
    • None
    • 7.7.0
    • None
    • None

      We are running Camunda on Apache Tomcat/8.0.37 (Java 1.8.0_131-b11) with Oracle 12.1c

      We have sporadically observed the following behavior (without being able to reproduce it reliably):

      Tomcat fails to shut down, apparently working heavily for an indefinite time (more than 12 hours). We have not observed this state to end naturally, and we ended up killing the process in all cases.

      We observe the following thread being busy:
      "Thread-13" - Thread t@4646
      java.lang.Thread.State: RUNNABLE
      at org.camunda.bpm.engine.impl.persistence.entity.HistoricDetailManager.deleteHistoricDetailsByProcessCaseInstanceId(HistoricDetailManager.java:95)
      at org.camunda.bpm.engine.impl.persistence.entity.HistoricDetailManager.deleteHistoricDetailsByProcessInstanceId(HistoricDetailManager.java:34)
      at org.camunda.bpm.engine.impl.persistence.entity.HistoricProcessInstanceManager.deleteHistoricProcessInstanceById(HistoricProcessInstanceManager.java:65)
      at org.camunda.bpm.engine.impl.persistence.entity.HistoricProcessInstanceManager.deleteHistoricProcessInstanceByProcessDefinitionId(HistoricProcessInstanceManager.java:56)
      at org.camunda.bpm.engine.impl.persistence.entity.ExecutionManager.deleteProcessInstancesByProcessDefinition(ExecutionManager.java:63)
      at org.camunda.bpm.engine.impl.persistence.entity.DeploymentManager.deleteDeployment(DeploymentManager.java:85)
      at org.camunda.bpm.engine.impl.cmd.DeleteDeploymentCmd.execute(DeleteDeploymentCmd.java:70)
      at org.camunda.bpm.engine.impl.cmd.DeleteDeploymentCmd.execute(DeleteDeploymentCmd.java:40)
      at org.camunda.bpm.engine.impl.interceptor.CommandExecutorImpl.execute(CommandExecutorImpl.java:24)
      at org.camunda.bpm.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:104)
      at org.camunda.bpm.engine.impl.interceptor.ProcessApplicationContextInterceptor.execute(ProcessApplicationContextInterceptor.java:66)
      at org.camunda.bpm.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:30)
      at org.camunda.bpm.engine.impl.RepositoryServiceImpl.deleteDeployment(RepositoryServiceImpl.java:115)
      at org.camunda.bpm.container.impl.deployment.UndeployProcessArchiveStep.deleteDeployment(UndeployProcessArchiveStep.java:74)
      at org.camunda.bpm.container.impl.deployment.UndeployProcessArchiveStep.performOperationStep(UndeployProcessArchiveStep.java:67)
      at org.camunda.bpm.container.impl.spi.DeploymentOperation.execute(DeploymentOperation.java:116)
      at org.camunda.bpm.container.impl.jmx.MBeanServiceContainer.executeDeploymentOperation(MBeanServiceContainer.java:156)
      at org.camunda.bpm.container.impl.spi.DeploymentOperation$DeploymentOperationBuilder.execute(DeploymentOperation.java:212)
      at org.camunda.bpm.container.impl.RuntimeContainerDelegateImpl.undeployProcessApplication(RuntimeContainerDelegateImpl.java:117)
      at org.camunda.bpm.application.AbstractProcessApplication.undeploy(AbstractProcessApplication.java:69)
      at org.camunda.bpm.container.impl.deployment.StopProcessApplicationsStep.stopProcessApplication(StopProcessApplicationsStep.java:64)
      at org.camunda.bpm.container.impl.deployment.StopProcessApplicationsStep.performOperationStep(StopProcessApplicationsStep.java:47)
      at org.camunda.bpm.container.impl.spi.DeploymentOperation.execute(DeploymentOperation.java:116)
      at org.camunda.bpm.container.impl.jmx.MBeanServiceContainer.executeDeploymentOperation(MBeanServiceContainer.java:156)
      at org.camunda.bpm.container.impl.spi.DeploymentOperation$DeploymentOperationBuilder.execute(DeploymentOperation.java:212)
      at org.camunda.bpm.container.impl.tomcat.TomcatBpmPlatformBootstrap.undeployBpmPlatform(TomcatBpmPlatformBootstrap.java:90)
      at org.camunda.bpm.container.impl.tomcat.TomcatBpmPlatformBootstrap.lifecycleEvent(TomcatBpmPlatformBootstrap.java:62)
      at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:95)
      at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:90)
      at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:388)

      • locked <4eaf3684> (a org.apache.catalina.core.StandardServer)
        at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:333)
      • locked <4eaf3684> (a org.apache.catalina.core.StandardServer)
        at org.apache.catalina.core.StandardServer.stopInternal(StandardServer.java:803)
        at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:221)
      • locked <4eaf3684> (a org.apache.catalina.core.StandardServer)
        at org.apache.catalina.startup.Catalina.stopServer(Catalina.java:440)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at org.apache.catalina.startup.Bootstrap.stopServer(Bootstrap.java:400)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:487)

      We believe the following parts of the log may be relevant in some way:

      02-Oct-2018 10:28:58.173 INFO [Thread-8] org.camunda.commons.logging.BaseLogger.logInfo ENGINE-14015 Shutting down the JobExecutor[org.camunda.bpm.engine.impl.jobexecutor.RuntimeContainerJobExecutor]
      02-Oct-2018 10:28:58.188 FINE [Thread-8] org.apache.ibatis.transaction.jdbc.JdbcTransaction.openConnection Opening JDBC Connection
      02-Oct-2018 10:28:58.188 FINE [Thread-8] org.apache.ibatis.transaction.jdbc.JdbcTransaction.setDesiredAutoCommit Setting autocommit to false on JDBC Connection [ProxyConnection[PooledConnection[oracle.jdbc.driver.T4CConnection@7e8dcdaa]]]
      02-Oct-2018 10:28:58.188 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Preparing: select * from ( select a., ROWNUM rnum from ( select distinct RES. from ACT_RE_PROCDEF RES WHERE RES.DEPLOYMENT_ID_ = ? order by RES.ID_ asc ) a where ROWNUM < ?) where rnum >= ?
      02-Oct-2018 10:28:58.188 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Parameters: b7d695ad-ba55-11e8-8cda-0050568790da(String), 2147483647(Integer), 1(Integer)
      02-Oct-2018 10:28:58.204 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug <== Total: 34
      [...]
      02-Oct-2018 10:28:59.095 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Preparing: select * from ACT_RE_PROCDEF where DEPLOYMENT_ID_ = ?
      02-Oct-2018 10:28:59.095 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Parameters: b7d695ad-ba55-11e8-8cda-0050568790da(String)
      02-Oct-2018 10:28:59.095 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug <== Total: 34
      [...]
      02-Oct-2018 10:30:41.260 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Preparing: select ID_ from ACT_RU_EXECUTION where PROC_DEF_ID_ = ? and PARENT_ID_ is null
      02-Oct-2018 10:30:41.260 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Parameters: execute_single_plugin:1:b897c22e-ba55-11e8-8cda-0050568790da(String)
      02-Oct-2018 10:30:41.276 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug <== Total: 0
      [...]

      (Some of the queries will produce results with more than 200k rows):

      02-Oct-2018 10:30:41.276 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Preparing: select ID_ from ACT_HI_PROCINST where PROC_DEF_ID_ = ?
      02-Oct-2018 10:30:41.276 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Parameters: execute_single_plugin:1:b897c22e-ba55-11e8-8cda-0050568790da(String)
      02-Oct-2018 10:30:54.807 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug <== Total: 226716

      (Some of the queries below cause full table scans on some of the history tables, apparently running more or less for ever: )

      02-Oct-2018 10:30:54.838 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Preparing: select * from ACT_HI_DETAIL where PROC_INST_ID_ = ?
      02-Oct-2018 10:30:54.838 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Parameters: bc30f984-ba56-11e8-8cda-0050568790da(String)
      02-Oct-2018 10:30:54.838 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug <== Total: 26
      02-Oct-2018 10:30:54.838 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Preparing: select * from ACT_GE_BYTEARRAY where ID_ = ?
      02-Oct-2018 10:30:54.838 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Parameters: bc30f9a7-ba56-11e8-8cda-0050568790da(String)
      02-Oct-2018 10:30:54.854 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug <== Total: 1
      [...]
      02-Oct-2018 10:30:54.901 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Preparing: select * from ACT_HI_VARINST where PROC_INST_ID_ = ?
      02-Oct-2018 10:30:54.901 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Parameters: bc30f984-ba56-11e8-8cda-0050568790da(String)
      02-Oct-2018 10:30:54.901 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug <== Total: 26
      02-Oct-2018 10:30:54.901 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Preparing: select * from ACT_GE_BYTEARRAY where ID_ = ?
      02-Oct-2018 10:30:54.901 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Parameters: bc30f9b3-ba56-11e8-8cda-0050568790da(String)
      02-Oct-2018 10:30:54.901 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug <== Total: 1
      [...]
      02-Oct-2018 10:30:54.932 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Preparing: select ID_ from ACT_HI_TASKINST WHERE PROC_INST_ID_ = ?
      02-Oct-2018 10:30:54.932 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Parameters: bc30f984-ba56-11e8-8cda-0050568790da(String)
      02-Oct-2018 10:30:54.932 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug <== Total: 0
      [...]
      02-Oct-2018 10:30:54.932 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Preparing: select * from ACT_HI_DETAIL where PROC_INST_ID_ = ?
      02-Oct-2018 10:30:54.932 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug ==> Parameters: bdc66717-ba56-11e8-8cda-0050568790da(String)
      02-Oct-2018 10:30:54.948 FINE [Thread-8] org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug <== Total: 26
      [...........................]

        This is the controller panel for Smart Panels app

              Unassigned Unassigned
              Christoph.Charlet@ecb.europa.eu Christoph Charlet
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Created:
                Updated:
                Resolved: