节前某个部门的测试环境反馈tomcat会意外退出,我们到实际环境排查后发现不是jvm crash,日志里有进程销毁的记录,从pause到destory的整个过程:
org.apache.coyote.AbstractProtocol pause
Pausing ProtocolHandler
org.apache.catalina.core.StandardService stopInternal
Stopping service Catalina
org.apache.coyote.AbstractProtocol stop
Stopping ProtocolHandler
org.apache.coyote.AbstractProtocol destroy
Destroying ProtocolHandler
从上面日志来可以判断:
1) tomcat不是通过脚本正常关闭(viaport: 即通过8005端口发送shutdown指令)
因为正常关闭(viaport)的话会在 pause 之前有这样的一句warn日志:
org.apache.catalina.core.StandardServer await
A valid shutdown command was received via the shutdown port. Stopping the Server instance.
然后才是 pause -> stop -> destroy
2) tomcat的shutdownhook被触发,执行了销毁逻辑
而这又有两种情况,一是应用代码里有地方用System.exit
来退出jvm,二是系统发的信号(kill -9
除外,SIGKILL信号JVM不会有机会执行shutdownhook)
先通过排查代码,应用方和中间件团队都排查了System.exit
在这个应用中使用的可能。那就只剩下Signal的情况了;经过一番排查后,发现每次tomcat意外退出的时间与ssh会话结束的时间正好吻合。
有了这个线索之后,银时同学立刻看了一下对方测试环境的脚本,简化后如下:
$ cat test.sh
#!/bin/bash
cd /data/server/tomcat/bin/
./catalina.sh start
tail -f /data/server/tomcat/logs/catalina.out
tomcat启动为后,当前shell进程并没有退出,而是挂住在tail进程,往终端输出日志内容。这种情况下,如果用户直接关闭ssh终端的窗口(用鼠标或快捷键),则java进程也会退出。而如果先ctrl-c
终止test.sh进程,然后再关闭ssh终端的话,则java进程不会退出。
这是一个有趣的现象,catalina.sh start
方式启动的tomcat会把java进程挂到init
(进程id为1)的父进程下,已经与当前test.sh
进程脱离了父子关系,也与ssh进程没有关系,为什么关闭ssh终端窗口会导致java进程退出?
我们的推测是ssh窗口在关闭时,对当前交互的shell以及正在运行的test.sh等子进程发送某个退出的Signal,找了一台装有systemtap的机器来验证,所用的stap脚本是从涧泉同学那里copy的:
function time_str: string () {
return ctime(gettimeofday_s() + 8 * 60 * 60);
}
probe begin {
printdln(" ", time_str(), "BEGIN");
}
probe end {
printdln(" ", time_str(), "END");
}
probe signal.send {
if (sig_name == "SIGHUP" || sig_name == "SIGQUIT" ||
sig_name=="SIGINT" || sig_name=="SIGKILL" || sig_name=="SIGABRT") {
printd(" ", time_str(), sig_name, "[", uid(), pid(), cmdline_str(),
"] -> [", task_uid(task), sig_pid, pid_name, "], ");
task = pid2task(pid());
while (task_pid(task) > 0) {
printd(" ", "[", task_uid(task), task_pid(task), task_execname(task), "]");
task = task_parent(task);
}
println("");
}
}
模拟时的进程层级(pstree)大致如下,tomcat启动后java进程已经脱离test.sh,挂在init下:
|-sshd(1622)-+-sshd(11681)---sshd(11699)---bash(11700)---test.sh(13285)---tail(13299)
经过内核组伯俞的协助,我们发现
a) 用 ctrl-c 终止当前test.sh进程时,系统events进程向 java 和 tail 两个进程发送了SIGINT
信号
SIGINT [ 0 11 ] -> [ 0 20629 tail ]
SIGINT [ 0 11 ] -> [ 0 20628 java ]
SIGINT [ 0 11 ] -> [ 0 20615 test.sh ]
注pid 11是events进程
b) 关闭ssh终端窗口时,sshd向下游进程发送SIGHUP
, 为何java进程也会收到?
SIGHUP [ 0 11681 sshd: hongjiang.wanghj [priv] ] -> [ 57316 11700 bash ]
SIGHUP [ 57316 11700 -bash ] -> [ 57316 11700 bash ]
SIGHUP [ 57316 11700 ] -> [ 0 13299 tail ]
SIGHUP [ 57316 11700 ] -> [ 0 13298 java ]
SIGHUP [ 57316 11700 ] -> [ 0 13285 test.sh ]
不过伯俞很忙没有继续协助分析这个问题(他给出了一些猜测,但后来证明并不是那样)。
确定了是由signal引起的之后,我的疑惑变成了:
1) 为什么SIGINT
(kill -2) 不会让tomcat进程退出?
2) 为什么SIGHUP
(kill -1) 会让tomcat进程退出?
我第一反应可能是jvm在某些参数下(或因为某些jni)对os的信号处理会不同,看了一下应用的jvm参数,没有看出问题,也排除了tomcat使用apr/tcnative的情况。
我们看一下默认情况下,jvm进程对SIGINT
和SIGHUP
是怎么处理的,用scala的repl模拟一下:
scala> Runtime.getRuntime