Python 多进程日志错乱排查：从 fork 到 RotatingFileHandler 的隐蔽陷阱

在一个日志采集服务的重构中，我遇到了一个很典型的问题：Python 多进程程序在跑了几小时后，日志文件里出现重复行、部分行被截断、甚至整段日志消失，但进程本身没有任何异常。单进程版本一切正常，改成 multiprocessing.Pool 之后才复现。这类问题看起来很玄，实际上根因非常明确，本文把它拆成三个层次讲清楚。

一、现象：日志文件里的三类异常

第一类是重复。同一秒内的同一条 WARNING 在文件里出现两到三次，内容完全一致，时间戳也一致。第二类是截断，文件里出现半行，例如 ERROR [worker-3] failed to conn 之后直接换行接上下一条。第三类是丢失，某个 worker 明明打印了日志，文件里却找不到。

这三种现象有一个共同特征：只发生在多进程写同一个文件时，且进程数越多越明显。如果是单进程，或者每个进程写自己的文件，都不会出现。这就是第一条线索：问题出在并发写同一个 file offset 上。

二、根因：fork 之后仍然共享同一个文件描述符

Python 在 Linux 上默认使用 fork 启动子进程。fork 出来的子进程会继承父进程全部打开的文件描述符，包括 logging 模块里 FileHandler 持有的那个 fd。关键点在于：fork 复制的是 fd 本身，父子进程的 fd 指向同一个内核 file 对象，也就共享同一个读写偏移量 offset。

而 logging.FileHandler 的写入并不是一次原子的 write 调用完成一整行。它内部先 format 出字符串，再经过 TextIOWrapper 缓冲，最后才落到 os.write。缓冲区加上共享 offset，就出现了两种竞态：一是两个进程同时从同一个 offset 开始写，互相覆盖；二是缓冲区在进程退出时 flush，写入时机完全不受控。

还有一个更隐蔽的点：RotatingFileHandler 做日志切割时，是先 rename 当前文件，再打开新文件。多个进程同时判断该切割了，就会出现 A 进程刚 rename 完，B 进程还拿着旧 fd 往已被 rename 的文件里写，于是这部分日志直接进了归档文件，当前文件里看不到。这就是日志丢失的来源。

三、排查：三步定位到具体原因

第一步，确认是否共享 fd。在子进程初始化后打印 os.getpid() 和 handler.stream.fileno()，如果多个进程打印出的 fileno 相同，且 offset 一致，基本可以确认共享。也可以用 lsof -p 加上进程号对比父子进程打开的同一个文件，看 inode 是否相同。

第二步，确认写入是否非原子。把 handler 的 buffer 关掉，写入时传 buffering=0 或改用 os.write 直接写，如果重复和截断现象消失，说明问题就在缓冲区与共享 offset 的竞态上。

第三步，确认切割是否冲突。在多进程下把日志量放大到触发切割的阈值，观察是否出现当前文件少了一段、归档文件多了一段的现象。如果有，就是 RotatingFileHandler 在 fork 场景下失效。

四、四种解法与取舍

方案一，QueueHandler 加 QueueListener。这是官方推荐的做法：子进程只把 LogRecord 放进 multiprocessing.Queue，父进程起一个 listener 线程独占文件写入。优点是写入只有一个进程，天然没有竞态；缺点是队列满时会阻塞，需要设置合理的 maxsize 并处理丢日志策略。

方案二，每个进程写独立文件。按 pid 或 worker 名分文件，日志平台侧做聚合。实现最简单、性能最好，弊端是文件数量随进程数增长，切割和清理成本变高。

方案三，改用 ConcurrentLogHandler 这类带文件锁的 handler。它通过 portalocker 在写入前加排他锁，能保证行级原子性，切割时也会加锁。代价是每次写入多一次系统调用，高并发下吞吐会下降约两到三成。

方案四，交给 journald 或容器 stdout。进程只写 stdout，由运行时统一收集。这是云原生环境下最省心的选择，但在需要本地文件归档的场景不适用。

实践中的建议是：如果已经用了 multiprocessing 且必须落本地文件，优先选方案一；如果日志量极大且能接受多文件，方案二更稳；只有在改造代价过高时才临时用方案三兜底，并明确接受性能损失。

五、几个容易踩的细节

第一，不要在子进程里重新调用 basicConfig。它不会替换已经存在的 root handler，只是静默忽略，看起来像配置没生效。要重新配置必须先清空 root.handlers。

第二，QueueListener 要在父进程 join 之前 stop，否则队列里残留的记录会丢。正确顺序是 pool.close()、pool.join()、listener.stop()。

第三，如果用了 fork 的启动方式，父进程里已经初始化的线程不会被复制。所以不要在 fork 之前启动 listener 线程，而应在 fork 之后、子进程开始干活之前再启动，或者直接用 spawn 启动方式规避这类继承问题。

第四，切割策略要考虑进程数。size 阈值如果按单进程估算，多进程下会频繁触发切割，反而放大竞争窗口，建议把阈值按进程数适当放大。

总结一下：Python 多进程日志错乱不是 logging 模块的 bug，而是 fork 语义下文件描述符共享的必然后果。理解 fd、file offset、缓冲区这三层关系，就能从现象直接推到根因，并在四种方案里做出符合自己场景的取舍。排查时优先用 fileno 和 inode 做实证，比反复改配置有效得多。