Python 后台日志延迟输出：用 -u、flush 和 Bash pipefail 排查

Python 脚本正在运行，日志却几秒甚至几分钟没有变化；一接上 tee，原本会逐行显示的进度又等到结束才出现。另一个容易漏掉的问题是：Python 已经失败，管道的退出码却是零。

本文用一个三秒演示，分别解决输出缓冲和失败状态被管道隐藏的问题。适合在 Linux 上运行批处理、后台任务和构建脚本的初学者到中级读者。

1. 准备环境

需要 Linux、Python 3.9 或更新版本、Bash 和 GNU Coreutils 的 tee，不需要第三方 Python 包。示例已在 Linux、Python 3.11.4 下验证。

python3 --version
command -v bash
tee --help
mkdir python-buffer-demo
cd python-buffer-demo
unset PYTHONUNBUFFERED

这里只在当前 shell 清除 PYTHONUNBUFFERED，方便复现默认行为。演示中的 tee 会覆盖同名日志，重复实验请使用新的工作目录。

将下一节代码保存为 demo.py，再运行 python3 demo.py --help。

2. 复现：终端有进度，管道里却延迟

"""Demonstrate delayed stdout and an optional failure. Python 3.9+."""
import argparse
import sys
import time


def main():
    parser = argparse.ArgumentParser(description=__doc__)
    parser.add_argument("--fail", action="store_true", help="exit with status 7")
    args = parser.parse_args()
    print("START")
    for number in range(1, 4):
        print(f"processed={number}")
        time.sleep(1)
    if args.fail:
        print("ERROR: simulated failure", file=sys.stderr)
        return 7
    print("DONE")
    return 0


if __name__ == "__main__":
    raise SystemExit(main())

先直接运行，再通过管道运行：

python3 demo.py
python3 demo.py 2>&1 | tee buffered.log

在普通交互终端中，第一条命令通常逐行输出。第二条命令的少量 stdout 输出通常会到大约三秒后才一起出现。这是本演示的预期现象，不代表脚本没有工作。

Python 的标准流文档说明：交互式 stdout 通常按行缓冲，非交互式 stdout 通常按块缓冲。接入管道后，Python 的 stdout 面向管道，不再直接面向终端。这里的 2>&1 把 stderr 合并进 stdout，便于一起记录。

3. 方法一：在启动命令上加 -u

不改代码，直接运行：

python3 -u demo.py 2>&1 | tee live.log

应很快看到 START 和 processed=1，然后约每秒出现下一条进度，最后输出 DONE。对照两个日志，最终内容应一致：

cmp buffered.log live.log
printf 'cmp_exit=%s\n' "$?"

预期为 cmp_exit=0。区别在输出到达时间，而不是这次成功运行的最终内容。

Python 的命令行文档定义了 -u：关闭 stdout 与 stderr 的缓冲，不影响 stdin。参数放在脚本文件名前面。如果启动入口更方便设置环境变量，可以用等价方式：

PYTHONUNBUFFERED=1 python3 demo.py 2>&1 | tee env.log
cmp live.log env.log

变量仅作用于这条命令。定时任务若还存在解释器、工作目录或变量缺失问题，先按定时任务环境排查固定入口，再加 -u。

4. 方法二：只刷新关键进度

如果能改代码，可以只在需要立即显示的消息上使用 flush=True：

import time

print("START", flush=True)
time.sleep(1)
print("DONE", flush=True)

保存为 flush_demo.py，运行：

python3 flush_demo.py 2>&1 | tee flush.log

应先看到 START，约一秒后看到 DONE。Python 的 print 文档说明，flush=True 会强制刷新输出流。它只作用于相应调用；其他普通 print 仍可能缓冲。

-u 适合统一调整已有 Python 任务，flush=True 适合只刷新关键检查点。频繁刷新会增加写入开销。两种方法都不等于把结果文件同步到磁盘，也不控制下游工具自己的缓冲。长期保存结构化日志时，可参考日志按大小轮转。

5. 验证失败：给 Bash 管道加 pipefail

下面两条 bash -c 命令各自启动独立 Bash，明确对比选项状态。逐条运行；第二次会按设计返回非零，不要放入遇错即退出的外层脚本：

bash -c 'set +o pipefail; python3 -u demo.py --fail 2>&1 | tee hidden-fail.log'
printf 'pipeline_exit=%s\n' "$?"

bash -c 'set -o pipefail; python3 -u demo.py --fail 2>&1 | tee visible-fail.log'
printf 'pipeline_exit=%s\n' "$?"

两次都会显示进度和 ERROR: simulated failure。当 tee 写入成功时，第一次为 pipeline_exit=0，第二次为 pipeline_exit=7。

Bash 管道官方手册说明：默认采用最后一条命令的退出状态；启用 pipefail 后，采用最右侧非零状态，全部成功才返回零。它不会自动中止后续命令。若 tee 本身也失败，管道状态可能来自 tee，不保证总等于 Python 的状态。

已有自动化脚本可以显式处理状态。将下面代码保存为 run_demo.sh，在当前目录运行 bash run_demo.sh，预期返回 7：

#!/usr/bin/env bash
set -o pipefail

python3 -u demo.py --fail 2>&1 | tee run.log
job_status=$?
if [ "$job_status" -ne 0 ]; then
    printf 'FAILED: pipeline exit=%s\n' "$job_status" >&2
    exit "$job_status"
fi
printf 'SUCCESS\n'

删除 --fail 后再运行，才应显示 SUCCESS 并返回零。这适用于当前示例；真实任务还应验证业务输出。需要从 Python 调用外部命令并管理超时时，可以配合子进程超时与日志教程。

6. 常见问题与修复

现象	检查与操作
加了 `tee` 仍等到结束才显示	在 Python 启动参数中加入 `-u`，而不是只调整日志查看工具。
`demo.py: unrecognized arguments: -u`	使用 `python3 -u demo.py`，把解释器参数放在脚本名前。
日志没有错误信息	使用 `2>&1 \| tee file.log` 合并两条流；见上面的完整命令。
Python 出错但任务仍显示成功	在 Bash 中启用 `pipefail`，立即保存并处理 `$?`。
`/bin/sh` 不支持这里的选项	用 `bash run_demo.sh` 执行；不要用 `sh run_demo.sh` 覆盖 Bash 入口。
日志不断变大	给真实任务选择日志轮转或保留策略；`-u` 只调整输出时机。

GNU tee 手册说明，默认写入会覆盖目标文件，-a 才是追加。根据任务选择模式；追加可能把多次运行混在一起。

如果下游还有过滤器或远程日志平台，应继续检查它们的刷新策略。日志及时出现也不能证明任务正确，更不能保证进程一定会结束。

7. 总结

先用短演示确认延迟是否来自 Python 的输出缓冲，再选择 -u 或关键消息的 flush=True。通过 tee 记录日志时，在 Bash 中启用 pipefail 并处理退出状态。分别验证实时进度、失败状态和最终业务结果，才能把命令接入自动化任务。