記一次python的print函數引起的血案

我最近項目是基於自研的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庫自己有問題，因而將webserver日誌級別調到debug級別，等待線上問題重現後查看異常堆棧。

次日上班時，線上就從新了這個問題，登陸線上環境，查看日誌發現異常調用堆棧以下：

[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);

後續我會完善webserver架構的相關文檔，而後將webserver框架發佈到開源社區，到時歡迎廣大猿友指正。