分别记录 stdout 和 stderr 时截断的输出日志文件

Question

我在上下文管理器中设置了一个子进程命令，该命令通过我自己的记录器将 stdout 和 stderr 通过管道传输到单独的文件。这是这里给出的答案的变体：

我的代码如下：

import logging
import subprocess

with StreamLogger(logging.DEBUG, my_out_logger) as out:
    with StreamLogger(logging.ERROR, my_err_logger) as err:
        p = subprocess.Popen(cmd, shell=False, stdout=out, stderr=err)
        p.communicate()
        p.wait()

其中 my_out_logger 和 my_err_logger 是记录对象，其句柄记录到文件等。

StreamLogger代码与上面link给出的代码类似：

import io
import os
import threading
import select
import time

class StreamLogger(io.IOBase):
    def __init__(self, level, logger):
        self.logger = logger
        self.level = level
        self.pipe = os.pipe()
        self.thread = threading.Thread(target=self._flusher)
        self.thread.start()

    def _flusher(self):
        self._run = True
        buf = b''
        while self._run:
            for fh in select.select([self.pipe[0]], [], [], 0)[0]:
                buf += os.read(fh, 1024)
                while b'\n' in buf:
                    data, buf = buf.split(b'\n', 1)
                    self.write(data.decode())
            time.sleep(0.01)
        self._run = None

    def write(self, data):
        return self.logger.log(self.level, data)

    def fileno(self):
        return self.pipe[1]

    def close(self):
        if self._run:
            self._run = False
            while self._run is not None:
                time.sleep(0.01)
            os.close(self.pipe[0])
            os.close(self.pipe[1])

我的代码与上面 link 的答案提供的代码之间的唯一显着区别是我的代码将日志消息发送到根据其句柄重定向而不是直接记录的记录器，因为在 link.

处的代码中

此代码大部分时间都可以正常工作。

但我注意到每隔一段时间就会有一个截断的输出日志文件。看起来 my_out_logger 中的 FileHandler 正在写入的输出文件在写入所有标准输出内容之前正在关闭。

我不确定为什么会发生这种情况或在哪里修复代码。现在我刚刚在 p.communicate() 和 p.wait() 之间添加了一个 time.sleep(0.3) 语句，这减少了截断文件的频率，但这似乎是一个丑陋的解决方案。

我宁愿了解问题所在并正确修复它。我欢迎任何建议或见解。

Answer 1

我想我终于明白了。这里的问题是 StreamLogger 代码无法显式检查以确保 stdout 已完全写入。一旦主线程运行 subprocess 收到 returncode，它退出上下文管理器，调用 StreamLogger 的 __exit__() 方法，该方法继承自 IOBase（源代码here）。这会调用 close()，将 self._run 属性更改为 False。这会导致正在轮询管道的线程停止循环，而不管管道中还有什么。

这对于大多数输出到 stdout 的命令都很好，在 returncode 返回和写入输出之间没有滞后时间。但就我而言，我是运行一个通过 subprocess 的程序，其中有大量文本写入 stdout。因此，在主线程告诉子线程停止轮询管道之前，需要争分夺秒地尝试清除管道。

这里的两个关键变量是从管道读取的缓冲区大小和轮询管道的频率。我通过将 os.read() 中的缓冲区大小增加到 4096 并在 _flusher() 方法的 while 循环中删除 time.sleep() 来解决我的问题。这最大限度地增加了可以从管道读取的数据量，在我的例子中，确保在日志循环停止之前输出被完整记录。

分别记录 stdout 和 stderr 时截断的输出日志文件

Truncated output log files when logging stdout and stderr separately

python

logging

subprocess

stdout

python-3.x