一崎苗、背景

svc是deamon-tools工具集中用戶守護(hù)進(jìn)程的服務(wù)，頭條目前在線上使用它來(lái)保證服務(wù)的存活(目前正在切換到更可靠的systemd)舀寓。當(dāng)進(jìn)程掛掉時(shí)胆数，svc能自動(dòng)重啟掛掉的進(jìn)程，當(dāng)被監(jiān)控的進(jìn)程有代碼更新時(shí)互墓，我們可以通過(guò)svc發(fā)送命令讓進(jìn)程進(jìn)行重啟必尼，以加載新上線的代碼。

最近篡撵，我們發(fā)現(xiàn)部分模塊有重啟失敗的情況判莉，這種情況發(fā)生的幾率極其小，幾乎沒法復(fù)現(xiàn)育谬。然而今天券盅，出現(xiàn)了另外一個(gè)奇怪的情況，就是沒有進(jìn)行過(guò)任何改動(dòng)的模塊膛檀，出現(xiàn)了無(wú)法啟動(dòng)的問(wèn)題锰镀。追查到最后，終于發(fā)現(xiàn)模塊啟動(dòng)失敗與模塊重啟失敗實(shí)際是一個(gè)問(wèn)題咖刃。 更具體的現(xiàn)象：對(duì)于一個(gè)應(yīng)用泳炉，執(zhí)行啟動(dòng)命令『python bootstrap.py』，發(fā)現(xiàn)程序只打印了一行信息（而正常啟動(dòng)會(huì)打印非常多信息）嚎杨，訪問(wèn)相應(yīng)的URL花鹅，返回504，證明應(yīng)用根本就沒起來(lái)枫浙，下面開始追查刨肃。 注：以下部分涉及到公司代碼及代碼路徑的地方，會(huì)做適當(dāng)替換/打碼處理自脯，不會(huì)影響問(wèn)題追查的描述之景。

二、程序的最后狀態(tài)

先看一下程序最后的執(zhí)行狀態(tài)膏潮，再一步步往上跟吧 Ctrl + C打斷程序執(zhí)行锻狗，程序會(huì)出錯(cuò)打出調(diào)用棧，直接貼出調(diào)用棧最深的部分：

image

程序應(yīng)該是卡在獲取某個(gè)文件鎖上了，使用strace來(lái)看一下當(dāng)前執(zhí)行的系統(tǒng)調(diào)用：

image

先看上面的紅色框轻纪，程序當(dāng)前是在不斷地嘗試得到『.python-error.log』這個(gè)文件鎖油额，為什么程序要獲取這個(gè)東西？去對(duì)應(yīng)的目錄看了一下『.python-error.log』這個(gè)文件是存在的刻帚，內(nèi)容為空潦嘶。這個(gè)時(shí)候如果把它刪掉呢？ 于是我真的把它刪了崇众，看一下下面的紅色框掂僵，再次strace程序，發(fā)現(xiàn)已經(jīng)沒有了獲取文件鎖的嘗試了顷歌，而且神奇的是這個(gè)時(shí)候程序啟動(dòng)成功了锰蓬，如下所示：

image

原本只打了一行信息，后來(lái)把文件鎖對(duì)應(yīng)的文件刪掉后眯漩，下面的其它啟動(dòng)信息全部打印出來(lái)了芹扭。 那么獲取文件鎖的代碼，究竟調(diào)用條件是什么赦抖？為什么要獲取文件鎖舱卡？看一下源碼：

image

