【Tomcat】启停日志--线上Tomcat进程怎么又没有了？

线上Tomcat进程怎么又不见了？

10月5日，作为程序员的你正享受着难得国庆长假，突然项目经理来电，你惊悚的接起电话，电话那头项目经理说：“那个’打羽毛球的码农’啊，怎么生产环境又访问不了啦？”。你心中暗想：“窝草，怎么服务又挂啦。 是我写的程序有问题？还是哪位同仁又杀了我服务的进程？怎么好端端的程序进程就没有了呢？”。
上面这个桥段是不是很熟悉？是不是自己也经常遇到？ 遇到这样的情况，你一般怎么处理与分析呢：最简单最粗暴的处理方式万能的重启服务；第二类是拿到应用日志与Tomcat日志初步分析后重启，一般都能根据Error日志找到原因做代码修整；最可怕的情况是在日志中没有有效Error信息，是不是很懵逼？本文就根据Tomcat的启停日志关键信息，来分析Tomcat进行无故消失的3种情况。

Tomcat8.5正常启动日志[注意日志解释]

Java HotSpot(TM) 64-Bit Server VM warning: ignoring option PermSize=256M; support was removed in 8.0
Java HotSpot(TM) 64-Bit Server VM warning: ignoring option MaxPermSize=256m; support was removed in 8.0
19-Jul-2019 10:57:38.374 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version:        Apache Tomcat/8.5.35
19-Jul-2019 10:57:38.376 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Nov 3 2018 17:39:20 UTC
19-Jul-2019 10:57:38.376 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server number:         8.5.35.0
19-Jul-2019 10:57:38.376 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
19-Jul-2019 10:57:38.376 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            3.10.0-957.1.3.el7.x86_64
19-Jul-2019 10:57:38.376 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
19-Jul-2019 10:57:38.376 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /cloud/server/jdk8/jre
19-Jul-2019 10:57:38.376 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           1.8.0_191-b12
19-Jul-2019 10:57:38.376 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
19-Jul-2019 10:57:38.377 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /cloud/server/tomcat_crm
19-Jul-2019 10:57:38.377 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /cloud/server/tomcat_crm
19-Jul-2019 10:57:38.377 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/cloud/server/tomcat_crm/conf/logging.properties
19-Jul-2019 10:57:38.377 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
19-Jul-2019 10:57:38.377 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xms4096m
19-Jul-2019 10:57:38.377 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xmx4096m
19-Jul-2019 10:57:38.377 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:PermSize=256M
19-Jul-2019 10:57:38.377 INFO [main] ... /**其他JVM启动参数日志MaxPermSize=256m,-Dcatalina.base=/cloud/server/tomcat_crm*/
19-Jul-2019 10:57:38.545 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [...]   /**localhost-startStop-1进程是Tomcat启动和关闭的线程*/
...
19-Jul-2019 10:58:15.355 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [...] has finished in [36,809] ms   /**应用部署完成日志*/
19-Jul-2019 10:58:15.358 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8030"]
19-Jul-2019 10:58:15.378 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 36883 ms /**Tomcat服务启动完成日志*/
2019-07-19 10:58:07,330 [Thread-6] INFO  /**业务进程日志*/
2019-07-19 10:58:19,785 [EventThread] ERROR /**业务进程日志*/

正常关闭Tomcat服务日志[shutdown.sh]

正常命令关闭Tomcat服务，会有“A valid shutdown command was received via the shutdown port. Stopping the Server instance”日志关键信息，如下：

19-Jul-2019 11:15:02.566 INFO [main] org.apache.catalina.core.StandardServer.await A valid shutdown command was received via the shutdown port. Stopping the Server instance.     /**Tomcat收到正常停止服务的命令通知*/
19-Jul-2019 11:15:02.567 INFO [main] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-8030"]
19-Jul-2019 11:15:02.573 INFO [main] org.apache.catalina.core.StandardService.stopInternal Stopping service [Catalina]
19-Jul-2019 11:15:02.629 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesJdbc The web application [chatbot] registered the JDBC driver [com.alibaba.druid.proxy.DruidDriver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.   /**localhost-startStop-2为tomcat关闭服务线程*/
19-Jul-2019 11:15:02.630 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesJdbc The web application [chatbot] registered the JDBC driver [com.mysql.jdbc.Driver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
19-Jul-2019 11:15:02.631 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [chatbot] appears to have started a thread named [Abandoned connection cleanup thread] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread: ...
19-Jul-2019 11:15:02.631 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [chatbot] appears to have started a thread named [Druid-ConnectionPool-Create-1269347162] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread: ...
19-Jul-2019 11:15:02.632 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [chatbot] appears to have started a thread named [Druid-ConnectionPool-Destroy-1269347162] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
19-Jul-2019 11:15:02.637 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [chatbot] appears to have started a thread named [MySQL Statement Cancellation Timer] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
19-Jul-2019 11:15:02.654 INFO [main] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-8030"]
19-Jul-2019 11:15:02.681 INFO [main] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["http-nio-8030"]
19-Jul-2019 11:15:05.387 INFO [Abandoned connection cleanup thread] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load []. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.

kill -9 进程号 关闭Tomcat

这种方式：什么日志都没有! 什么日志都没有! 什么日志都没有!

tomcat的shutdownhook被触发，执行了销毁逻辑

Tomcat使用了关闭钩子来完成退出过程的，在org,apache.catalina.startup.Catalina类中，可以找到这样的代码，Catalina类负责启动管理其他组件的Server对象。一个名为CatalinaShutdownHook的内部类继承自Thread类，提供了run方法的实现，它调用server对象的stop方法，执行关闭操作，当出现如下情况的时候，Tomcat的shutdownhook会被执行:

• 情况1:应用代码里有地方用System.exit来退出jvm
• 情况2:系统发的信号(kill -9除外):一般来自启动Tomcat终端shell命令进程,一旦终端进程结束(会话到期\ctrl+c\关闭窗口),都会因为终端进程结束而触发tomcat的shutdownhook,日志示例如下:

19-Jul-2019 14:23:08.860 INFO [Thread-20] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-8030"]    /**shutdownhook被触发的日志与进程,相比于正常关闭Tomcat,进程号由main变成了Thread-N,更主要特征是没有'A valid shutdown command was received via the shutdown port. Stopping the Server instance'正常关闭信息*/
19-Jul-2019 14:23:08.881 INFO [Thread-20] org.apache.catalina.core.StandardService.stopInternal Stopping service [Catalina]
19-Jul-2019 14:23:08.950 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesJdbc The web application [chatbot] registered the JDBC driver [com.alibaba.druid.proxy.DruidDriver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.    /**localhost-startStop-2为tomcat关闭服务线程*/
19-Jul-2019 14:23:08.950 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesJdbc The web application [chatbot] registered the JDBC driver [com.mysql.jdbc.Driver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
19-Jul-2019 14:23:08.951 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [chatbot] appears to have started a thread named [Abandoned connection cleanup thread] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
19-Jul-2019 14:23:08.952 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [chatbot] appears to have started a thread named [Druid-ConnectionPool-Create-985155300] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
19-Jul-2019 14:23:08.952 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [chatbot] appears to have started a thread named [Druid-ConnectionPool-Destroy-985155300] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
19-Jul-2019 14:23:08.958 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [chatbot] appears to have started a thread named [MySQL Statement Cancellation Timer] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
19-Jul-2019 14:23:08.983 INFO [Thread-20] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-8030"]
19-Jul-2019 14:23:09.042 INFO [Thread-20] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["http-nio-8030"]

有了如上各种情况下Tomcat的日志特征，希望对你日后分析线上问题有帮助。