时间戳

首页 > 技术文章 > Tomcat进程意外退出的问题分析

Tomcat进程意外退出的问题分析

zhangww 2019-05-07 20:00 原文

http://ifeve.com/why-kill-2-cannot-stop-tomcat/?tdsourcetag=s_pctim_aiomsg

tail后关掉客户端

正常执行shutdown.sh

Tomcat进程意外退出的问题分析

测试环境反馈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 -> destory

  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().addShutdownHook(
new Thread() { override def run() { println("ok") } })
对这个java进程分别用kill -2和kill -1发现都会导致jvm进程退出，并且也触发shutdownhook。这也符合oracle对hotspot虚拟机处理Signal的说明，参考这里，SIGTERM,SIGINT,SIGHUP三种信号都会触发shutdownhook

看来并不是jvm的事，继续猜测是否与进程的状态有关？catalina.sh脚本里并没有使用start-stop-daemon之类的方式启动java进程，start参数的执行方式简化后脚本相当于：

eval '"/pathofjdk/bin/java"' 'params' org.apache.catalina.startup.Bootstrap start '&'
就是简单的把java放到后台执行。当catalina.sh自身进程退出后，java进程的ppid变成了1

花了很多的时间猜测可能是OS层面的原因，后来发现并没有关系。春节后回来让少明和涧泉也一起分析这个问题，因为他们有c的背景，对系统底层知道的多一些，用了大半天时间，不断猜测和验证，最后确认了是Shell的原因。

SIGINT (kill -2) 不会让后台java进程退出的原因
为了简便，我们用sleep来模拟进程，当我们在交互模式下：

$ sleep 1000 &

$ ps -opid,pgid,ppid,stat,cmd -C sleep
PID PGID PPID STAT CMD
9897 9897 9813 S sleep 1000
注意，进程sleep 1000的pid与pgid(进程组)是相同的，这时我们用kill -2是可以杀掉sleep 1000进程的。

现在我们把sleep进程放到一个脚本里后台执行：

$ cat a.sh

!/bin/sh

sleep 4400 &
echo "shell exit"
运行a.sh脚本之后，sleep 4400进程的pid与pgid是不同的，pgid是其父进程的id，即已经退出了的a.sh进程

$ ps -opid,pgid,ppid,comm -p 63376
PID PGID PPID COMM
63376 63375 1 sleep
这时我们用kill -2是杀不掉sleep 4400进程的。

到了这一步，已经非常接近原因了，一定是shell对后台进程signal_handler做了什么手脚。少明实现了一个自定handler的命令看看是否对kill -2有效：

include <stdio.h>

include <signal.h>

include <stdlib.h>

void my_handler(int sig) {
printf("handler aaa\n");
exit(0);
}

int main() {
signal(SIGINT, my_handler);
for(;

推荐阅读