說(shuō)明這個(gè)函數(shù)是在日志進(jìn)行切分時(shí)調(diào)用的，由于多個(gè)進(jìn)程可能會(huì)打印日志到同一個(gè)文件队萤，當(dāng)它們都發(fā)現(xiàn)應(yīng)該切分日志時(shí)轮锥，應(yīng)該由誰(shuí)去切分呢？假設(shè)要切分的日志文件名為『A.log』浮禾，程序的邏輯就是大家都去 阻塞地?fù)屆麨椤?A.log』的文件鎖交胚，誰(shuí)搶到了誰(shuí)就去切分一下日志份汗。 這里再說(shuō)一個(gè)實(shí)際是后面才觀察到的結(jié)論盈电，就是程序什么時(shí)候去檢查是否要切分日志？即什么時(shí)候執(zhí)行這個(gè)『def doRollOver』函數(shù)杯活？在每次有日志需要打印的時(shí)候匆帚，例如出現(xiàn)『logger.INFO/TRACE..』或者『logging.INFO/TRACE…』，因此每次打印日志旁钧，就會(huì)調(diào)用這個(gè)函數(shù)吸重，但是否一定會(huì)執(zhí)行到獲取文件鎖那一段代碼（with Filelock…），還不一定歪今，它會(huì)檢查是否到了切分間隔嚎幸，到了切分間隔才會(huì)切分日志。不了解python的log handler的同學(xué)可以去看一下相關(guān)資料寄猩，這個(gè)東西有點(diǎn)類似回調(diào)函數(shù)嫉晶，如果你注冊(cè)了一個(gè)log handler到某個(gè)某個(gè)logger，則這個(gè)logger在每次發(fā)生日志打印行為的時(shí)候，就會(huì)調(diào)用handler里面的『emit』函數(shù)（這里調(diào)用了父類的emit替废，父類的emit調(diào)用doRollOver函數(shù)）箍铭。

三、初步結(jié)論

1.程序啟動(dòng)時(shí)會(huì)使用『.python-error.log』作為文件鎖椎镣，如果無(wú)法獲得文件鎖就一直等待诈火；
2.有其它程序占用了文件鎖，而且一直不釋放状答，導(dǎo)致程序無(wú)法啟動(dòng)冷守；
3.由于所有服務(wù)化的程序都要在啟動(dòng)時(shí)獲取一下這個(gè)文件鎖，如果某臺(tái)機(jī)器上出現(xiàn)了鎖一直沒釋放的情況惊科，那么從那一刻開始之后所有的要打印到這個(gè)文件的程序都無(wú)法重啟教沾、啟動(dòng)，而且在大量上線的時(shí)候你還沒辦法發(fā)現(xiàn)這個(gè)問(wèn)題译断。

四授翻、誰(shuí)動(dòng)了大家的文件鎖

在上述過(guò)程中我已經(jīng)把『.python-error.log』這個(gè)文件刪掉了，所以問(wèn)題在這臺(tái)機(jī)器上暫時(shí)就沒法繼續(xù)查了孙咪。還好還有另外一臺(tái)有問(wèn)題的線上機(jī)器堪唐！ 現(xiàn)在就要找出是誰(shuí)擁有這個(gè)文件鎖，我搜了很久翎蹈，都沒說(shuō)怎么查文件鎖歸屬（英文中文變著搜）淮菠。后來(lái)忽然想到我直接看看誰(shuí)打開了這個(gè)文件應(yīng)該就可以了吧，然后再慢慢排除荤堪？這些轉(zhuǎn)不過(guò)腦子的變通總是能卡你很久…… 關(guān)鍵的良心工具『lsof』出馬了合陵，結(jié)果如下圖：

image

乍一眼看上去，像是我之前啟動(dòng)的程序中的幾個(gè)子進(jìn)程在占用澄阳，直接用ps命令查看我之前起的所有進(jìn)程拥知，如下圖：

image

就是這幾個(gè)進(jìn)程無(wú)疑！上面使用lsof列出的PID在下面的ps命令列出的PID中悉數(shù)出現(xiàn)碎赢，而且都是我懷疑的目標(biāo)進(jìn)程低剔，同一個(gè)服務(wù)『supervise toutiao.monitor.monitor』同時(shí)存在兩個(gè)，現(xiàn)在重新用strace查看這些問(wèn)題進(jìn)程到底在執(zhí)行什么肮塞。 先直接看看模塊服務(wù)的父進(jìn)程109567在干什么：

