自帶的 print 函數竟然會報錯？

前言

最近用 Python 寫了幾個簡單的腳原本處理一些數據，由於只是簡單功能因此我就直接使用 print 來打印日誌。

任務運行時偶爾會出現一些異常：

由於我在不一樣地方都有打印日誌，致使每次報錯的地方都不太同樣，從而致使程序運行結果很是詭異；有時候是這段代碼沒有運行，下一次就多是另一段代碼沒有觸發。

雖然說當時有注意到 Broken pipe 這個關鍵異常，但沒有特別在乎，由於代碼中也有一些發送 http 請求的地方，一直覺得是網絡 IO 出現了問題，壓根沒往 print 這個最基本的打印函數上思考🤔。

直到這個問題反覆出現我才認真看了這個異常，定睛一看 print 不也是 IO 操做嘛，難道真的是自帶的 print 函數都出問題了？

---

但在本地、測試環境我運行無數次也沒能發現異常；因而我找運維拿到了線上的運行方式。

原來爲了方便維護你們提交上來的腳本任務，運維本身有維護一個統一的腳本，在這個腳本中使用：

cmd = 'python /xxx/test.py'
os.popen(cmd)
複製代碼

來觸發任務，這也是與我在本地、開發環境的惟一區別。

popen 原理

爲此我在開發環境模擬出了異常：

test.py:

import time
if __name__ == '__main__':
    time.sleep(20)
    print '1000'*1024
複製代碼

task.py:

import os
import time
if __name__ == '__main__':
    start = int(time.time())
    cmd = 'python test.py'
    os.popen(cmd)
    end = int(time.time())
    print 'end****{}s'.format(end-start)
複製代碼

運行:

python task.py
複製代碼

等待 20s 必然會復現這個異常：

Traceback (most recent call last):
  File "test.py", line 4, in <module>
    print '1000'*1024
IOError: [Errno 32] Broken pipe
複製代碼

爲何會出現這個異常呢？

首先得了解 os.popen(command[, mode[, bufsize]]) 這個函數的運行原理。

根據官方文檔的解釋，該函數會執行 fork 一個子進程執行 command 這個命令，同時將子進程的標準輸出經過管道鏈接到父進程；

也就該方法返回的文件描述符。

這裏畫個圖能更好地理解其中的原理：

在這裏的使用場景中並無獲取 popen() 的返回值，因此 command 的執行本質上是異步的；

也就是說當 task.py 執行完畢後會自動關閉讀取端的管道。 如圖所示，關閉以後子進程會向 pipe 中輸出 print '1000'*1024，因爲這裏輸出的內容較多會一會兒填滿管道的緩衝區；

因而寫入端會收到 SIGPIPE 信號，從而致使 Broken pipe 的異常。

從維基百科中咱們也能夠看出這個異常產生的一些條件：

其中也提到了 SIGPIPE 信號。

解決辦法

既然知道了問題緣由，那解決起來就比較簡單了，主要有如下幾個方案：

1. 使用 read() 函數讀取管道中的數據，所有讀取以後再關閉。
2. 若是不須要子進程中的輸出時，也能夠將 command 的標準輸出重定向到 /dev/null。
3. 也可使用 Python3 的 subprocess.Popen 模塊來運行。

這裏使用第一種方案進行演示：

import os
import time
if __name__ == '__main__':
    start = int(time.time())
    cmd = 'python test.py'
    with os.popen(cmd) as p:
        print p.read()
    end = int(time.time())
    print 'end****{}s'.format(end-start)
複製代碼

運行 task.py 以後不會再拋異常，同時也將 command 的輸出打印出來。

線上修復時我沒有采用這個方案，爲了方便查看日誌，仍是使用標準的日誌框架將日誌輸出到了 es 中，方便統一在 kibana 中進行查看。

因爲日誌框架並無使用到管道，因此天然也不會有這個問題。

更多內容

問題雖然是解決了，其中仍是涉及到了一些我們平時不太注意的知識點，此次咱們就來一塊兒回顧一下。

首先是父子進程的內容，這個在 c/c++/python 中比較常見，在 Java/golang 中直接使用多線程、協程會更多一些。

好比此次提到的 Python 中的 os.popen() 就是建立了一個子進程，既然是子進程那確定是須要和父進程進行通訊才能達到協同工做的目的。

很容易想到，父子進程之間能夠經過上文提到的管道（匿名管道）來進行通訊。

仍是以剛纔的 Python 程序爲例，當運行 task.py 後會生成兩個進程：

分別進入這兩個程序的 /proc/pid/fd 目錄能夠看到這兩個進程所打開的文件描述符。

父進程：

子進程：

能夠看到子進程的標準輸出與父進程關聯，也就是 popen() 所返回的那個文件描述符。

這裏的 0 1 2 分別對應一個進程的stdin(標準輸入)/stdout(標準輸出)/stderr(標準錯誤)。

還有一點須要注意的是，當咱們在父進程中打開的文件描述符，子進程也會繼承過去；

好比在 task.py 中新增一段代碼：

x = open("1.txt", "w")
複製代碼

以後查看文件描述符時會發現父子進程都會有這個文件：

但相反的，子進程中打開的文件父進程是不會有的，這個應該很容易理解。

總結

一些基礎知識在排查一些詭異問題時顯得尤其重要，好比本次涉及到的父子進程的管道通訊，最後來總結一下：

1. os.popen() 函數是異步執行的，若是須要拿到子進程的輸出，須要自行調用 read() 函數。
2. 父子進程是經過匿名管道進行通訊的，當讀取端關閉時，寫入端輸出到達管道最大緩存時會收到 SIGPIPE 信號，從而拋出 Broken pipe 異常。
3. 子進程會繼承父進程的文件描述符。

你的點贊與分享是對我最大的支持