1. 先看现场一段能稳定复现日志错乱的代码先说一次真实经历。我手头有个抓取公开数据的多线程爬虫日志量不算大平时控制台输出也很正常。结果有几天深夜跑批量任务时终端里突然开始出现那种一看就让人头皮发麻的输出两行日志从中间拼到了一起前一行还没写完后一行就插了进来甚至同一行里出现了两个不同的 URL。一开始我还以为是数据源返回的数据有问题排查了大半天最后才确认纯粹是 Python 多线程日志输出错乱。这个问题的关键词是logging.Handler。很多人对 logging 的认知是“标准库总该是线程安全的吧”实际情况远比这个判断复杂。我想把整个排查过程拆开讲清楚日志错乱到底发生在哪个环节、官方 Handler 里的锁保护了什么、为什么有人把 Handler 重写一遍之后反而更乱、以及最后我用什么方案彻底解决。如果你写过或正在写多线程爬虫、批量任务脚本、Web 接口这篇文章应该能帮你少走不少弯路。1.1 最小复现 Demo很多报错现场没法稳定复现因为线程切换是概率事件。为了把问题暴露出来我写了一个故意放大竞争窗口的 Handler它把一条日志拆成两半中间强制 sleep 一小段时间让另一个线程有机会插入。import sys import logging import threading import time class TornHandler(logging.Handler): def __init__(self): super().__init__() self.setFormatter( logging.Formatter(%(asctime)s [%(threadName)s] %(message)s) ) def emit(self, record): msg self.format(record) half len(msg) // 2 sys.stdout.write(msg[:half]) time.sleep(0.0005) # 人为放大线程切换窗口 sys.stdout.write(msg[half:] \n) logger logging.getLogger(torn) logger.setLevel(logging.INFO) logger.addHandler(TornHandler()) def worker(n): for i in range(20): logger.info(item-%d url-%03d % (n, i)) threads [] for n in range(5): t threading.Thread(targetworker, args(n,)) threads.append(t) for t in threads: t.start() for t in threads: t.join()运行几次后输出会变成类似这样2026-01-04 10:00:00 [Thread-2] item-1 url-0012026-01-04 10:00:00 [Thread-1] item-0 url-000 2026-01-04 10:00:00 [Thread-4] item-3 url-0062026-01-04 10:00:00 [Thread-2] item-1 url-002同一行里出现了两个线程的内容日志从中间被“撕”开了。这种输出一旦落到日志文件里后面任何按行解析的程序都会出错而且很难快速定位是哪段业务逻辑写坏的。中间加的那次 sleep 不是制造问题只是把本来偶发的竞争变成必现这样后面验证修复是否生效就方便多了。1.2 错乱到底长什么样我平时排查日志错乱时会先把现象分成两类因为两类问题的成因完全不同现象具体表现对日志可用性的影响乱序线程 A 先调用 logger.info但线程 B 的日志先落盘单线程追踪仍可用影响较小行撕裂两条日志的前后半段交错在一起同一行出现两个线程内容行解析直接失败影响严重日志丢失高峰期部分日志没有写入文件或滚动切割后内容不完整排障时关键线索缺失影响严重字段穿插自定义格式里的多个变量被不同线程的内容混在同一个字段中数据分析和告警误判影响严重如果你遇到的只是乱序其实不用太焦虑多线程环境本来就不承诺“调用顺序等于输出顺序”。真正破坏日志可用性的是行撕裂和日志丢失这两类问题通常都绕不开 Handler 的实现方式。1.3 为什么默认 StreamHandler 很难复现撕裂如果你现在把上面的 TornHandler 换成标准库自带的 StreamHandler几乎不会出现同样的交错输出。原因是标准 Handler 的调用链深处已经存在一把锁。很多人第一次看到这里会困惑既然标准库有锁为什么网上还有大量“Python 多线程日志错乱”的讨论答案在后面几章锁确实存在但它保护的范围和不保护的范围可能和你想的不太一样。2. 谁的锅GIL、系统调用与 logging 内部的三层竞态先给不熟悉 logging 调用链的同学补个背景。一条logger.info()从进入到真正写出去至少经过这几步logger.info()创建 LogRecord记录日志时间、级别、线程名、进程号等信息。Logger._log()判断当前级别是否达到阈值达到才继续。Logger.callHandlers()遍历当前 Logger 以及所有父 Logger 上挂的 Handler。每个Handler.handle()会先尝试获取自己的锁然后调用emit()。emit()里调用 Formatter 把 LogRecord 格式化成字符串再写入目标流并 flush。这五步里能造成日志错乱的“竞态窗口”不止一个。2.1 GIL 不是保护日志的万能护盾CPython 有全局解释器锁GIL保证同一时刻只有一条线程在跑 Python 字节码。很多人以为有了 GIL两条线程就不可能同时执行代码也就不可能存在“写到一半被抢走”的情况。这个理解忽略了两个细节执行到sys.stdout.write()这类 I/O 调用时解释器经常在等待系统调用返回的过程中释放 GIL另一个线程会立刻拿到执行权。Python 层的一次write(msg \n)到了底层可能被拆分成多次系统调用即使TextIOWrapper对单次 write 有内部缓冲锁也管不住“两次 write 调用之间的切换”。所以“单次 write 调用本身不会被同对象的另一个 write 调用拆碎”是真的但“一条日志的完整输出只做一次 write”这个前提很容易被打破。只要你自定义 Handler 里把日志拆成多次写或者把格式化、拼接、flush 分散到多个调用GIL 就帮不了任何忙。2.2 官方 Handler 里的锁到底锁住了什么标准库的logging.Handler在初始化时会创建一个threading.RLock()核心逻辑在handle()里def handle(self, record): if self.acquire(): try: self.emit(record) finally: self.release()也就是说同一个 Handler 实例上的emit()过程是串行的。只要你的程序里只有一个 Handler 实例并且所有线程的日志都走这个实例那么两条日志就不会在emit()内部互相穿插。官方StreamHandler.emit()的实现也确实只有“格式化 write flush”这几步被锁包住之后单行日志的内容是完整的。但注意这里锁住的只是 Python 层面的调用链。真正写到终端、管道或文件时底层 C 库的缓冲行为不在你控制范围内。实际工程里更常见的错乱不是这个 Handler 的锁失效了而是系统里同时存在多个 Handler或者有人绕过了handle()直接调emit()。2.3 乱序不是 bug锁竞争导致输出顺序不可预测标准库的锁保证了同一条日志在 emit 期间不会被别的线程打断但没有保证“谁先调用 info 谁就先落盘”。多线程并发时每个线程都在抢同一把锁抢到锁的顺序取决于线程调度而不是调用顺序。你经常看到的现象是线程 A 先执行了logger.info(step 1)线程 B 后执行了logger.info(step 2)但文件里的顺序是 B 在前、A 在后。这绝不是 logging 框架的 bug而是并发本身的语义。如果非要让全局日志绝对有序唯一办法是把所有日志写入串行化也就是第 4 章要讲的队列方案。理解了乱序是天然现象后你再回头看那些“日志顺序不对”的工单至少能少折腾一半。3. 官方 Handler 自带锁为什么很多人还是遇到错乱先纠正一个流传很广的说法“标准库 logging 在多线程下不安全所以要自己加锁。”这句话只说对了一半。标准库 Handler 默认就有RLock正常用法下不会出现行撕裂。真正的问题往往出在下面这三个地方。3.1 最常见的重写方式悄悄绕过了锁有些项目为了给日志加特殊格式、加缓冲、加日志染色会选择继承logging.Handler重写emit()。问题在于Logger.callHandlers()调用的入口是Handler.handle()而不是Handler.emit()。如果你在自定义 Handler 里又主动调用了别的 handler 的emit()或者业务代码里直接执行handler.emit(record)那么标准库 handle 那层锁完全没生效。我见过一个很典型的错误写法# 错误示范直接绕过了 handle() 的锁 class UnsafeHandler(logging.Handler): def emit(self, record): msg self.format(record) other_handler.emit(record) # 这里又手动调了一次 sys.stdout.write(msg \n)这种代码跑起来日志错乱是必然的。排查技巧很简单把日志格式里加上线程名然后看同一行里有没有两个线程名出现如果有基本就是有人绕过锁直接调emit()了。3.2 多个 Handler 实例之间锁互不认识还有一种更隐蔽的情况项目里并不是只有一把锁而是有很多把锁。比如某个服务先调了basicConfig()后面又手动给 logger 挂了一个 FileHandler或者在两个不同模块里各自 new 了一个 StreamHandler最终都指向同一个终端。每把锁都只保护自己的emit()Handler A 写一半释放锁Handler B 拿到自己的锁开始写两段输出在终端上就交错了。排查时可以写一小段脚本import logging for name in logging.Logger.manager.loggerDict: logger logging.getLogger(name) for handler in logger.handlers: print(name, id(handler), getattr(handler, stream, None))看到多个不同 id 的 Handler 挂着同一个 stream基本就找到了错乱来源。解决方案不是给每个 Handler 加锁而是收敛成“全局唯一 Handler 实例”或者直接用第 4 章的队列方案。3.3 emit 里的重活不错乱了但程序被日志拖死另一种隐蔽问题是锁虽然保证了正确性却也放大了性能问题。emit()执行期间所有其他线程都会阻塞在acquire()上排队。如果 emit 里只是简单格式化加写文件问题不大但如果有人在 emit 里加了网络请求、JSON 序列化、耗时计算那么日志一多整个线程池都会被拖住。我之前帮人看一个耗时暴涨的接口最后发现他的自定义 Handler 在emit()末尾发了一个 HTTP 通知每次写日志都要走一次网络。表面上看日志不乱但所有请求线程都在等这把锁接口整体慢了上百倍。日志设计的目标不只是“不错乱”还得“不阻塞业务线程”。这也是我后来坚决切换到队列方案的原因。4. 从加锁到队列手写一个真正线程安全的日志 Handler解决多线程日志错乱不能只靠“哪里乱了加哪里”。更稳妥的思路是把日志写入从业务线程里剥离出来让所有输出在一个地方串行执行。4.1 基于标准库锁的正确姿势如果你只是想要一个自定义 Handler最省事的办法是继承logging.StreamHandler不要随意改变emit()的调用方式。标准库handle()已经自带锁你只需要保证自己不在 emit 里做耗时操作、不主动绕过锁调别的 handler 就好。如果你必须继承logging.Handler写新的 emit也不要在 emit 里再自己搞一把锁。正确做法是保持emit()只做“格式化 写流”这两件事锁交给外层handle()统一控制。换句话说自定义 Handler 的线程安全责任在 handle 层不在 emit 层。很多人一上来就在 emit 里加threading.Lock()反而把锁的层级搞乱了。4.2 QueueHandler 与 QueueListener把“写”从业务线程里彻底剥离真正彻底解决并发问题的方案是 Python 标准库自带的logging.handlers.QueueHandler和QueueListener。核心逻辑是业务线程只把 LogRecord 丢进一个queue.Queue这一步是线程安全的而且非常快。后台有一个监听线程专门从队列里取记录再交给真正的 FileHandler、StreamHandler 去格式化、写文件。这样日志写入全部发生在监听线程里天然串行行撕裂和锁竞争同时消失。一个最小可用的配置长这样import logging import logging.handlers import queue log_queue queue.Queue(maxsize10000) # 生产者端只负责入队 queue_handler logging.handlers.QueueHandler(log_queue) log logging.getLogger(myservice) log.setLevel(logging.DEBUG) log.addHandler(queue_handler) # 消费者端真正写文件的 handler file_handler logging.FileHandler(myservice.log, encodingutf-8) file_handler.setLevel(logging.DEBUG) file_handler.setFormatter( logging.Formatter(%(asctime)s|%(process)d|%(threadName)s|%(levelname)s|%(message)s) ) listener logging.handlers.QueueListener(log_queue, file_handler) listener.start()一个常被忽略的细节格式化器要挂在真正写文件的file_handler上而不是挂在QueueHandler上。因为QueueHandler只负责把 LogRecord 丢进队列它根本不调用 Formatter。许多新手把setFormatter()写在 queue_handler 上结果日志文件里全是默认格式。程序退出前必须调用listener.stop()否则队列里还没消费完的日志会直接丢失。项目如果用了atexit注册记得把 stop 放在最后。4.3 队列满时怎么办QueueHandler默认的enqueue()用的是put_nowait()也就是说队列满了它会立刻抛queue.Full随后被 logging 的handleError吞掉并打印到 stderr。这会造成日志丢失但换来的好处是业务线程绝不会被日志阻塞。如果你希望队列满的时候业务线程阻塞等待可以覆盖enqueue()import queue import logging.handlers class BlockingQueueHandler(logging.handlers.QueueHandler): def enqueue(self, record): self.queue.put(record)如果你希望不阻塞但能统计丢失量可以这样class CountingQueueHandler(logging.handlers.QueueHandler): def __init__(self, queue): super().__init__(queue) self.dropped 0 def enqueue(self, record): try: self.queue.put_nowait(record) except queue.Full: self.dropped 1队列大小我一般设置在 1000 到 10000 之间。太小容易丢日志太大在日志异常爆发时又容易吃内存。这个量级对大多数爬虫和 Web 服务已经足够。4.4 三种方案的取舍对照方案行撕裂风险顺序控制业务阻塞实现成本单个标准 Handler基本无乱序锁内写入可能排队最低多个 Handler 写同一目标高乱序每把锁各堵各的低但不可取QueueHandler Listener无完全串行几乎零阻塞中等这几种方案里只有队列方案能同时解决“行撕裂”“日志阻塞”“锁粒度混乱”三个问题。过去几年我在实际项目里基本默认用它除非日志量小到可以忽略。5. Rollover 不是线程安全的避风港轮转竞态与丢失日志多线程日志还有一个非常隐蔽的坑就是 RotatingFileHandler 的滚动切割。很多人在没有摸清机制的情况下发现“高峰期的日志文件少了半行”“备份文件里混进了新日志”直接把锅扣到多线程头上。5.1 单 Handler 实例的滚动其实是安全的先澄清一个结论如果整个进程只有一个RotatingFileHandler实例所有线程都共用它那么官方锁会让emit()串行执行两个线程不可能同时进入doRollover()。也就是说正常情况下不会出现“两个线程同时触发切割把文件搞坏”的情况。很多人看到的轮转丢日志其实来自多进程场景或者多个 Handler 实例指向同一个文件路径。这时候每个实例各有一把锁、各自的文件描述符互相之间完全不知道对方的存在。5.2 多进程轮转的经典竞态假设有两个 worker 进程同时在写log.txt各自开了自己的 Handler时间事件T0进程 A 打开 log.txt持有 fd100T1进程 B 打开 log.txt持有 fd120T2进程 A 触发轮转把 log.txt 改名为 log.txt.1再新建 log.txtT3进程 B 继续往 fd120 写入关键问题在 T3fd120 指向的已经不是新的log.txt而是被改名前的旧 inode。进程 B 的日志全部写进了旧文件新log.txt看起来缺了一段备份文件log.txt.1里却混进了新日志。在 Windows 上更麻烦文件被打开时 rename 经常直接失败轮转瞬间所有日志线程可能集体报错。5.3 解决方案最省心的方案是回到第 4 章的“单写者模型”把滚动过程限制在监听线程里业务线程只往队列丢日志。轮转只在一个地方发生竞态自然消失。如果项目已经上了多进程又没法立刻改造可以退一步用按天切割TimedRotatingFileHandler。它的轮转频率低每天只切一次竞态窗口比大小切割小很多但零点那一刻仍可能丢一小段日志需要业务能容忍。更彻底的方案是把日志交给外部统一收集程序只负责发消息落盘和切割由远端完成。这需要一定的基础设施但对大型系统来说是最正确的路径。另外要给个务实的提醒锁内做 rollover 会阻塞所有日志线程。文件重命名、目录同步在高 IO 负载下可能耗时几十毫秒高峰时你能明显感觉到日志输出“顿了一下”。换成队列方案后这种停顿只会出现在监听线程上业务线程完全无感。6. 爬虫与 Web 服务里的配置实例Filter、队列与滚动参数的取舍理论知识讲再多不如给出两个可以直接用的配置。6.1 多线程爬虫控制台精简、文件详细爬虫项目最常见的诉求是控制台只关心关键步骤文件里保留完整细节随时能按线程追踪某次抓取的全过程。建议配置如下import logging import logging.handlers import queue log_queue queue.Queue(maxsize5000) queue_handler logging.handlers.QueueHandler(log_queue) log logging.getLogger(crawler) log.setLevel(logging.DEBUG) log.addHandler(queue_handler) formatter_console logging.Formatter(%(asctime)s %(threadName)s %(levelname)s %(message)s) formatter_file logging.Formatter( %(asctime)s|%(process)d|%(threadName)s|%(filename)s:%(lineno)d|%(levelname)s|%(message)s ) console logging.StreamHandler() console.setLevel(logging.INFO) console.setFormatter(formatter_console) file_handler logging.FileHandler(crawler.log, encodingutf-8) file_handler.setLevel(logging.DEBUG) file_handler.setFormatter(formatter_file) listener logging.handlers.QueueListener(log_queue, console, file_handler) listener.start()如果你只想临时跟踪某个线程的日志可以加一个简单的 Filterclass ThreadNameFilter(logging.Filter): def __init__(self, name): super().__init__() self.target name def filter(self, record): return record.threadName self.target把ThreadNameFilter(Thread-3)挂到一个独立 Handler 上就能把某个线程的完整日志单独抽出来看不影响其他线程输出。6.2 Web 服务按请求串联日志避免请求间“串线”Web 服务里比“行撕裂”更常见的痛点是多个并发请求的日志混在一起你根本分不清哪几行属于同一个请求。做法是给每个请求分配一个 request_id通过 ContextVar 传递再写入每条 LogRecord。import logging import logging.handlers import queue from contextvars import ContextVar request_id_var: ContextVar[str] ContextVar(request_id, default-) class RequestIdFilter(logging.Filter): def filter(self, record): record.request_id request_id_var.get() return True log_queue queue.Queue(10000) queue_handler logging.handlers.QueueHandler(log_queue) file_handler logging.handlers.TimedRotatingFileHandler( web.log, whenmidnight, backupCount7, encodingutf-8 ) file_handler.setFormatter( logging.Formatter(%(asctime)s %(levelname)s %(request_id)s %(message)s) ) file_handler.addFilter(RequestIdFilter()) listener logging.handlers.QueueListener(log_queue, file_handler) listener.start() log logging.getLogger(web) log.addHandler(queue_handler)这里的顺序有个讲究RequestIdFilter 要挂在真正执行格式化的file_handler上而不是挂在 QueueHandler 上。因为queue_handler只负责把记录丢进队列格式化动作发生在消费者线程的file_handler链路里Filter 必须在格式化前把record.request_id填好。如果用了 asyncio还要注意一个细节contextvars.ContextVar的值只在当前上下文里有效。日志被 QueueHandler 丢进队列后消费者线程根本拿不到生产者的 ContextVar 值。所以 request_id 必须在生产者端通过 Filter 写进 LogRecord 的额外字段里千万不能在监听线程里再去读request_id_var.get()那个位置取到的基本全是默认值。6.3 参数与效果预期我常用的参数是队列大小 10000文件按天切割backupCount 保留 7 天编码用 UTF-8Formatter 里必带process、threadName、request_id三件套。队列方案下每条日志在生产端只是入队一个对象开销远低于“格式化 写盘”。消费端单线程每秒处理几千条文本日志没有问题普通爬虫和中小型 Web 服务都够用。7. 排查思路与更复杂场景多进程、异步与“假错乱”如果日志已经乱了与其急着改代码不如先按一套固定流程排查。我在实际项目里形成了一套顺序基本能覆盖九成以上的日志错乱问题。7.1 拿到错乱日志后的固定排查顺序判断是行撕裂还是乱序同一行里出现两个线程名是撕裂每行完整但顺序颠倒是乱序。后者多半不用改。看进程数量如果系统里有多个 Python 进程在写同一个日志文件先默认是跨进程问题线程锁救不了。给格式加上%(process)d和%(threadName)s没有这两个字段你再怎么猜也猜不出乱的那几行各来自谁。统计 Handler 实例遍历 loggerManager 里的所有 handler看是否多个实例指向同一个输出。关掉自定义 Handler用标准 StreamHandler 对比如果问题消失说明你的自定义 emit 绕过了锁或者在 emit 里做了不该做的操作。这一步里最容易被忽略的是第二步。很多人只开一个命令行窗口以为只有一个进程实际上项目可能用 supervisor、systemd 拉起多个 worker每个 worker 都有独立的 logging 锁写入同一个文件就跟多线程完全不是一回事。7.2 多进程 多线程叠加时的唯一出路多进程写同一个日志文件标准库是无解的。每个进程的锁只对本进程内的线程有效跨进程的“行撕裂”和轮转竞态必须靠“唯一写入者”模型来根治。你可以选三种路线所有业务进程把日志发到一个专门的日志进程由它统一落盘。用文件锁把“format write flush”整体保护起来但要小心文件锁性能差且锁粒度必须覆盖完整日志行否则两条日志之间仍然可能穿插。直接把日志发到外部收集系统落盘、切割、备份全交给远端。选型上没有绝对正确但底线是同一时刻只能有一个进程在写同一个日志文件描述符。7.3 异步框架里的“假错乱”最后提一个很容易误判的场景asyncio 框架里日志看起来“乱”但代码里并没有多线程。其实在同一个事件循环里任务是协作式调度的日志输出本身就是线程安全的不会出现线程级撕裂。真正的乱通常是因为日志被丢进了ThreadPoolExecutor或者事件循环里的任务和工作线程池的线程共用了同一个 Handler又绕回了传统多线程问题。排查时要先确认“乱”发生在进程内哪个执行上下文。给日志格式加上threadName如果全部日志都来自同一个MainThread那这大概率是业务层面的顺序问题不是日志写入的并发问题。8. 收尾前的一点实用建议格式字段是排查工具不只是展示窗口。平时多花十秒钟在 Formatter 里加上%(process)d/%(threadName)d/%(lineno)d乱的时候能少掉一半头发。我现在的新项目只要涉及多线程或多进程起步就是“生产者队列 单监听线程 按天切割”格式化字段必带进程号和线程名。如果哪天日志又突然乱了我不会先去怀疑 logging 框架而是先看有没有人绕过 QueueListener 直接写文件句柄或者是不是又有人为了格式化方便加了一个自定义 Handler 还不走 handle 通道。日志这东西平时越不起眼出问题时定位成本越高。把“单写者”这件事做到位90% 的并发错乱都能提前消失。剩下的 10%大概率出在多进程文件锁、外部轮转工具和异步上下文混淆上按上面的排查顺序走一遍基本都能找到答案。
1. 先看现场一段能稳定复现日志错乱的代码先说一次真实经历。我手头有个抓取公开数据的多线程爬虫日志量不算大平时控制台输出也很正常。结果有几天深夜跑批量任务时终端里突然开始出现那种一看就让人头皮发麻的输出两行日志从中间拼到了一起前一行还没写完后一行就插了进来甚至同一行里出现了两个不同的 URL。一开始我还以为是数据源返回的数据有问题排查了大半天最后才确认纯粹是 Python 多线程日志输出错乱。这个问题的关键词是logging.Handler。很多人对 logging 的认知是“标准库总该是线程安全的吧”实际情况远比这个判断复杂。我想把整个排查过程拆开讲清楚日志错乱到底发生在哪个环节、官方 Handler 里的锁保护了什么、为什么有人把 Handler 重写一遍之后反而更乱、以及最后我用什么方案彻底解决。如果你写过或正在写多线程爬虫、批量任务脚本、Web 接口这篇文章应该能帮你少走不少弯路。1.1 最小复现 Demo很多报错现场没法稳定复现因为线程切换是概率事件。为了把问题暴露出来我写了一个故意放大竞争窗口的 Handler它把一条日志拆成两半中间强制 sleep 一小段时间让另一个线程有机会插入。import sys import logging import threading import time class TornHandler(logging.Handler): def __init__(self): super().__init__() self.setFormatter( logging.Formatter(%(asctime)s [%(threadName)s] %(message)s) ) def emit(self, record): msg self.format(record) half len(msg) // 2 sys.stdout.write(msg[:half]) time.sleep(0.0005) # 人为放大线程切换窗口 sys.stdout.write(msg[half:] \n) logger logging.getLogger(torn) logger.setLevel(logging.INFO) logger.addHandler(TornHandler()) def worker(n): for i in range(20): logger.info(item-%d url-%03d % (n, i)) threads [] for n in range(5): t threading.Thread(targetworker, args(n,)) threads.append(t) for t in threads: t.start() for t in threads: t.join()运行几次后输出会变成类似这样2026-01-04 10:00:00 [Thread-2] item-1 url-0012026-01-04 10:00:00 [Thread-1] item-0 url-000 2026-01-04 10:00:00 [Thread-4] item-3 url-0062026-01-04 10:00:00 [Thread-2] item-1 url-002同一行里出现了两个线程的内容日志从中间被“撕”开了。这种输出一旦落到日志文件里后面任何按行解析的程序都会出错而且很难快速定位是哪段业务逻辑写坏的。中间加的那次 sleep 不是制造问题只是把本来偶发的竞争变成必现这样后面验证修复是否生效就方便多了。1.2 错乱到底长什么样我平时排查日志错乱时会先把现象分成两类因为两类问题的成因完全不同现象具体表现对日志可用性的影响乱序线程 A 先调用 logger.info但线程 B 的日志先落盘单线程追踪仍可用影响较小行撕裂两条日志的前后半段交错在一起同一行出现两个线程内容行解析直接失败影响严重日志丢失高峰期部分日志没有写入文件或滚动切割后内容不完整排障时关键线索缺失影响严重字段穿插自定义格式里的多个变量被不同线程的内容混在同一个字段中数据分析和告警误判影响严重如果你遇到的只是乱序其实不用太焦虑多线程环境本来就不承诺“调用顺序等于输出顺序”。真正破坏日志可用性的是行撕裂和日志丢失这两类问题通常都绕不开 Handler 的实现方式。1.3 为什么默认 StreamHandler 很难复现撕裂如果你现在把上面的 TornHandler 换成标准库自带的 StreamHandler几乎不会出现同样的交错输出。原因是标准 Handler 的调用链深处已经存在一把锁。很多人第一次看到这里会困惑既然标准库有锁为什么网上还有大量“Python 多线程日志错乱”的讨论答案在后面几章锁确实存在但它保护的范围和不保护的范围可能和你想的不太一样。2. 谁的锅GIL、系统调用与 logging 内部的三层竞态先给不熟悉 logging 调用链的同学补个背景。一条logger.info()从进入到真正写出去至少经过这几步logger.info()创建 LogRecord记录日志时间、级别、线程名、进程号等信息。Logger._log()判断当前级别是否达到阈值达到才继续。Logger.callHandlers()遍历当前 Logger 以及所有父 Logger 上挂的 Handler。每个Handler.handle()会先尝试获取自己的锁然后调用emit()。emit()里调用 Formatter 把 LogRecord 格式化成字符串再写入目标流并 flush。这五步里能造成日志错乱的“竞态窗口”不止一个。2.1 GIL 不是保护日志的万能护盾CPython 有全局解释器锁GIL保证同一时刻只有一条线程在跑 Python 字节码。很多人以为有了 GIL两条线程就不可能同时执行代码也就不可能存在“写到一半被抢走”的情况。这个理解忽略了两个细节执行到sys.stdout.write()这类 I/O 调用时解释器经常在等待系统调用返回的过程中释放 GIL另一个线程会立刻拿到执行权。Python 层的一次write(msg \n)到了底层可能被拆分成多次系统调用即使TextIOWrapper对单次 write 有内部缓冲锁也管不住“两次 write 调用之间的切换”。所以“单次 write 调用本身不会被同对象的另一个 write 调用拆碎”是真的但“一条日志的完整输出只做一次 write”这个前提很容易被打破。只要你自定义 Handler 里把日志拆成多次写或者把格式化、拼接、flush 分散到多个调用GIL 就帮不了任何忙。2.2 官方 Handler 里的锁到底锁住了什么标准库的logging.Handler在初始化时会创建一个threading.RLock()核心逻辑在handle()里def handle(self, record): if self.acquire(): try: self.emit(record) finally: self.release()也就是说同一个 Handler 实例上的emit()过程是串行的。只要你的程序里只有一个 Handler 实例并且所有线程的日志都走这个实例那么两条日志就不会在emit()内部互相穿插。官方StreamHandler.emit()的实现也确实只有“格式化 write flush”这几步被锁包住之后单行日志的内容是完整的。但注意这里锁住的只是 Python 层面的调用链。真正写到终端、管道或文件时底层 C 库的缓冲行为不在你控制范围内。实际工程里更常见的错乱不是这个 Handler 的锁失效了而是系统里同时存在多个 Handler或者有人绕过了handle()直接调emit()。2.3 乱序不是 bug锁竞争导致输出顺序不可预测标准库的锁保证了同一条日志在 emit 期间不会被别的线程打断但没有保证“谁先调用 info 谁就先落盘”。多线程并发时每个线程都在抢同一把锁抢到锁的顺序取决于线程调度而不是调用顺序。你经常看到的现象是线程 A 先执行了logger.info(step 1)线程 B 后执行了logger.info(step 2)但文件里的顺序是 B 在前、A 在后。这绝不是 logging 框架的 bug而是并发本身的语义。如果非要让全局日志绝对有序唯一办法是把所有日志写入串行化也就是第 4 章要讲的队列方案。理解了乱序是天然现象后你再回头看那些“日志顺序不对”的工单至少能少折腾一半。3. 官方 Handler 自带锁为什么很多人还是遇到错乱先纠正一个流传很广的说法“标准库 logging 在多线程下不安全所以要自己加锁。”这句话只说对了一半。标准库 Handler 默认就有RLock正常用法下不会出现行撕裂。真正的问题往往出在下面这三个地方。3.1 最常见的重写方式悄悄绕过了锁有些项目为了给日志加特殊格式、加缓冲、加日志染色会选择继承logging.Handler重写emit()。问题在于Logger.callHandlers()调用的入口是Handler.handle()而不是Handler.emit()。如果你在自定义 Handler 里又主动调用了别的 handler 的emit()或者业务代码里直接执行handler.emit(record)那么标准库 handle 那层锁完全没生效。我见过一个很典型的错误写法# 错误示范直接绕过了 handle() 的锁 class UnsafeHandler(logging.Handler): def emit(self, record): msg self.format(record) other_handler.emit(record) # 这里又手动调了一次 sys.stdout.write(msg \n)这种代码跑起来日志错乱是必然的。排查技巧很简单把日志格式里加上线程名然后看同一行里有没有两个线程名出现如果有基本就是有人绕过锁直接调emit()了。3.2 多个 Handler 实例之间锁互不认识还有一种更隐蔽的情况项目里并不是只有一把锁而是有很多把锁。比如某个服务先调了basicConfig()后面又手动给 logger 挂了一个 FileHandler或者在两个不同模块里各自 new 了一个 StreamHandler最终都指向同一个终端。每把锁都只保护自己的emit()Handler A 写一半释放锁Handler B 拿到自己的锁开始写两段输出在终端上就交错了。排查时可以写一小段脚本import logging for name in logging.Logger.manager.loggerDict: logger logging.getLogger(name) for handler in logger.handlers: print(name, id(handler), getattr(handler, stream, None))看到多个不同 id 的 Handler 挂着同一个 stream基本就找到了错乱来源。解决方案不是给每个 Handler 加锁而是收敛成“全局唯一 Handler 实例”或者直接用第 4 章的队列方案。3.3 emit 里的重活不错乱了但程序被日志拖死另一种隐蔽问题是锁虽然保证了正确性却也放大了性能问题。emit()执行期间所有其他线程都会阻塞在acquire()上排队。如果 emit 里只是简单格式化加写文件问题不大但如果有人在 emit 里加了网络请求、JSON 序列化、耗时计算那么日志一多整个线程池都会被拖住。我之前帮人看一个耗时暴涨的接口最后发现他的自定义 Handler 在emit()末尾发了一个 HTTP 通知每次写日志都要走一次网络。表面上看日志不乱但所有请求线程都在等这把锁接口整体慢了上百倍。日志设计的目标不只是“不错乱”还得“不阻塞业务线程”。这也是我后来坚决切换到队列方案的原因。4. 从加锁到队列手写一个真正线程安全的日志 Handler解决多线程日志错乱不能只靠“哪里乱了加哪里”。更稳妥的思路是把日志写入从业务线程里剥离出来让所有输出在一个地方串行执行。4.1 基于标准库锁的正确姿势如果你只是想要一个自定义 Handler最省事的办法是继承logging.StreamHandler不要随意改变emit()的调用方式。标准库handle()已经自带锁你只需要保证自己不在 emit 里做耗时操作、不主动绕过锁调别的 handler 就好。如果你必须继承logging.Handler写新的 emit也不要在 emit 里再自己搞一把锁。正确做法是保持emit()只做“格式化 写流”这两件事锁交给外层handle()统一控制。换句话说自定义 Handler 的线程安全责任在 handle 层不在 emit 层。很多人一上来就在 emit 里加threading.Lock()反而把锁的层级搞乱了。4.2 QueueHandler 与 QueueListener把“写”从业务线程里彻底剥离真正彻底解决并发问题的方案是 Python 标准库自带的logging.handlers.QueueHandler和QueueListener。核心逻辑是业务线程只把 LogRecord 丢进一个queue.Queue这一步是线程安全的而且非常快。后台有一个监听线程专门从队列里取记录再交给真正的 FileHandler、StreamHandler 去格式化、写文件。这样日志写入全部发生在监听线程里天然串行行撕裂和锁竞争同时消失。一个最小可用的配置长这样import logging import logging.handlers import queue log_queue queue.Queue(maxsize10000) # 生产者端只负责入队 queue_handler logging.handlers.QueueHandler(log_queue) log logging.getLogger(myservice) log.setLevel(logging.DEBUG) log.addHandler(queue_handler) # 消费者端真正写文件的 handler file_handler logging.FileHandler(myservice.log, encodingutf-8) file_handler.setLevel(logging.DEBUG) file_handler.setFormatter( logging.Formatter(%(asctime)s|%(process)d|%(threadName)s|%(levelname)s|%(message)s) ) listener logging.handlers.QueueListener(log_queue, file_handler) listener.start()一个常被忽略的细节格式化器要挂在真正写文件的file_handler上而不是挂在QueueHandler上。因为QueueHandler只负责把 LogRecord 丢进队列它根本不调用 Formatter。许多新手把setFormatter()写在 queue_handler 上结果日志文件里全是默认格式。程序退出前必须调用listener.stop()否则队列里还没消费完的日志会直接丢失。项目如果用了atexit注册记得把 stop 放在最后。4.3 队列满时怎么办QueueHandler默认的enqueue()用的是put_nowait()也就是说队列满了它会立刻抛queue.Full随后被 logging 的handleError吞掉并打印到 stderr。这会造成日志丢失但换来的好处是业务线程绝不会被日志阻塞。如果你希望队列满的时候业务线程阻塞等待可以覆盖enqueue()import queue import logging.handlers class BlockingQueueHandler(logging.handlers.QueueHandler): def enqueue(self, record): self.queue.put(record)如果你希望不阻塞但能统计丢失量可以这样class CountingQueueHandler(logging.handlers.QueueHandler): def __init__(self, queue): super().__init__(queue) self.dropped 0 def enqueue(self, record): try: self.queue.put_nowait(record) except queue.Full: self.dropped 1队列大小我一般设置在 1000 到 10000 之间。太小容易丢日志太大在日志异常爆发时又容易吃内存。这个量级对大多数爬虫和 Web 服务已经足够。4.4 三种方案的取舍对照方案行撕裂风险顺序控制业务阻塞实现成本单个标准 Handler基本无乱序锁内写入可能排队最低多个 Handler 写同一目标高乱序每把锁各堵各的低但不可取QueueHandler Listener无完全串行几乎零阻塞中等这几种方案里只有队列方案能同时解决“行撕裂”“日志阻塞”“锁粒度混乱”三个问题。过去几年我在实际项目里基本默认用它除非日志量小到可以忽略。5. Rollover 不是线程安全的避风港轮转竞态与丢失日志多线程日志还有一个非常隐蔽的坑就是 RotatingFileHandler 的滚动切割。很多人在没有摸清机制的情况下发现“高峰期的日志文件少了半行”“备份文件里混进了新日志”直接把锅扣到多线程头上。5.1 单 Handler 实例的滚动其实是安全的先澄清一个结论如果整个进程只有一个RotatingFileHandler实例所有线程都共用它那么官方锁会让emit()串行执行两个线程不可能同时进入doRollover()。也就是说正常情况下不会出现“两个线程同时触发切割把文件搞坏”的情况。很多人看到的轮转丢日志其实来自多进程场景或者多个 Handler 实例指向同一个文件路径。这时候每个实例各有一把锁、各自的文件描述符互相之间完全不知道对方的存在。5.2 多进程轮转的经典竞态假设有两个 worker 进程同时在写log.txt各自开了自己的 Handler时间事件T0进程 A 打开 log.txt持有 fd100T1进程 B 打开 log.txt持有 fd120T2进程 A 触发轮转把 log.txt 改名为 log.txt.1再新建 log.txtT3进程 B 继续往 fd120 写入关键问题在 T3fd120 指向的已经不是新的log.txt而是被改名前的旧 inode。进程 B 的日志全部写进了旧文件新log.txt看起来缺了一段备份文件log.txt.1里却混进了新日志。在 Windows 上更麻烦文件被打开时 rename 经常直接失败轮转瞬间所有日志线程可能集体报错。5.3 解决方案最省心的方案是回到第 4 章的“单写者模型”把滚动过程限制在监听线程里业务线程只往队列丢日志。轮转只在一个地方发生竞态自然消失。如果项目已经上了多进程又没法立刻改造可以退一步用按天切割TimedRotatingFileHandler。它的轮转频率低每天只切一次竞态窗口比大小切割小很多但零点那一刻仍可能丢一小段日志需要业务能容忍。更彻底的方案是把日志交给外部统一收集程序只负责发消息落盘和切割由远端完成。这需要一定的基础设施但对大型系统来说是最正确的路径。另外要给个务实的提醒锁内做 rollover 会阻塞所有日志线程。文件重命名、目录同步在高 IO 负载下可能耗时几十毫秒高峰时你能明显感觉到日志输出“顿了一下”。换成队列方案后这种停顿只会出现在监听线程上业务线程完全无感。6. 爬虫与 Web 服务里的配置实例Filter、队列与滚动参数的取舍理论知识讲再多不如给出两个可以直接用的配置。6.1 多线程爬虫控制台精简、文件详细爬虫项目最常见的诉求是控制台只关心关键步骤文件里保留完整细节随时能按线程追踪某次抓取的全过程。建议配置如下import logging import logging.handlers import queue log_queue queue.Queue(maxsize5000) queue_handler logging.handlers.QueueHandler(log_queue) log logging.getLogger(crawler) log.setLevel(logging.DEBUG) log.addHandler(queue_handler) formatter_console logging.Formatter(%(asctime)s %(threadName)s %(levelname)s %(message)s) formatter_file logging.Formatter( %(asctime)s|%(process)d|%(threadName)s|%(filename)s:%(lineno)d|%(levelname)s|%(message)s ) console logging.StreamHandler() console.setLevel(logging.INFO) console.setFormatter(formatter_console) file_handler logging.FileHandler(crawler.log, encodingutf-8) file_handler.setLevel(logging.DEBUG) file_handler.setFormatter(formatter_file) listener logging.handlers.QueueListener(log_queue, console, file_handler) listener.start()如果你只想临时跟踪某个线程的日志可以加一个简单的 Filterclass ThreadNameFilter(logging.Filter): def __init__(self, name): super().__init__() self.target name def filter(self, record): return record.threadName self.target把ThreadNameFilter(Thread-3)挂到一个独立 Handler 上就能把某个线程的完整日志单独抽出来看不影响其他线程输出。6.2 Web 服务按请求串联日志避免请求间“串线”Web 服务里比“行撕裂”更常见的痛点是多个并发请求的日志混在一起你根本分不清哪几行属于同一个请求。做法是给每个请求分配一个 request_id通过 ContextVar 传递再写入每条 LogRecord。import logging import logging.handlers import queue from contextvars import ContextVar request_id_var: ContextVar[str] ContextVar(request_id, default-) class RequestIdFilter(logging.Filter): def filter(self, record): record.request_id request_id_var.get() return True log_queue queue.Queue(10000) queue_handler logging.handlers.QueueHandler(log_queue) file_handler logging.handlers.TimedRotatingFileHandler( web.log, whenmidnight, backupCount7, encodingutf-8 ) file_handler.setFormatter( logging.Formatter(%(asctime)s %(levelname)s %(request_id)s %(message)s) ) file_handler.addFilter(RequestIdFilter()) listener logging.handlers.QueueListener(log_queue, file_handler) listener.start() log logging.getLogger(web) log.addHandler(queue_handler)这里的顺序有个讲究RequestIdFilter 要挂在真正执行格式化的file_handler上而不是挂在 QueueHandler 上。因为queue_handler只负责把记录丢进队列格式化动作发生在消费者线程的file_handler链路里Filter 必须在格式化前把record.request_id填好。如果用了 asyncio还要注意一个细节contextvars.ContextVar的值只在当前上下文里有效。日志被 QueueHandler 丢进队列后消费者线程根本拿不到生产者的 ContextVar 值。所以 request_id 必须在生产者端通过 Filter 写进 LogRecord 的额外字段里千万不能在监听线程里再去读request_id_var.get()那个位置取到的基本全是默认值。6.3 参数与效果预期我常用的参数是队列大小 10000文件按天切割backupCount 保留 7 天编码用 UTF-8Formatter 里必带process、threadName、request_id三件套。队列方案下每条日志在生产端只是入队一个对象开销远低于“格式化 写盘”。消费端单线程每秒处理几千条文本日志没有问题普通爬虫和中小型 Web 服务都够用。7. 排查思路与更复杂场景多进程、异步与“假错乱”如果日志已经乱了与其急着改代码不如先按一套固定流程排查。我在实际项目里形成了一套顺序基本能覆盖九成以上的日志错乱问题。7.1 拿到错乱日志后的固定排查顺序判断是行撕裂还是乱序同一行里出现两个线程名是撕裂每行完整但顺序颠倒是乱序。后者多半不用改。看进程数量如果系统里有多个 Python 进程在写同一个日志文件先默认是跨进程问题线程锁救不了。给格式加上%(process)d和%(threadName)s没有这两个字段你再怎么猜也猜不出乱的那几行各来自谁。统计 Handler 实例遍历 loggerManager 里的所有 handler看是否多个实例指向同一个输出。关掉自定义 Handler用标准 StreamHandler 对比如果问题消失说明你的自定义 emit 绕过了锁或者在 emit 里做了不该做的操作。这一步里最容易被忽略的是第二步。很多人只开一个命令行窗口以为只有一个进程实际上项目可能用 supervisor、systemd 拉起多个 worker每个 worker 都有独立的 logging 锁写入同一个文件就跟多线程完全不是一回事。7.2 多进程 多线程叠加时的唯一出路多进程写同一个日志文件标准库是无解的。每个进程的锁只对本进程内的线程有效跨进程的“行撕裂”和轮转竞态必须靠“唯一写入者”模型来根治。你可以选三种路线所有业务进程把日志发到一个专门的日志进程由它统一落盘。用文件锁把“format write flush”整体保护起来但要小心文件锁性能差且锁粒度必须覆盖完整日志行否则两条日志之间仍然可能穿插。直接把日志发到外部收集系统落盘、切割、备份全交给远端。选型上没有绝对正确但底线是同一时刻只能有一个进程在写同一个日志文件描述符。7.3 异步框架里的“假错乱”最后提一个很容易误判的场景asyncio 框架里日志看起来“乱”但代码里并没有多线程。其实在同一个事件循环里任务是协作式调度的日志输出本身就是线程安全的不会出现线程级撕裂。真正的乱通常是因为日志被丢进了ThreadPoolExecutor或者事件循环里的任务和工作线程池的线程共用了同一个 Handler又绕回了传统多线程问题。排查时要先确认“乱”发生在进程内哪个执行上下文。给日志格式加上threadName如果全部日志都来自同一个MainThread那这大概率是业务层面的顺序问题不是日志写入的并发问题。8. 收尾前的一点实用建议格式字段是排查工具不只是展示窗口。平时多花十秒钟在 Formatter 里加上%(process)d/%(threadName)d/%(lineno)d乱的时候能少掉一半头发。我现在的新项目只要涉及多线程或多进程起步就是“生产者队列 单监听线程 按天切割”格式化字段必带进程号和线程名。如果哪天日志又突然乱了我不会先去怀疑 logging 框架而是先看有没有人绕过 QueueListener 直接写文件句柄或者是不是又有人为了格式化方便加了一个自定义 Handler 还不走 handle 通道。日志这东西平时越不起眼出问题时定位成本越高。把“单写者”这件事做到位90% 的并发错乱都能提前消失。剩下的 10%大概率出在多进程文件锁、外部轮转工具和异步上下文混淆上按上面的排查顺序走一遍基本都能找到答案。