image

父進(jìn)程在發(fā)送SIGTERM信號(hào)給子進(jìn)程襟齿，然后等待這些子進(jìn)程，如果等著等著發(fā)現(xiàn)子進(jìn)程不退出枕赵，又會(huì)重新發(fā)送SIGTERM信號(hào)猜欺，不斷循環(huán)。 那么子進(jìn)程為什么就非不退出呢拷窜？ 看一下打開了『.python-error.log』的子進(jìn)程在干什么开皿，依然使用strace：

image

還是在不斷地獲取文件鎖钓试！ 那么到底還有誰(shuí)在拿著這個(gè)文件鎖不放？

五副瀑、中段結(jié)論

1.某些模塊無(wú)法啟動(dòng)弓熏、無(wú)法重啟的問(wèn)題，其直接原因都是有人占用了『.python-error.log』這個(gè)文件鎖糠睡，導(dǎo)致想啟動(dòng)的起不來(lái)挽鞠，想退出的退不了；
2.通過(guò)lsof能夠發(fā)現(xiàn)當(dāng)前嘗試打開文件的只有這些想退出的service子進(jìn)程狈孔；
3.因此『.python-error.log』文件鎖的占用只可能有2種情況：a.有其它程序退出時(shí)沒有釋放文件鎖信认，導(dǎo)致文件一直被鎖，別的程序沒法用均抽；b.service某些進(jìn)程在獲取鎖之后沒有釋放嫁赏，導(dǎo)致其它進(jìn)程無(wú)法獲取。
我們現(xiàn)在就要查出在結(jié)論3中油挥，到底是a還是b導(dǎo)致了所有進(jìn)程無(wú)法獲取鎖潦蝇。

六、文件鎖的獲取與釋放

感覺快要接觸到真理了深寥！ 誰(shuí)導(dǎo)致了文件鎖無(wú)法釋放：a.是已退出的程序沒有釋放文件鎖攘乒；b.還是在運(yùn)行的程序自己沒有釋放文件鎖導(dǎo)致進(jìn)程內(nèi)死鎖。 文件鎖在程序退出時(shí)惋鹅，會(huì)自動(dòng)釋放则酝，所以只剩下一個(gè)可能了，就是進(jìn)程內(nèi)部有死鎖闰集。

七沽讹、哪里發(fā)生了死鎖？

有一點(diǎn)需要引起注意武鲁，為什么所有的子進(jìn)程都會(huì)嘗試去獲取『.python-error.log』這個(gè)文件鎖爽雄？之前已經(jīng)查明了，只有在打印日志的時(shí)候洞坑，才有可能觸發(fā)獲取文件鎖的代碼盲链，子進(jìn)程在哪里打印日志導(dǎo)致它想獲取文件鎖？ 看源碼：

image

就是這里迟杂！svc發(fā)送重啟命令（SIGTERM）時(shí)，父進(jìn)程會(huì)進(jìn)入『def exitsignalhandler』這個(gè)函數(shù)本慕，父進(jìn)程在這個(gè)函數(shù)里會(huì)發(fā)送『SIGTERM』給所有的子進(jìn)程排拷，所有子進(jìn)程接到信號(hào)，實(shí)際上也是進(jìn)入這個(gè)『def exitsignalhandler』函數(shù)锅尘，然后它們調(diào)用了『logging.info…』监氢！ 但這個(gè)應(yīng)該不會(huì)造成死鎖布蔗，頂多是各個(gè)子進(jìn)程排隊(duì)去獲取一下這個(gè)鎖而已，除非某個(gè)拿到鎖的子進(jìn)程hung住了浪腐。纵揍。。议街。泽谨。為什么它會(huì)hung住特漩？我不負(fù)責(zé)任地猜測(cè)吧雹，因?yàn)樗诘戎面i！ 靈光一閃后的細(xì)思極恐涂身，它自己已經(jīng)拿到鎖了雄卷，為什么它還要再拿一次！蛤售？我忽然想起上面第3節(jié)使用strace觀察父進(jìn)程時(shí)它在干的事情——父進(jìn)程在不斷發(fā)SIGTERM給子進(jìn)程丁鹉。 看一下代碼，就是這樣的悴能！父進(jìn)程只要發(fā)現(xiàn)子進(jìn)程沒有完全退出鳄炉，就會(huì)隔0.1秒重新發(fā)一次SIGTERM給所有活著的子進(jìn)程。 信號(hào)處理函數(shù)是搶占式的搜骡，無(wú)論當(dāng)前的進(jìn)程在干什么拂盯，只要信號(hào)一來(lái)，會(huì)保存當(dāng)前執(zhí)行的上下文记靡，強(qiáng)制切換到信號(hào)處理函數(shù)并開始執(zhí)行谈竿，設(shè)想一個(gè)這樣的場(chǎng)景（下面就是理解這次線上問(wèn)題的關(guān)鍵）：

