Python logging 实测：多进程丢日志、重复输出与六个真实报错

Pythonlogging排错

我实际在 Windows 11 + Python 3.13.14 上把下面六组配置各跑了一遍，正文里每个行数都是跑完后数出来的，不是估算。起因很具体：一个跑在 Gunicorn 后面的服务，日志里能查到报错前的 INFO，却查不到报错那一刻的 DEBUG，文件明明在轮转、磁盘也没满。查到最后是两件互不相干的事叠在一起——轮转只留三个文件，而六个 worker 进程在互相覆盖。

本文不含任何联盟推广链接，没有商品推荐，下面所有数字都来自本机跑出来的结果或官方文档原文。

口径：解释器为 Python 3.13.14（MSC v.1944 64 bit，AMD64），logging 模块文件位于 ...\python\versions\3.13.12\Lib\logging\__init__.py；官方文档取 docs.python.org 的 Logging HOWTO 与 Logging Cookbook（2026-10-23 访问，页面标注版本为 3.15.1）。下文每条判断都给两个来源：官方原文，加本机源码字面量或本机实测数字。两者不一致的地方我会直接写出来。

六组对照：写进去 1800 条，磁盘上还剩几条

六组都用同一条格式 %(message)s、同样的 40 字节填充，只有并发形态和 handler 类型不同。

场景	计划写入	磁盘上读到的行数
单进程，FileHandler（不轮转）	1800	1800
单进程，RotatingFileHandler(4096, 2)	1800	180
单进程 6 线程共用一个 RotatingFileHandler	1800	183
6 个子进程各建 FileHandler（不轮转）	1800	1674（少 7.00%）
6 个子进程各建 RotatingFileHandler	1800	220 与 200（两次运行）

第一行是基线：单进程、不轮转，一条都不少。第二行是同一段代码只换了 handler 类型，留下 180 条——这不是 bug，是 backupCount=2 加 maxBytes=4096 的正常结果，磁盘上永远只有三个约 4 KB 的文件。真正值得警惕的是第四、五行：只要变成多进程，连不轮转的 FileHandler 都会少 7.00%。

判断一：propagate 会让每一行日志打两遍

给 root 挂一个 handler，再给子 logger 挂一个，实测一条 child.info("hello") 输出 2 行；把 child.propagate 设为 False 后回到 1 行。

官方文档原话是：「Child loggers propagate messages up to the handlers associated with their ancestor loggers.」，并给出关闭方式「setting the *propagate* attribute of a logger to False」。本机源码 logging/__init__.py 的 Logger.callHandlers() 里对应的一行是 if not c.propagate:，命中即停止向上走。

这件事的麻烦之处在于它只在「两边都配了 handler」时才发作。你在自己的模块里加了个 StreamHandler，框架那边也给 root 加了一个，于是每行出现两次，而两次的内容、级别、时间全都一样，看日志时很难意识到是重复而不是重试。

判断二：basicConfig 在别人已经配过之后是空操作

实测：先给 root 挂一个 handler，再调 logging.basicConfig(filename=...)，目标文件根本没有被创建，后续日志一条都没进去，也没有任何报错。

源码里的判据就一句 if len(root.handlers) == 0:，函数 docstring 自己也写着「This function does nothing if the root logger already has handlers」。实测要覆盖必须带 force=True：第一次 force=True 建成 one.log，第二次不带 force 时 two.log 不存在，第三次带 force=True 时 three.log 出现。

还有一个更隐蔽的触发路径：HOWTO 写明模块级函数 logging.warning() 这类调用「will call basicConfig() for you if it has not been called yet」。也就是说，你在入口文件里写 logging.basicConfig() 之前，只要有任何一个第三方库先调了模块级日志函数，配置就已经被占住了，你的那次调用从此永久失效。

判断三：fileConfig 默认关掉你所有早期 logger，而且有效级别反而变低

实测一个 early.created logger：调用 fileConfig() 之前 disabled=False、getEffectiveLevel() 为 30；调用之后 disabled=True，而 getEffectiveLevel() 变成了 10。

这是最反直觉的一点：它不是靠提高级别来关掉你，级别反而降到了 10（DEBUG），真正起作用的是 disabled 这个标志位。所以出问题时你去调 setLevel(logging.DEBUG) 毫无用处——级别已经够低了，是 disabled 挡在前面。本机源码 Logger.handle() 里的判据就是 if (not self.disabled) and self.filter(record):。

