Python 子进程 : read returncode is sometimes different from returned code

Question

我有一个 Python 脚本，它使用 subprocess.Popen 调用另一个 Python 脚本。我知道被调用的代码总是返回 10 ，这意味着它失败了。

我的问题是，调用者只有大约 75% 的时间读取 10。其他 25% 它读取 0 并将调用的程序失败代码误认为是成功。相同的命令，相同的环境，显然是随机发生的。

环境:Python 2.7.10，Linux Redhat 6.4。此处提供的代码是(非常)简化的版本，但我仍然可以使用它重现问题。

这是被调用的脚本，constant_return.py:

#!/usr/bin/env python2.7
# -*- coding: utf-8 -*-

"""
Simplified called code
"""
import sys

if __name__ == "__main__":
    sys.exit(10)

这是调用者代码:

#!/usr/bin/env python2.7
# -*- coding: utf-8 -*-

"""
Simplified version of the calling code
"""

try:
    import sys
    import subprocess
    import threading

except Exception, eImp:
    print "Error while loading Python library : %s" % eImp
    sys.exit(100)


class BizarreProcessing(object):
    """
    Simplified caller class
    """

    def __init__(self):
        """
        Classic initialization
        """
        object.__init__(self)


    def logPipe(self, isStdOut_, process_):
        """
        Simplified log handler
        """
        try:
            if isStdOut_:
                output = process_.stdout
                logfile = open("./log_out.txt", "wb")
            else:
                output = process_.stderr
                logfile = open("./log_err.txt", "wb")

            #Read pipe content as long as the process is running
            while (process_.poll() == None):
                text = output.readline()
                if (text != '' and text.strip() != ''):
                    logfile.write(text)

        #When the process is finished, there might still be lines remaining in the pipe
            output.readlines()
            for oneline in output.readlines():
                if (oneline != None and oneline.strip() != ''):
                    logfile.write(text)
        finally:
            logfile.close()


    def startProcessing(self):
        """
        Launch process
        """

        # Simplified command line definition
        command = "/absolute/path/to/file/constant_return.py"

        # Execute command in a new process
        process = subprocess.Popen(command, shell=True, stdout=subprocess.PIPE, stderr=subprocess.PIPE)

        #Launch a thread to gather called programm stdout and stderr
        #This to avoid a deadlock with pipe filled and such
        stdoutTread = threading.Thread(target=self.logPipe, args=(True, process))
        stdoutTread.start()
        stderrThread = threading.Thread(target=self.logPipe, args=(False, process))
        stderrThread.start()

        #Wait for the end of the process and get process result
        stdoutTread.join()
        stderrThread.join()
        result = process.wait()

        print("returned code: " + str(result))

        #Send it back to the caller
        return (result)


#
# Main
#
if __name__ == "__main__":

    # Execute caller code
    processingInstance = BizarreProcessing()
    aResult = processingInstance.startProcessing()

    #Return the code
    sys.exit(aResult)

这是我在 bash 中键入的内容以执行调用者脚本:

for res in {1..100}
do
    /path/to/caller/script.py
    echo $? >> /tmp/returncodelist.txt
done

它似乎与我读取被调用程序输出的方式有某种联系，因为当我使用 process = subprocess.Popen(command, shell=True, stdout=sys.stdout, stderr=sys 创建子进程时.stderr) 并删除它读取正确返回码的所有 Thread 内容(但不再按我想要的方式记录...)

知道我做错了什么吗？

非常感谢您的帮助

Answer 1

logPipe 还检查进程 是否处于事件状态以确定是否有更多数据要读取。这是不正确的 - 您应该通过查找零长度读取或使用 output.readlines() 来检查 pipe 是否已达到 EOF。 I/O 管道的生命周期可能比进程长。

这大大简化了 logPipe:如下更改 logPipe:

  def logPipe(self, isStdOut_, process_):
      """
      Simplified log handler
      """
      try:
          if isStdOut_:
              output = process_.stdout
              logfile = open("./log_out.txt", "wb")
          else:
              output = process_.stderr
              logfile = open("./log_err.txt", "wb")

          #Read pipe content as long as the process is running
          with output:
              for text in output:
                  if text.strip(): # ... checks if it's not an empty string
                      logfile.write(text)

      finally:
          logfile.close()

其次，在 process.wait() 之前不要加入您的日志记录线程，出于同样的原因 - I/O 管道可能会比进程长。

我认为幕后发生的事情是发出了一个 SIGPIPE 并在某处处理不当 - 可能被误解为进程终止条件。这是因为管道在一端或另一端被关闭而没有被冲洗。 SIGPIPE 有时在较大的应用程序中会很麻烦；可能是 Python 库吞下了它或者用它做了一些幼稚的事情。

编辑 正如@Blackjack 指出的那样，SIGPIPE 会自动被 Python 阻止。因此，这排除了 SIGPIPE 渎职行为。第二种理论:Popen.poll() 背后的文档指出:

Check if child process has terminated. Set and return returncode attribute.

如果您对其进行 strace(例如，strace -f -o strace.log ./caller.py)，这似乎是通过 wait4(WNOHANG) 完成的。您有 2 个线程使用 WNOHANG 等待，一个正常等待，但只有一个调用会正确返回进程退出代码。如果在 subprocess.poll() 的实现中没有锁定，那么很可能会出现分配 process.resultcode 的竞争，或者可能无法正确执行。将 Popen.waits/polls 限制为单个线程应该是避免这种情况的好方法。请参阅 man waitpid。

编辑 顺便说一句，如果您可以将所有 stdout/stderr 数据保存在内存中，则 subprocess.communicate() 会更容易使用，并且根本不需要 logPipe 或后台线程。

https://docs.python.org/2/library/subprocess.html#subprocess.Popen.communicate