1.子進(jìn)程A接到SIGTERM信號(hào)，它要準(zhǔn)備退出了摸吠，于是打印一條日志說(shuō)『我接收到信號(hào)空凸，要退出了』；
2.子進(jìn)程A在打印日志的時(shí)候寸痢，發(fā)現(xiàn)——哎呀呀洲，到點(diǎn)切日志了，獲取一下文件鎖先啼止。于是道逗，它成功獲取了文件鎖；
3.當(dāng)它成功獲取到文件鎖的時(shí)候献烦，忽然滓窍，又收到一個(gè)『SIGTERM』信號(hào)。這個(gè)信號(hào)來(lái)自父進(jìn)程巩那，因?yàn)楦高M(jìn)程心里想：都過(guò)去0.1秒了吏夯，怎么子進(jìn)程還沒退出按蓑凇？我再發(fā)一個(gè)SIGTERM給子進(jìn)程讓它退出噪生。于是子進(jìn)程人格分裂了裆赵；
4.子進(jìn)程把自己原來(lái)的人格保存好，新的人格心想——我接到SIGTERM信號(hào)跺嗽，準(zhǔn)備退出了战授，打印一條日志說(shuō)『我接收到信號(hào)，要退出了』抛蚁，打印日志的時(shí)候發(fā)現(xiàn)——哎呀陈醒，到點(diǎn)切日志了，獲取一下文件鎖先…獲取一下文件鎖先…獲取一下文件鎖先…
死鎖發(fā)生了瞧甩！感覺就是這個(gè)原因岸巍！但是嚴(yán)謹(jǐn)?shù)奈疫€是設(shè)計(jì)了一個(gè)小程序來(lái)驗(yàn)證我的想法肚逸，萬(wàn)一對(duì)于每個(gè)進(jìn)程而言爷辙，它可以多次獲取它已經(jīng)獲取到的文件鎖呢？ 我的程序源碼如下：

image

很簡(jiǎn)單的實(shí)驗(yàn)辦法：

1.開兩個(gè)窗口朦促，都執(zhí)行這個(gè)程序膝晾，假設(shè)為進(jìn)程A和進(jìn)程B。
2.然后給進(jìn)程A發(fā)送SIGUSR1务冕，進(jìn)程A這個(gè)時(shí)候會(huì)獲取『filelock.lock』這個(gè)文件鎖血当，它不釋放，它直接就睡覺
3.這個(gè)時(shí)候給進(jìn)程B發(fā)送SIGUSR1禀忆，進(jìn)程B無(wú)法拿到鎖臊旭，所以一直輪詢
4.在A睡眠結(jié)束前，再發(fā)送一個(gè)SIGUSR1信號(hào)給進(jìn)程A
5.觀察兩個(gè)進(jìn)程的執(zhí)行情況
直接上圖箩退，上方是進(jìn)程A离熏，下方是進(jìn)程B：

image