官方 HOWTO 的 Warning 原话：「takes a default parameter, disable_existing_loggers, which defaults to True for reasons of backward compatibility」，并说明它「will cause any non-root loggers existing before the fileConfig() call to be disabled」。本机 inspect.signature(logging.config.fileConfig) 给出的签名一致：(fname, defaults=None, disable_existing_loggers=True, encoding=None)。

判据：凡是在 fileConfig() 之前 import 并创建过 logger 的库，日志会整体消失。修法是显式传 disable_existing_loggers=False，或者改用 dictConfig() 并在字典里显式写这个键（默认值同样是 True）。

判断四：RotatingFileHandler 留不下你以为的那么多历史

实测 maxBytes=1024、backupCount=2、写 200 条之后目录里的样子：app.log 336 字节（8 行，第一行是 line-0192，最后一行是 line-0199）、app.log.1 1008 字节、app.log.2 1008 字节。

编号方向和很多人想的反过来：app.log 永远是最新的一段，数字越大越旧，.2 是最老的那一份，下次轮转时被删掉的也是它。源码 doRollover() 里先 self.rotate(...) 再按 if self.backupCount > 0: 删除末尾旧文件。

于是「日志在轮转」和「日志还在」是两件事。按上表第二行，1800 条只剩 180 条，也就是 10% 左右；如果 maxBytes 设成 4 KB 而单条日志 50 字节，一个文件只装得下 80 条，三个文件装 240 条——这个上限在你写第一行代码时就已经定死了，和磁盘剩余空间无关。

判断五：多进程写同一个文件，官方明说不支持

Logging Cookbook 的原话很硬：「logging to a single file from *multiple processes* is *not* supported, because there is no standard way to serialize access to a single file across multiple processes in Python.」，并紧接着说明「The stdlib FileHandler and subclasses do not make use of multiprocessing.」

实测印证了这两句，而且分两层：

不轮转也丢。6 个子进程各建一个 FileHandler 指向同一路径，1800 条只回来 1674 条，少 7.00%。logging 的锁是进程内的，跨进程没有任何保护。
一轮转更糟，而且不报错。6 个子进程各建 RotatingFileHandler，两次运行分别只剩 220 条与 200 条（并发轮转的时序本身不确定，两次结果不同）。子进程 stderr 里躺着真实异常：PermissionError: [WinError 5] 拒绝访问。 与 FileNotFoundError: [WinError 2] 系统找不到指定的文件。，栈指向 handlers.py 的 emit() → doRollover() → os.remove(dfn)。

注意这些异常不会让程序退出。HOWTO 有一节专门讲这个：「The logging package is designed to swallow exceptions which occur while logging in production.」，并说明 emit() 里的异常会转给 handleError()，由它检查 raiseExceptions：为真就往 sys.stderr 打一段 traceback，为假就直接吞掉。默认情况下 raiseExceptions 是 True（HOWTO 原话，本机实测也是 True），所以你能看到 --- Logging error ---；我实测把它设成 False 之后，stderr 变成完全空白——记录照样丢，只是连这行提示都没了。

官方给的两条出路是：QueueHandler + 一个独立的 listener 进程（或线程），或者 SocketHandler + 单独的接收进程。实测 QueueListener 配 4 个线程各写 50 条，收回 200/200。如果用 ProcessPoolExecutor，Cookbook 特别提醒队列要换成 multiprocessing.Manager().Queue(-1)。部署在 Gunicorn / uWSGI 上时，官方建议「avoid creating file-based handlers directly in your web application」。

顺带一个对照：单进程内 6 个线程共用一个 RotatingFileHandler，1800 条留下 183 条，和单进程的 180 条同一量级，也没有出现异常。这正好对上 Cookbook 前半句「logging is thread-safe」——锁在线程之间有效，在进程之间无效。

判断六：有两层 level 过滤，改错一层就没了

实测矩阵（logger.setLevel × handler.setLevel × 发出 DEBUG）：

logger 级别	handler 级别	发出 DEBUG	结果
DEBUG	DEBUG	DEBUG	输出
DEBUG	ERROR	DEBUG	无
ERROR	DEBUG	DEBUG	无

官方 HOWTO 的解释是：「The level set in the logger determines which severity of messages it will pass to its handlers. The level set in each handler determines which messages that handler will send on.」

实际踩法：只想让文件里记 DEBUG、控制台保持 INFO，于是把 handler 的级别设成 INFO，却发现文件也空了——因为 logger 那层还是默认的 WARNING，DEBUG 根本没走到 handler。反过来，把 logger 设成 DEBUG 但忘了 handler，也一样没有输出。两级都得过。

