前言

最近用 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 信号。

解决办法

既然知道了问题原因，那解决起来就比较简单了，主要有以下几个方案：

使用 read() 函数读取管道中的数据，全部读取之后再关闭。
如果不需要子进程中的输出时，也可以将 command 的标准输出重定向到 /dev/null。
也可以使用 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)