好了，復(fù)現(xiàn)了戴涝，兩個(gè)進(jìn)程都沒法繼續(xù)往下走了滋戳。正常情況下，進(jìn)程拿到鎖30秒后就會(huì)釋放啥刻，但是我等了很久奸鸯，鎖都沒有釋放，程序也沒動(dòng)郑什。

八府喳、最終結(jié)論

至此，我們得到了最終結(jié)論：

1.父進(jìn)程接到重啟蘑拯、退出信號(hào)（SIGTERM）時(shí)钝满，會(huì)發(fā)送SIGTERM信號(hào)給所有的子進(jìn)程；
2.子進(jìn)程接到SIGTERM信號(hào)申窘，打印一條日志表明自己要退出了弯蚜，這個(gè)時(shí)候如果恰好要進(jìn)行一次日志切分，它會(huì)獲取相應(yīng)日志的文件鎖剃法，獲取成功后準(zhǔn)備進(jìn)行日志文件的重命名以及新建碎捺；
3.父進(jìn)程等了0.1秒，發(fā)現(xiàn)還有子進(jìn)程沒有退出贷洲，于是重新發(fā)送SIGTERM信號(hào)給所有未退出的子進(jìn)程收厨；
4.剛才獲取了文件鎖的子進(jìn)程恰好還沒有釋放鎖的時(shí)候再次接到SIGTERM信號(hào)，于是將當(dāng)前的上下文環(huán)境保存（不釋放文件鎖）优构，重新開始執(zhí)行信號(hào)處理函數(shù)诵叁，信號(hào)處理函數(shù)中打印一條日志表明自己要退出了，然后發(fā)現(xiàn)要進(jìn)行日志切分钦椭，去嘗試獲取文件鎖拧额，這個(gè)時(shí)候，發(fā)現(xiàn)文件鎖被占用彪腔，于是它阻塞等待這個(gè)文件鎖侥锦。
5.死鎖發(fā)生，所有未退出的子進(jìn)程都無(wú)法退出德挣，并且父進(jìn)程一直發(fā)送信號(hào)給子進(jìn)程恭垦。
不知道上下文不斷保存會(huì)不會(huì)造成線上出core？按道理說(shuō)在時(shí)間足夠長(zhǎng)的情況下格嗅，內(nèi)存沒法繼續(xù)放得下上下文了番挺，整個(gè)進(jìn)程就直接退出了（這個(gè)時(shí)候文件鎖被釋放）然后supervise發(fā)現(xiàn)進(jìn)程死了，好家伙吗浩，重新啟動(dòng)建芙，這個(gè)時(shí)候，由于文件鎖已經(jīng)釋放了懂扼，所以程序可以重新啟動(dòng)了禁荸，并且日志也正常切分了。而在程序掛掉到重新啟動(dòng)之間阀湿，這個(gè)時(shí)間到底有多長(zhǎng)赶熟，不好說(shuō)，可能持續(xù)幾天也是有可能的陷嘴。除非說(shuō)保存上下文的機(jī)制與我想的不一樣映砖，否則最終基本內(nèi)存不夠用。 但無(wú)論上下文的保存機(jī)制是怎么樣的灾挨，有一個(gè)沒法否認(rèn)的邑退，就是文件鎖肯定是不會(huì)釋放竹宋。

九、解決方案

知道原因后解決方案就相對(duì)簡(jiǎn)單了地技，父進(jìn)程不需要多次發(fā)送SIGTERM給子進(jìn)程蜈七，發(fā)送一次就可以了（如果發(fā)送一次都沒法退出的子進(jìn)程，發(fā)送兩次也是重新執(zhí)行信號(hào)處理函數(shù)莫矗，行為就更加無(wú)法預(yù)測(cè)了）飒硅，發(fā)送后直接阻塞地join子進(jìn)程就可以了。 目前修改后的信號(hào)處理函數(shù)代碼如下：

image

折騰了一整天啊這個(gè)問(wèn)題作谚，上面的追查看似行云流水三娩，實(shí)際碰壁極多，Google+百度搜了很多無(wú)效的結(jié)果妹懒。還好最終查到了雀监。