排错：六个真实报错与它们的真实原因

报错一：--- Logging error --- 加 TypeError: not enough arguments for format string

lg.warning("user %s has %d points", "bob") 少传一个参数。程序不会崩，stderr 出现 --- Logging error --- 与那行 TypeError。原因见判断五里提到的吞异常机制。实测把 logging.raiseExceptions 设成 False 后，stderr 完全空白，错误彻底消失但记录照丢。修法：把参数补齐；这类问题在 CI 里可以用 raiseExceptions=True 加 stderr 断言来兜。

报错二：PermissionError: [WinError 5] 拒绝访问。

6 个子进程同时轮转同一个文件时出现，栈在 handlers.py 的 doRollover() → os.remove(dfn)。另一个进程正持有 b.log.2。根因是判断五的官方结论——标准库 handler 不做跨进程串行化。修法：改用 QueueHandler + 单一 listener，或换支持进程锁的第三方 handler。

报错三：FileNotFoundError: [WinError 2] 系统找不到指定的文件。

同上场景，另一处栈指向把 b.log 改名成 b.log.1 的那次 os.rename，以及删除 b.log.2 的那次 os.remove。两个进程同时判定「该轮转了」，先到者把文件移走，后到者扑空。同样是并发轮转的症状，不是磁盘问题。

报错四：NoneType: None

logging.exception() 写在 except 块之外时，输出里会多出一行 NoneType: None，没有 traceback。官方 HOWTO 对 Logger.exception() 的说明是「Call this method only from an exception handler.」。实测在 except ZeroDivisionError: 内部调用则正常带出完整栈。判据：exception() 默认带 exc_info=True，块外没有活动异常，sys.exc_info() 取到 (None, None, None)。

报错五：spawn 模式下子进程一条日志都没写

我把 Process(...).start() 写在模块顶层跑了第一版，结果日志目录里一个文件都没有（0/1800），也没有报错。根因是 Windows 默认的 spawn 会重新导入 __main__，顶层代码在子进程里又执行一遍。修法：把启动逻辑放进 if __name__ == "__main__":，并把 worker 函数放到独立模块里——改完之后才有上表第四、五行那些数字。这个坑本身不产生日志，所以只能靠「目录里没文件」发现。

报错六：AttributeError: module 'logging' has no attribute 'handlers'

只写了 import logging 就用 logging.handlers.RotatingFileHandler。logging.handlers 是子模块，不会随父模块自动导入。修法：显式 import logging.handlers。本机实测报错原文后面还跟着解释器提示 Did you mean: 'Handler'?——注意大小写，父模块里那个是基类 Handler，不是子模块。

常见问题

Q：logging 明明是线程安全的，为什么我的日志还是少了？

线程安全和进程安全是两件事。判断五里 6 线程那组留下 183 条、与单进程 180 条同量级，而 6 子进程那组只剩 200 条且伴随 PermissionError。进程才是问题所在。

Q：为什么我在入口文件里配的 basicConfig() 没生效？

先看判断二：只要 root 已经有过 handler，它就不做任何事，且不报错。可用 logging.getLogger().handlers 先确认，需要覆盖就传 force=True。

Q：轮转后旧日志去哪了？

去 .1、.2，数字越大越旧；超过 backupCount 的那一份在下次轮转时被删。判断四的实测里，1800 条最终只剩 180 条。

Q：多进程场景最短的改法是什么？

按 Cookbook，worker 只挂 QueueHandler，另起一个 listener 进程（或线程）用 RotatingFileHandler 落盘。实测 QueueListener 4 线程 × 50 条收回 200/200。用 ProcessPoolExecutor 时队列要用 Manager().Queue(-1)。

Q：生产环境要不要关掉 raiseExceptions？

HOWTO 的建议是「set raiseExceptions to False for production usage」。但请先看清楚代价：实测设成 False 之后报错一那类问题在 stderr 上完全消失，记录照丢。关之前先确认你有别的手段发现日志本身在失败。

本文的边界

只测了 Windows 11 上的 CPython 3.13.14，Linux 下的文件语义不同（重命名与删除的行为尤其不一样），未做跨平台对照。未测 TimedRotatingFileHandler、WatchedFileHandler（官方文档写明它 only useful on Unix-like systems）、SysLogHandler，也未测任何第三方 handler。SocketHandler 方案我只引用了官方做法，没有在本机起接收端实测。Gunicorn / uWSGI 那段是官方原文的转述，未在本机部署验证。