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(;;) { }
return 0;
}
我們把編譯後的a.out命令在腳本里以後臺方式執行:
$ cat a.sh
#!/bin/sh
/tmp/a.out &
這次再嘗試用kill -2
去殺a.out程序,是可以的。這說明shell對signal_handler
做手腳是在執行使用者邏輯之前,也就是指令碼在fork出子程序的時候就設定了。按照這個線索我們google後瞭解到: shell在非互動模式下對後臺程序處理SIGINT
訊號時設定的是IGNORE
。
互動模式與非互動模式對作業控制(job control)預設方式不同
為什麼在互動模式下shell不會對後臺程序處理SIGINT
訊號設定為忽略,而非互動模式下會設定為忽略呢?還是比較好理解的,舉例來說,我們先某個前臺程序執行時間太長,可以ctrl-z
中止一下,然後通過bg %n
把這個程序放入後臺,同樣也可以把一個cmd &
方式啟動的後臺程序,通過fg %n
放回前臺,然後在ctrl-c
停止它,當然不能忽略SIGINT
。
為何互動模式下的後臺程序會設定一個自己的程序組ID呢?因為預設如果採用父程序的程序組ID,父程序會把收到的鍵盤事件比如ctrl-c
之類的SIGINT
傳播給程序組中的每個成員,假設後臺程序也是父程序組的成員,因為作業控制的需要不能忽略SIGINT
,你在終端隨意ctrl-c
就可能導致所有的後臺程序退出,顯然這樣是不合理的;所以為了避免這種干擾後臺程序設定為自己的pgid。
而非互動模式下,通常是不需要作業控制的,所以作業控制在非互動模式下預設也是關閉的(當然也可以在腳本里通過選項set -m
開啟作業控制選項)。不開啟作業控制的話,腳本里的後臺程序可以通過設定忽略SIGINT
訊號來避免父程序對組中成員的傳播,因為對它來說這個訊號已經沒有意義。
回到tomcat的例子,catalina.sh指令碼通過start引數啟動的時候,就是以非互動方式後臺啟動,java程序也被shell設定了忽略SIGINT
訊號,因此在ctrl-c
結束test.sh程序時,系統傳送的SIGINT
對java沒有影響。
SIGHUP
(kill -1) 讓tomcat程序退出的原因
在非互動模式下,shell對java程序設定了SIGINT
,SIGQUIT
訊號設定了忽略,但並沒有對SIGHUP
訊號設為忽略。再看一下當時的程序層級:
|-sshd(1622)-+-sshd(11681)---sshd(11699)---bash(11700)---test.sh(13285)---tail(13299)
sshd把SIGHUP
傳遞給bash程序後,bash會把SIGHUP
傳遞給它的子程序,並且對於其子程序test.sh,bash還會對test.sh的程序組裡的成員都傳播一遍SIGHUP
。因為java後臺程序從父程序catalina.sh(又是從其父程序test.sh)繼承的pgid,所以java程序仍屬於test.sh程序組裡的成員,收到SIGHUP
後退出。
如果我們在test.sh裡設定開啟作業控制的話,就不會讓java程序退出了
#!/bin/bash
set -m
cd /home/admin/tt/tomcat/bin/
./catalina.sh start
tail -f /home/admin/tt/tomcat/logs/catalina.out
此時java後臺程序繼承父程序catalina.sh的pgid,而catalina.sh不再使用test.sh的程序組,而是自己的pid作為pgid,catalina.sh程序在執行完退出後,java程序掛到了init下,java與test.sh程序就完全脫離關係了,bash也不會再向它傳送訊號。