天天看點

程序無故消失的破案曆程

概述

前段時間公司有個系統的程序老是無故退出,在客戶那邊好好的,在家裡伺服器上老是出現,而且出現的時間也沒啥規律,當然最終查出來還是有規律的,不過這個規律比較特别。大家看了後面的内容之後就明白了,真的很特殊!

初步分析 程序Crash?

當同僚找到我的時候,我第一反應是是不是程序Crash了,如果是crash,那通常情況下會有crash的日志,檢查了一遍,什麼日志都沒有留下,當然有時候Crash了,JVM也确實也不會留下Crash日志,不過這個特别罕見了,絕大部分是人為操作了。

被OS Kill?

既然不是Crash,那是不是系統存在記憶體洩露,被OS Kill了,不過很快通過dmesg也排除了,因為沒有看到任何kill的迹象。

System.exit?

排除掉以上兩個因素之後,接着馬上就懷疑是否有什麼代碼執行過System.exit,于是重新編譯了一把JDK,在System的exit方法處列印了些日志,于是坐等奇迹的發生。

令人興奮的是,程序真的消失了,可是令人遺憾的是,我們埋點的日志并沒有出現。這讓我再次陷入沉思。

回歸源碼

從日志看确實是調用了ShutdownHook

程式無故消失的破案曆程

于是找到addShutdownHook源碼的位置

程式無故消失的破案曆程

再次翻了一下JDK的源碼,除了正常退出,System.exit等之外還有哪些情況會調用這個Shutdown的Hook,于是将埋點埋到了Shutdown.runHooks方法裡。

程式無故消失的破案曆程

繼續等待事情再次發生,果然沒多久,當天下午又發生了,列印了如下日志

程式無故消失的破案曆程

也就是說當時是收到了一個SIGHUP的信号,這個信号最終會讓程序退出,JVM對這個信号确實是沒有特殊處理的,是以沒有我們看到的Crash日志。

那接下來就是要找到為什麼會收到這個信号了,這個信号又是誰發出的。

找出信号源

SIGHUP這個信号,最主要發生的場景是Shell終端關閉一個Session的時候會對該Session關聯的程序發送一個SIGHUP信号,這個信号預設是會退出程序的。為此我還特地下載下傳了ITerm2(我和同僚都是mac,用的iTerm2的終端)的源碼,還真找到了幾個發送SIGHUP信号的代碼

程式無故消失的破案曆程

看名字PTYTask就能猜到了,這應該是一個seesion任務,于是進到代碼裡看到主要是有兩個方法有發送SIGHUP信号給子程序,分别是dealloc和stop,其中stop會通過sendSignal函數給子程序發送SIGHUP信号。

程式無故消失的破案曆程

對于我這種比較喜歡自虐的人,一般會想怎麼就确定這個就是我要找的代碼,之前從沒有寫過Object-C的代碼,想着是否有個類似java的jmap的工具可以讓我看記憶體裡的對象的情況,然而臨時沒找到,不過偶然發現mac自帶的Activity工具就能看到一些迹象,于是在Activity裡找到了iTerm2程序,然後對其記憶體資料進行了采樣,看能否抓到類似PTYTask. dealloc或者stop的調用棧,可是比較難模拟,因為存在時間差,點選采樣的時候,很快就結束了,我還沒來得及關閉session。在看采樣報告的時候偶然看到了/usr/bin/sample的指令,原來Activity是采用這個指令進行采樣的,于是摸索了一把,真能搞起來,采樣的時間可以自定義,間隔是1ms一次,這樣可以讓我有充足的時間來操作了,于是在采樣開啟之後,不斷地開一個session,起一個程序,然後close,重複做了好幾次,結束采樣之後看采樣的輸出,還真的就抓到了PTYTask.stop的調用棧

程式無故消失的破案曆程

這也就驗證了我close session的時候确實會給對應的子程序發送SIGHUP的信号。

那到此為止我們可以确認的是

  • 程序退出是因為收到了信号SIGHUP
  • 而SIGHUP的發生是因為終端Session Close

    那到底是不是這種情況呢?

重新複盤問題現場

這個貌似不太可能,因為我們的shell腳本裡執行java的時候都會帶上&,這樣程序就會背景運作,不會出現這種session的問題。看了下腳本,确實是帶上了&的,自己也模拟了幾遍,在一個shell裡調用帶有&的java指令,關閉終端java程序并不會退出。難道是因為同僚的終端配置和我的不一樣?後來要同僚發了它的iTerm2裡的seesion的配置給我看了下,和我的完全一樣,這就挺奇怪了。

于是再回過來看看之前的幾次程序消失時候的日志(我要同僚有保留),看到那幾個程序退出的時間點,分别是

  • 2019-01-14 20:42:52 2019-01-15 18:34:00 2019-01-18 00:57:58* 2019-01-18 17:34:30

這幾個時間點完全沒有規律看起來,不過我突然想起2019-01-18那天是周五,同僚是在上海出差,而17:34:30那會應該是快下班了,或者那會正好從上海趕車回杭州,于是問了下那個點同僚是不是準備回杭州了,同僚說那會确實合上電腦準備趕車回杭州,于是我接着問其他幾個時間是不是差不多也是合上電腦的時間,結果還真是那麼巧,既然這樣,那說明我們的判斷方向是正确的了。

水落石出

後面突然發現同僚修改過這個啟動腳本,在腳本的最後加了行指令

java xxxx &cd $DIR_LOG && tail -f common-*.log

難道是這個指令搞的鬼?

突然想起一個問題來,父子程序的問題,假如說當我們在shell裡加了&跑的話,當父程序跑完之後,會直接将其挂到init程序下面,也就是你通過ps -ef去看它的父程序會是1号程序,但是如果原來的父程序沒有跑完,那其父程序仍然會是原來的程序,是以當我們執行這個腳本的時候,一直被執行tail等待日志輸出,這樣一來,如果我們将目前視窗關閉了,那就意味着父程序會退出,然後給子程序發送SIGHUP的信号,于是導緻java程序退出,但是如果我們在tail日志過程中ctrl c了,那java程序會過繼給init程序,是以此時當我們再關閉視窗的時候也不會給其發送SIGHUP的信号了。

經過驗證果然如此,至此這個消失的程序終于得到了解釋,嗯,好在不是我們代碼的問題,值得欣慰,畢竟我們的代碼是要在客戶那邊運作的,必須要保證好穩定性。

文章轉載自阿裡雲 MVP李嘉鵬,

檢視原文