当前位置 博文首页 > 闫玉林的博客:spring cloud服务tomcat异常关闭,排查及解决awai

    闫玉林的博客:spring cloud服务tomcat异常关闭,排查及解决awai

    作者:[db:作者] 时间:2021-08-29 16:11

    问题及现象

    • tomcat异常关闭,服务从注册中心移除
    • 为了可用性,在2台服务器各部署了这个应用,结果2个都会出现异常关闭现象
    • 2台服务器上的应用,有时候只有一台服务被终止,有时候2台都被终止
    • 追踪日志,就是tomcat自己把一个个中间件关闭,然后自己关闭,例如MySQL、Redis、elasticsearch、mq等

    曲折的排查过程

    • 一开始怀疑代码问题,重新找了新服务器,配置都几乎是一样的,把tomcat拷贝过去,应用代码也一并拷贝过去,保证代码一致。但是很奇怪,服务正常运行了几天,都没问题。期间,另外生产上的那2台,还是挂了几次。幸好不是2台一起挂,暂不影响服务提供。
    • 后来怀疑是偶发的高并发,导致服务不可用。找测试专门做了压测,竟然没问题。虽然某2个接口,返回超时,但整体服务是可用的,tomcat也没有异常关闭。
    • 接着怀疑Spring boot的健康检查,因为服务停止时从Eureka注册中心移除了。Spring boot框架自带应用监控,会对应用的一些监控端点进行检查,如DB、redis等,在应用的安全检查时,如果某项不可用,变成DOWN状态,这个应用服务整个会变成down,会从注册中心里移除这个服务。但是仔细看了下,我们没有启用这个。
    • 后面,前台服务赶上被扫描,大批量访问,导致数据库连接池爆了,服务不可用,但并没有异常关闭,证实了不是这个原因。
    • 最终2台又一起挂了(其实是先后挂的),客户那边发火了。不处理不行了,必须彻底解决这个问题。我看了,tomcat异常关闭,是整个进程都死掉了,不是假死进程还在的情况。但是还是没找到原因,先应急再处理。
    • 只好又加了一台服务器部署应用,3台一起提供服务。并写了个服务监控重启脚本,使用Linux的定时器crontab,每分钟检测一次,如果服务死了,就重启。这样只要不是3台服务在1分钟内同时挂掉,就没问题。
    • 最终还是要看日志啊,再次把tomcat异常关闭的catalina.out日志翻出来,异常关闭附近的一行行的看。然后把一个正常运行的服务,使用tomcat的shutdown命令关闭一次记录日志。又使用Linux的kill(-9)命令杀掉一个正常的服务。对比这3个日志,kill时Catalina是没日志的,对比另外2个,发现绝大多数都相同,关闭一个个中间件(MySQL、redis等),状态变为DOWN等。但是,还是有一点不同的。关键是这一句,shutdown命令执行时是没有输出的org.apache.catalina.core.StandardServer.await A valid shutdown command was received via the shutdown port. Stopping the Server instance.拿着这个百度,果然找到了。下面是异常关闭时的关键部分日志。
    25-Dec-2019 13:40:15.965 信息 [main] org.apache.catalina.core.StandardServer.await A valid shutdown command was received via the shutdown port. Stopping the Server instance.
    25-Dec-2019 13:40:15.966 信息 [main] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-8081"]
    25-Dec-2019 13:40:15.972 信息 [main] org.apache.catalina.core.StandardService.stopInternal Stopping service [Catalina]
    2019-12-25 13:40:15  INFO [localhost-startStop-2] (AbstractApplicationContext.java:1006) - Closing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@146edeec: startup date [Wed Dec 25 09:00:55 GMT+08:00 2019]; parent: org.springframework.context.annotation.AnnotationConfigApplicationContext@7353390
    2019-12-25 13:40:15  INFO [localhost-startStop-2] (EurekaServiceRegistry.java:65) - Unregistering application STATIC-CENTER with eureka with status DOWN
    2019-12-25 13:40:15  WARN [localhost-startStop-2] (DiscoveryClient.java:1297) - Saw local status change event StatusChangeEvent [timestamp=1577252415987, current=DOWN, previous=UP]
    2019-12-25 13:40:15  INFO [DiscoveryClient-InstanceInfoReplicator-0] (DiscoveryClient.java:826) - DiscoveryClient_STATIC-CENTER/172.30.52.240:static-center:8081: registering service...
    2019-12-25 13:40:15  INFO [DiscoveryClient-InstanceInfoReplicator-0] (DiscoveryClient.java:835) - DiscoveryClient_STATIC-CENTER/172.30.52.240:static-center:8081 - registration status: 204
    2019-12-25 13:40:15  INFO [localhost-startStop-2] (DefaultLifecycleProcessor.java:369) - Stopping beans in phase 2147483647
    2019-12-25 13:40:15  INFO [localhost-startStop-2] (QuartzScheduler.java:585) - Scheduler quartzScheduler_$_NON_CLUSTERED paused.
    2019-12-25 13:40:21
    Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.161-b12 mixed mode):
    

    解决方法

    • 既然别人也遇到过,并写成博客了,那肯定能解决。开始一篇篇的去翻,去对照自己的情况。
    • 回想一下,确实是shell脚本的问题。几乎同样的环境和完全相同的代码,使用tomcat的启动命令,在控制台直接启动没问题,也不会异常关闭。使用事先写好的shell脚本同步代码重启的,过了一段时间就自动异常关闭了。
    • 参考找到的博客,里面的前辈也做了比较详细的实验,由于本人对Linux系统和shell脚本没有那么深入的了解,看懂了大概。意识是,使用shell脚本重启tomcat服务时,此Java进程的父进程ID为1,当服务器运行一段时间后,进程使用完了从头开始杀死无用的进程,把1杀死后,它的子进程(包含此Java进程)也会被杀死。然后系统给了tomcat一个指令,告诉你你要死了,tomcat开始一个个断开连接,关闭自己。
    • 最终方法是,需要在shell脚本里添加作业控制(set -m),就可以避免这种异常关闭。暂时还没深入研究,有兴趣或有这方面经验的可以看下(下面有我参考的博客地址)。业有专攻,有错漏之处请指出。

    参考

    • http://ifeve.com/why-kill-2-cannot-stop-tomcat/
    • https://blog.csdn.net/zhouyannian1988/article/details/53508689
    cs