記一次python的print函式引發的血案
阿新 • • 發佈：2019-06-23
我最近專案是基於自研的webserver框架實現的，支援C++、Java、Python等語言混合開發，上線一年多都沒有發現重大問題。但就在昨天快下班時，運營同事突然打電話說生產環境無法匯入報表，於是我登入生產環境，看了一下日誌，發現報表檔案已經正常上到伺服器，但在解析時無法正常開啟。
我們的報表都是xls格式，匯入功能是Python開發的，我們選擇xlrd庫來解析xls檔案。檢視日誌發現xlrd在開啟檔案時報“輸入/輸出錯誤”，具體日誌如下：
[20190614 17:28:48|ERR] system error[Errno 5 輸入/輸出錯誤]由於是線上問題，我馬上轉存日誌後，就重啟了webserver服務，重啟後就可以正常匯入報表，果然是萬能的重啟大法。
問題分析
但是問題還是要解決，由於是xlrd模組報錯，一開始一直堅信xlrd庫不會有問題，那麼很有可能是xls檔案損壞引起了，計算了一下報表檔案的MD5值，發現檔案是完整的，下載到本地可以正常開啟，而且線上下環境匯入竟然成功了，多次線上下測試都不能重現線上的問題。
排除了不是xls檔案的問題後，開始懷疑是線上環境存在檔案使用完後沒有關閉的情況，導致長時間執行後webserver程序的檔案控制代碼用完了，因此無法正常開啟檔案，於是用lsof -c webserver | wc -l命令跟蹤了一個websever服務開啟的檔案數量，發現開啟檔案數量是穩定了，這就奇怪了，明明是“輸入/輸出”錯誤，難道xlrd
第二天上班時，線上就重新了這個問題，登入線上環境，檢視日誌發現異常呼叫堆疊如下：
[20190615 08:50:08|ERR] system error[Errno 5 輸入/輸出錯誤] [20190615 08:50:08|ERR] system error[Traceback (most recent call last): File "/home/work/application/webserver/pyc/alibaba/importexlist.py", line 56, in main vec = GetDataList(app.getPath() + url); File "/home/work/application/webserver/pyc/alibaba/importexlist.py", line 17, in GetDataList with xlrd.open_workbook(path) as xls: File "/usr/local/lib/python3.6/site-packages/xlrd/__init__.py", line 157, in open_workbook ragged_rows=ragged_rows, File "/usr/local/lib/python3.6/site-packages/xlrd/book.py", line 88, in open_workbook_xls ragged_rows=ragged_rows, File "/usr/local/lib/python3.6/site-packages/xlrd/book.py", line 632, in biff2_8_load cd = compdoc.CompDoc(self.filestr, logfile=self.logfile) File "/usr/local/lib/python3.6/site-packages/xlrd/compdoc.py", line 119, in __init__ % (len(mem), sec_size), file=logfile) OSError: [Errno 5] 輸入/輸出錯誤
很明顯，程式執行到xlrd/compdoc.py檔案第119行出現異常，執行以下命令檢視原始碼內容如下：
head -120 /usr/local/lib/python3.6/site-packages/xlrd/compdoc.py | cat -n
114 mem_data_secs, left_over = divmod(mem_data_len, sec_size)
115 if left_over:
116 #### raise CompDocError("Not a whole number of sectors")
117 mem_data_secs += 1
118 print("WARNING *** file size (%d) not 512 + multiple of sector size (%d)"
119 % (len(mem), sec_size), file=logfile)
120 self.mem_data_secs = mem_data_secs # use for checking later
看了原始碼後有點不淡定了，心中有一萬匹草泥馬在奔騰，原始碼中只有print函式(第119行)與“輸入/輸出”有關，難道是print函式的問題，不可能呀，這個是Python的系統函式怎麼可能會有問題？繼續分析原始碼，發現print函式傳入了file引數，但這個引數的值是sys.stdout。
sys.stdout這不就是輸出終端嗎？分析至此，看來Python的print函式有貓膩，這時用lsof -c webserver命令重點觀察了一下webserver開啟檔案情況：
webserver 10237 work 0u CHR 136,0 0t0 3 /dev/pts/0(deleted)
webserver 10237 work 1u CHR 136,0 0t0 3 /dev/pts/0(deleted)
webserver 10237 work 2u CHR 136,0 0t0 3 /dev/pts/0(deleted)對比線下測試環境的lsof -c webserver命令執行結果，發現上面開啟檔案記錄後面多了一個deleted標記，說明對應的檔案或裝置已經被刪除了。
webserver 10632 work 0u CHR 136,0 0t0 3 /dev/pts/4
webserver 10632 work 1u CHR 136,0 0t0 3 /dev/pts/4
webserver 10632 work 2u CHR 136,0 0t0 3 /dev/pts/4看來真的是線上webserver服務終端輸出裝置的問題，確認問題後立馬重啟線上webserver服務，再次執行lsof -c webserver命令輸出如下：
webserver 10413 work 0u CHR 136,0 0t0 3 /dev/pts/1
webserver 10413 work 1u CHR 136,0 0t0 3 /dev/pts/1
webserver 10413 work 2u CHR 136,0 0t0 3 /dev/pts/1重啟結果和預期一致，上面輸出內容第4列0u/1u/2u實際上是webserver程序啟動時最先開啟的三個檔案控制代碼，依次對應以下終端裝置：
0號檔案---stdin標準輸入裝置1號檔案---stdout標準輸出裝置2號檔案---stderr錯誤輸出裝置
那麼在什麼情況下檔案會出現deleted刪除標記呢？原來webserver服務通過終端啟動，當啟動終端退出或關閉時，對應的終端裝置也就不存在了，如果這時不關閉對應檔案控制代碼，就會出現上面這種情況，不幸的是Python的print函式會把這種情況當異常處理，於是就產生了這個問題。
解決方案
問題原因找到了，怎麼解決這個呢？既然檔案的deleted標記是終端關閉時引起，那麼一定是終端關閉時向核心傳送了訊號，然後核心根據這個訊號將對應的檔案控制代碼標記為deleted。
實際上終端關閉時會向核心傳送SIGHUP訊號，我們可以呼叫signal函式給SIGHUP訊號註冊一個回撥方法，然後在回撥方法裡面關閉終端相關的裝置，就是對stdin/stdout/stderr執行close方法，相關程式碼如下：
//SIGHUP訊號回撥函式
void sighup(int signum)
{
fclose(stdin);
fclose(stdout);
fclose(stderr);
//忽略後繼SIGHUP訊號
signal(signum, SIG_IGN);
}
//註冊SIGHUP訊號回撥函式
signal(SIGHUP, sighup);