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

【问题标题】：Truncated output log files when logging stdout and stderr separately分别记录 stdout 和 stderr 时截断的输出日志文件
【发布时间】：2020-01-27 23:34:25
【问题描述】：

我在上下文管理器中设置了一个子进程命令，该命令通过我自己的记录器将标准输出和标准错误通过管道传输到单独的文件。这是此处给出的答案的变体： https://stackoverflow.com/a/4838875/4844311

我的代码如下：

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 代码类似于上面链接中给出的代码：

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])

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

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

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

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

我宁愿了解出了什么问题并妥善解决。我欢迎任何建议或见解。

【问题讨论】：

删除p.communicate()，这里不需要
好吧，我想我明白为什么了。我尝试不使用该行，但我得到了更多截断的文件，但我认为这是因为 communicate 正在执行延迟角色，就像我一直在使用的 time.sleep() hack 一样。删除线并不能解决问题。
不知道。关门前你试过冲水吗？
我尝试添加sys.stdout.flush()，但没有帮助。你能解释一下 StreamLogger 代码是如何工作的吗？ close() 在哪里调用？为什么while self._run: 循环不是无限循环？

标签： python python-3.x logging subprocess stdout

【解决方案1】：

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

这适用于大多数输出到stdout 的小到中等的命令，其中returncode 返回和输出被写入之间没有延迟时间。但就我而言，我正在通过subprocess 运行一个程序，其中大量文本写入stdout。因此，在主线程告诉子线程停止轮询管道之前，有一种与时间赛跑的方式来尝试清除管道。

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

【讨论】：