1. 背景与挑战
在Python脚本中执行外部命令是常见的操作，例如运行docker build .、执行shell脚本或调用其他可执行程序。通常，我们会使用Python标准库中的subprocess模块。然而，当我们需要实时捕获这些外部命令的输出，并为每行输出添加自定义前缀（例如时间戳）时，subprocess模块的默认行为可能会遇到挑战。
直接通过管道将子进程输出重定向到另一个shell命令（如| while IFS= read -r line; do printf '[%s] %s\n' "$(date '+%Y-%m-%d %H:%M:%S')" "$line"; done）在Python的subprocess环境中往往难以有效集成和控制，因为它需要模拟复杂的shell行为，并且可能导致缓冲问题或阻塞。为了实现更精细的控制和更专业的日志记录，我们需要一种更健壮的方法。
2. 解决方案概述：Pexpect与Logging的结合
本教程将介绍一种结合pexpect库和Python内置logging模块的解决方案：
- Pexpect: pexpect是一个强大的Python库，用于自动化交互式应用程序。它能够生成（spawn）子进程，并像终端用户一样向其发送命令、读取其输出。其核心优势在于能够逐行读取子进程的输出，这为我们处理每行数据提供了机会。
- Logging: Python的logging模块是一个功能全面、高度可配置的日志系统。它支持多种日志级别、输出目标（文件、控制台等）以及自定义日志格式。通过配置日志格式，我们可以轻松地为每条日志消息自动添加时间戳。
通过将pexpect捕获的子进程输出作为消息传递给logging模块，我们便能实现带时间戳的输出记录。
立即学习“Python免费学习笔记（深入）”；
3. 环境准备
在开始之前，请确保您的Python环境中已安装pexpect库。如果尚未安装，可以通过pip进行安装：
pip install pexpect
4. 核心实现：代码示例与解析
以下是实现此功能的Python代码示例：
import logging
import pexpect
import sys
# 1. 配置日志系统
# 设置日志的基本配置：
# - filename: 日志将写入的文件名。
# - encoding: 文件编码。
# - format: 日志消息的格式。'%(asctime)s' 会自动添加时间戳。
# '%(levelname)-8s' 添加日志级别，并左对齐占用8个字符。
# '%(message)s' 添加实际的日志内容。
# - level: 设置最低的日志级别，只有达到或高于此级别的消息才会被记录。
logging.basicConfig(
filename='subprocess_output.log', # 将日志输出到文件
encoding='utf-8',
format='%(asctime)s %(levelname)-8s %(message)s',
level=logging.INFO # 记录INFO级别及以上的消息
)
# 也可以配置同时输出到控制台，方便实时查看
# console_handler = logging.StreamHandler(sys.stdout)
# console_handler.setFormatter(logging.Formatter('%(asctime)s %(message)s'))
# logging.getLogger().addHandler(console_handler)
def run_command_and_log_output(command: str):
"""
运行指定的shell命令，并将其每行输出通过logging模块记录，自动添加时间戳。
Args:
command (str): 要执行的shell命令字符串。
"""
logging.info(f"--- 正在执行命令: {command} ---")
process = None
try:
# 2. 使用pexpect.spawn启动子进程
# pexpect.spawn() 接收一个命令字符串，它会像在终端中一样执行该命令。
# encoding="utf-8" 确保正确处理输出字符编码。
process = pexpect.spawn(command, encoding="utf-8", timeout=3600) # 设置超时时间，防止无限等待
# 3. 逐行读取子进程输出并记录
while True:
try:
# readline() 方法读取一行输出，直到遇到换行符或EOF。
# 如果没有更多行，它会返回一个空字符串。
line = process.readline()
if not line: # 遇到EOF (End Of File)，表示子进程输出结束
break
# 使用strip()去除行尾的换行符，避免日志中出现多余空行
logging.info(line.strip())
except pexpect.exceptions.TIMEOUT:
# 处理超时异常
logging.warning(f"命令 '{command}' 执行超时，可能仍在运行或已挂起。")
break # 退出循环，或根据需要进行其他处理
except pexpect.exceptions.EOF:
# 处理EOF异常，通常表示进程已结束
logging.info(f"命令 '{command}' 输出已结束 (EOF)。")
break
except Exception as e:
# 捕获其他可能的异常
logging.error(f"处理命令 '{command}' 输出时发生错误: {e}")
break
# 4. 获取子进程的退出状态
process.close() # 关闭pexpect进程对象，释放资源
if process.exitstatus is not None:
logging.info(f"命令 '{command}' 已完成，退出状态码: {process.exitstatus}")
elif process.signalstatus is not None:
logging.warning(f"命令 '{command}' 被信号 {process.signalstatus} 终止。")
except pexpect.exceptions.ExceptionPexpect as e:
# 捕获pexpect特有的异常，例如命令找不到等
logging.error(f"启动命令 '{command}' 时发生Pexpect错误: {e}")
except Exception as e:
# 捕获其他通用异常
logging.error(f"执行命令 '{command}' 时发生未知错误: {e}")
finally:
if process and process.isalive():
# 确保进程被终止，防止僵尸进程
process.terminate()
logging.warning(f"命令 '{command}' 在清理阶段被强制终止。")
logging.info(f"--- 命令 '{command}' 执行结束 ---")
# 示例用法
if __name__ == "__main__":
print("日志将输出到 'subprocess_output.log' 文件中。")
print("请查看该文件以获取带时间戳的输出。")
# 示例1: 简单的ls命令
run_command_and_log_output("ls -l")
# 示例2: 模拟一个长时间运行的命令
# (在Unix/Linux上运行，Windows上可能需要不同的命令，如 ping -n 5 127.0.0.1)
run_command_and_log_output("sh -c 'for i in $(seq 1 3); do echo \"Line $i from long running task\"; sleep 1; done'")
# 示例3: 原始问题中提到的docker build命令（假设docker已安装并配置）
# run_command_and_log_output("docker build .")
# 示例4: 一个不存在的命令，用于测试错误处理
run_command_and_log_output("this_command_does_not_exist_12345")5. 代码解析与注意事项
5.1 日志配置 (logging.basicConfig)
- filename='subprocess_output.log': 指定日志输出的文件。您可以根据需要更改文件名或路径。
- format='%(asctime)s %(levelname)-8s %(message)s': 这是关键部分。
- %(asctime)s: 日志记录时间，格式默认为YYYY-MM-DD HH:MM:SS,ms。这是自动添加时间戳的核心。
- %(levelname)-8s: 日志级别（如INFO, WARNING, ERROR），-8s表示左对齐并占据8个字符宽度。
- %(message)s: 实际的日志内容，即子进程的输出行。
- level=logging.INFO: 设置日志级别。只有INFO级别或更高级别的消息才会被记录。您可以根据需要调整为DEBUG、WARNING、ERROR等。
5.2 启动子进程 (pexpect.spawn)
- process = pexpect.spawn(command, encoding="utf-8", timeout=3600):
- pexpect.spawn()是启动子进程的主要函数。它接收一个字符串作为命令，并像在shell中一样执行它。
- encoding="utf-8"参数非常重要，确保pexpect能正确解码子进程的输出，避免乱码。
- timeout=3600：设置一个超时时间（秒）。如果子进程在指定时间内没有输出，pexpect会抛出pexpect.exceptions.TIMEOUT异常。这对于防止脚本无限期等待非常有用。
5.3 逐行读取与记录 (while True: process.readline())
- while True: line = process.readline(): 这是一个循环，不断尝试从子进程读取一行输出。
- process.readline(): 这是pexpect的关键方法。它会阻塞直到读取到完整的行（以换行符结束）或者遇到文件结束符（EOF）。
- if not line: break: 当readline()返回一个空字符串时，表示子进程已经结束并且没有更多的输出了（即达到了EOF）。此时应该跳出循环。
- logging.info(line.strip()): 将读取到的行（去除首尾空白，特别是换行符）作为INFO级别的消息记录。logging模块会自动根据配置的format添加时间戳、日志级别等信息。
5.4 错误处理与资源清理
- 异常捕获: 代码中包含了对pexpect.exceptions.TIMEOUT和pexpect.exceptions.EOF的捕获，以及更通用的pexpect.exceptions.ExceptionPexpect和Exception。这使得脚本在面对子进程异常终止、无响应或命令不存在等情况时更加健壮。
- process.close(): 在处理完子进程输出后，务必调用close()方法。这会等待子进程退出，并设置process.exitstatus（退出状态码）或process.signalstatus（终止信号）。
- finally块中的process.terminate(): 这是一个重要的安全措施。即使在try块中发生未捕获的异常，finally块也能确保尝试终止子进程，防止僵尸进程的产生。
6. 总结
通过结合pexpect和logging模块，我们提供了一个强大且灵活的解决方案，用于在Python中执行外部命令并为每行输出添加时间戳。这种方法不仅解决了subprocess模块在处理实时、逐行输出时的局限性，还利用了logging模块的专业日志能力，使得输出管理更加规范和可控。
此方法特别适用于：
- 需要实时监控输出的长时间运行命令。
- 需要详细记录外部工具执行过程的自动化脚本。
- 需要统一日志格式以方便分析和调试的系统集成项目。
请记住，在执行任意外部命令时，务必注意潜在的安全风险，并确保只执行来自可信源的命令。
