★ FEATURED ARTICLE 先捋一下这个需求背后到底藏着多少事。很多人以为日志分割就是调一个RotatingFileHandler几行代码完事。但真上了多进程生产环境你会发现日志串行写入没问题一到按时间分割或者文件体积到上限触发滚动的那一瞬间各种诡异现象全冒出来了日志写丢了、日志写重复了、两个进程同时改同一个文件把行写花了、或者旧文件还没rename完新进程已经往新文件写了。这个标题里三个关键词——按大小分割、按时间分割、多进程安全配置——其实已经点出了一个工程问题Python标准库自带的日志Handler单进程绰绰有余多进程场景下敢直接用就等于在线踩雷。这篇文章我会从标准库自带Handler的底层逻辑讲起把按大小和按时间分割各自的工作原理、隐藏缺陷拆开讲明白然后重点给出多进程场景下的完整解决方案包括自定义Handler的完整代码、每一行到底在防什么以及我在实际生产环境里踩过的一组坑。无论你是刚接触logging的新手还是已经在多进程服务里被日志坑过几回的老手这篇都能让你少走至少一个晚上的弯路。1. 先把需求拆开按大小分割和按时间分割本质上是两套完全不同的逻辑日志分割最常见的两个触发条件一个是文件体积一个是时间周期。很多人默认“反正都是滚动嘛差不多”但这两者在实现机理上差别很大坑也不一样。1.1 按大小分割到达阈值就滚动但“到达阈值”的判断时机很微妙按大小分割标准做法是logging.handlers.RotatingFileHandler。它内部维护着一个字节计数器每次emit()写入一条日志时把当前消息长度累加进去一旦当前累积字节数 maxBytes就会执行一次doRollover()先关掉当前文件把当前日志文件rename成带序号的后备文件再重新打开一个全新的当前日志文件计数器清零。这个设计的几个关键细节很多人没注意maxBytes和backupCount是成对生效的。maxBytes设了但backupCount不设或者设0代码里根本不会进入滚动分支文件会无限增长这是最常见的“我明明设置了但是没分割”的原因。rename的方向是从新到旧的文件 - 文件.1原来的文件.1 - 文件.2依次后移最后把最老的那个删掉。这个机制决定了后备文件数量越多滚动一次要做的文件操作越多如果backupCount设到100每次滚动要重命名99个文件这在文件系统IO繁忙的时候会有明显的性能开销。滚动触发的时机是**“写一条日志时”**不是“文件正好到达maxBytes那一刻”。也就是说实际文件大小永远是maxBytes 最新一条消息长度的偏移这是正常现象不用焦虑。1.2 按时间分割靠的是“等到下一次时间边界才动手”按时间分割标准做法是logging.handlers.TimedRotatingFileHandler。它相比体积分割逻辑上复杂一个维度它不是一到点就立刻滚动而是等到下一次周期边界的“下一笔写入”时才执行滚动。举个例子你设置了whenH每小时滚动程序上午10点过10分启动那么第一次计划滚动时间点不是10点整而是11点整。在10:30写入一条日志时它发现“当前时间还没到11点”不滚动正常写入等11点过后第一条日志进来它发现当前时间已经超过计划滚动时间点执行doRollover()把上一次写入的文件rename成带后缀的备份文件然后建立新文件并把下一次计划滚动时间更新成12点。这个机制里有个长期被吐槽的设计滚动完之后的两个时间边界点之间如果中间没有任何日志写入它不会自动创建新日志文件而是等下一次写入才动。也就是说凌晨2点到3点之间你的服务静默无流量期间它不会在2点整准时生成一个新的空日志文件而是要等到2点多第一条新日志进来才顺便滚一下。这个行为对“日志必须按小时文件对齐”的审计场景非常不友好。1.3 双条件同时生效时标准库是没有现成解的按大小也切、按时间也切标准库没有现成的Handler支持把两者同时组合在一个文件上。常规做法是写两个Handler挂到同一个Logger下面但问题马上来了两个Handler各自维护一套文件句柄和滚动逻辑同一个日志事件会同时写两个文件你要的是“同一个文件到了时间点滚动同时文件体积到上限也滚动”实际得到的却是“两个文件各滚各的”。所以生产环境里做双条件分割基本绕不开重写Handler。# 常见的错误理解加两个handler就能同时按大小和时间分割 import logging logger logging.getLogger(demo) size_handler logging.handlers.RotatingFileHandler(app.log, maxBytes10 * 1024 * 1024, backupCount5) time_handler logging.handlers.TimedRotatingFileHandler(app.log, whenMIDNIGHT, backupCount7) logger.addHandler(size_handler) logger.addHandler(time_handler) # 结果一条日志被写两次两个handler同时操作app.log文件内容重复2. 多进程安全为什么logging模块的标准Handler一上多进程就出事单进程下logging自带Handler的线程安全性是有保障的——Handler.emit()内部有RLock保护同一进程内多线程不会把一行日志写花。但多进程完全是另一码事。2.1 多进程写同一文件问题不在写入在滚动多个进程同时往同一个日志文件追加写入只要每条日志长度不算夸张每条write()都是一个系统调用数据交错的可能性不大这种事操作系统层面基本能扛住。真正出问题的是滚动瞬间的文件操作竞争。想象一下这个场景进程A和进程B都在用标准TimedRotatingFileHandler写同一个app.log。到了滚动点两个进程几乎同时发现“时间到了”然后各自执行自己的滚动逻辑进程A先rename把app.log改名为app.log.2024-01-01然后自己打开新的app.log。进程B此时还持有旧文件的句柄它以为自己在往app.log写但实际上它写的是已经被rename之后的旧文件。如果两个进程同时执行rename第二个rename会因为源文件已经不存在而抛异常或者更糟——把进程A刚生成的新文件给rename到别处去。结果就是日志散落在旧文件里新文件没人写甚至整个滚动过程直接崩掉。这种问题不会每次都复现但每过一段时间就出现一次排查起来极其折磨人。2.2 线程锁保护不了进程跨进程需要文件锁很多人第一个想到的办法是给自定义Handler里加一个threading.Lock但这玩意儿在进程之间毫无用处——每个进程都有自己的内存空间线程锁锁住的只是当前进程里的其他线程其他进程管不着。真正要锁住多进程之间的竞争只有两条路操作系统提供的跨进程信号量比如fcntl.flock或msvcrt.locking或者一个所有进程都能共享的第三方锁文件。fcntl.flock是Linux下最直接的办法对日志文件本身加排他锁锁住整个“检查时间点→rename→建新文件→写入”的过程其他进程在这段时间只能等待等锁释放后才能继续。2.3 还有个隐蔽问题多进程各自维护“计划滚动时间”时间基准不一致标准TimedRotatingFileHandler滚动的触发依据是Handler实例内部维护的nextRolloverTime字段——它是进程内私有的内存变量。进程A和进程B启动时间不同、各自计算的nextRolloverTime可能会有细微差异哪怕只差几十毫秒都会导致两个进程不在同一瞬间触发滚动进而出现上面说的“A在滚动B在往旧文件写”的割裂状态。要解决这个基准不一致必须引入一个外部共享存储来记录“上一次滚动发生的时间”比如一个时间戳文件。所有进程滚动前先去读这个文件判断“当前时间减去文件里的最后滚动时间是否已经超过滚动周期”是才真正执行滚动。这样即便各进程内部的内存状态千差万别读到的外部基准是一致的。3. 实操方案一套多进程安全、兼顾按大小和按时间分割的Handler下面这套方案是我在多个生产项目里实测过的核心思路就三条用文件锁串行化滚动动作、用共享时间戳文件校准滚动基准、把“按体积”和“按时间”两个滚动条件都塞进同一个滚动流程里。代码基于Python 3.8全程只用标准库。3.1 总体架构设计整个Handler的滚动判定逻辑一句话总结就是每次写入一条日志前先拿锁然后检查“时间周期到了没”或“体积阈值超了没”只要满足其一就执行滚动否则正常写文件。import os import time import logging import logging.handlers import fcntl from datetime import datetime, timedelta from threading import RLock class MultiProcessSafeSizeTimeRotatingFileHandler(logging.Handler): 多进程安全的日志Handler支持按时间周期和按文件大小双条件滚动。 设计要点 1. 用 fcntl.flock 对日志文件加排他锁串行化滚动动作 2. 用独立的时间戳文件记录最近一次滚动时间统一多进程的滚动判断基准 3. rollover 时同时检查时间条件和体积条件满足任一即滚动 4. 内部加 RLock保证同一进程内线程并发安全。 def __init__(self, filename, whenmidnight, interval1, maxBytes0, backupCount0, encodingutf-8, delayTrue): super().__init__() self.baseFilename os.path.abspath(filename) self.when when.upper() self.interval interval self.maxBytes maxBytes self.backupCount backupCount self.encoding encoding # 这里用 delayTrue 的关键原因 # 文件一开始不打开等第一条日志进来再打开。 # 在多进程环境里如果启动时就打开文件 # 所有进程的 fd 可能指向同一个 inode滚动后句柄更不好管理。 self.delay delay self.stream None self._lock RLock() # 解析时间滚动周期得到单次周期的秒数 self.computeRolloverInterval() # 初始化“上次滚动时间” # 不直接用内存变量而是从时间戳文件读读不到再用当前时间 self.rolloverAt self.read_last_rollover_time() def computeRolloverInterval(self): 把 when 字符串换算成 interval 对应的秒数。 只处理常见的几种周期其他可自行扩展。 if self.when S: self.rollover_seconds 1 elif self.when M: self.rollover_seconds 60 elif self.when H: self.rollover_seconds 3600 elif self.when D or self.when MIDNIGHT: self.rollover_seconds 86400 elif self.when W0: self.rollover_seconds 86400 * 7 # 星期一 else: self.rollover_seconds 864003.2 时间戳文件的读写与滚动判定逻辑先解释一下为什么要用独立的时间戳文件而不是直接在锁内更新self.rolloverAt内存变量。原因很实际假如进程A先拿到文件锁执行完滚动把时间戳文件更新成当前时间然后释放锁。进程B拿到锁时它读时间戳文件发现“上次滚动是刚发生的”就不会再滚一次。如果只用各自的内存变量进程B不知道A刚才已经滚过了它自己的rolloverAt还是老早以前的值于是又执行一遍滚动把A刚滚出来的新文件再rename一遍造成误滚动。def read_last_rollover_time(self): 从独立的时间戳文件读取上次滚动时间。 如果文件不存在或读取失败用当前时间作为初始值。 ts_file self.baseFilename .rollover_time try: if os.path.exists(ts_file): with open(ts_file, r, encodingutf-8) as f: ts int(f.read().strip()) return ts except Exception: pass return int(time.time()) def write_last_rollover_time(self, tsNone): 把当前滚动发生的时间写入时间戳文件。 注意写的时候是覆盖写不是追加。 if ts is None: ts int(time.time()) ts_file self.baseFilename .rollover_time with open(ts_file, w, encodingutf-8) as f: f.write(str(ts))滚动判定条件要注意一个细节时间条件使用的是绝对时间差而不是标准库那种“下次动作点一到就滚动”的逻辑。用绝对时间差的优势是多进程下即使某条日志写入时距上次滚动已经过了三四个小时比如中间一直没日志下次写入时一次性把过期周期全补上也只会滚动一次文件后缀还是按滚动发生的实际时间生成不会出现中间空档期文件名乱跳的问题。def should_rollover(self, record): 判断当前是否需要滚动。 返回 True 表示需要滚动。 # 条件1按时间 now int(time.time()) if now - self.rolloverAt self.rollover_seconds: return True # 条件2按大小 if self.maxBytes 0 and self.stream is not None: try: self.stream.flush() cur_size os.path.getsize(self.baseFilename) if cur_size self.maxBytes: return True except OSError: # 文件可能被外部删了或者正在滚动中保守判断不滚动 # 同时把流重新打开 self._open_file() pass return False3.3 文件加锁、滚动执行与多进程互斥的关键代码这是整个Handler的核心——doRollover()。每一步注释里我都会写清楚这个动作在防什么竞争。def doRollover(self): 执行滚动。整个方法必须在持有文件锁和线程锁的情况下调用。 if self.stream: self.stream.close() self.stream None # 先拿到当前文件名对应的 inode # rename 之后新写入必须落到新文件上 if os.path.exists(self.baseFilename): backup_name self._generate_backup_name() # 这里用 try exists 判断的原因是 # 锁保护的是持有锁的过程但进程 A 拿到锁之前 # 进程 B 可能已经把文件 rename 走了。 # 所以真正rename前要再检查一次源文件是否存在。 try: os.rename(self.baseFilename, backup_name) except FileNotFoundError: # 源文件已经没了说明另一个进程已经替我们滚过了 pass # 无论上面的 rename 做没做都要重新打开新文件 self._open_file() # 更新时间戳基准 now int(time.time()) self.rolloverAt now self.write_last_rollover_time(now) # 清理最老的后备日志 self._cleanup_old_backups()_generate_backup_name()里用日期时间做后缀比标准库TimedRotatingFileHandler那套“带序号的滚动文件轮换”更直观而且天然规避了“多进程都往同一序号上挤”的问题def _generate_backup_name(self): 生成后备文件名app.log - app.log.2024-01-01_14-30-00.log 时间精确到秒重复概率极低。 ts datetime.now().strftime(%Y-%m-%d_%H-%M-%S) return f{self.baseFilename}.{ts}.log后备文件清理逻辑按时间后缀排序只保留最近backupCount个def _cleanup_old_backups(self): 清理超龄后备文件。 通过 glob 匹配同名前缀加时间后缀的日志文件砍掉最老的。 if self.backupCount 0: return import glob pattern f{self.baseFilename}.*.log files glob.glob(pattern) # 按文件名倒序排最新的在最前面 files.sort(reverseTrue) # 只保留前 backupCount 个 for old in files[self.backupCount:]: try: os.remove(old) except FileNotFoundError: pass3.4 emit 入口与锁的组装emit()是整个Handler对外暴露的唯一门口锁的获取顺序是先线程锁再文件锁。顺序不能反——如果先拿文件锁再拿线程锁同一进程内两个线程同时写的时候可能会出现死锁等待线程1拿着文件锁等线程锁线程2拿着线程锁等文件锁。def emit(self, record): 写日志入口。整个写入过程都加锁确保单条日志的完整性。 try: # 线程锁保证同进程内并发安全 with self._lock: msg self.format(record) # 多进程文件锁保证跨进程的滚动互斥 # 注意这里锁的是 baseFilename 文件本身 fd os.open(self.baseFilename, os.O_RDWR | os.O_CREAT) try: fcntl.flock(fd, fcntl.LOCK_EX) # 先打开或确认文件流是好的 if self.stream is None: self._open_file() else: # 如果当前流的文件 inode 已经被其他进程 rename 过 # 需要重新打开新文件否则会继续写旧文件。 self._reopen_if_inode_changed(fd) # 判断是否需要滚动 if self.should_rollover(record): self.doRollover() # 真正写入 if self.stream: self.stream.write(msg \n) self.stream.flush() finally: try: fcntl.flock(fd, fcntl.LOCK_UN) except Exception: pass os.close(fd) except Exception: self.handleError(record)_reopen_if_inode_changed()的作用是防止下面这个经典问题进程A拿到锁后滚动完成释放锁。进程B拿到锁时它之前持有的self.stream还指向旧的被rename的文件如果直接往旧文件写日志就永远落在过期文件里了。通过比对“当前打开文件的fd”和“baseFilename 当前的inode”不一致就重新打开一次。def _reopen_if_inode_changed(self, fd): 如果当前打开文件的 inode 和 baseFilename 对应的 inode 不一致 说明文件已经被 rename 过了需要重新打开新文件。 try: new_stat os.fstat(fd) old_stat os.fstat(self.stream.fileno()) if new_stat.st_ino ! old_stat.st_ino: self.stream.close() self.stream None self._open_file() except Exception: self.stream None self._open_file() def _open_file(self): 后面追加写方式打开新文件。 if self.stream is None: self.stream open(self.baseFilename, a, encodingself.encoding) def close(self): with self._lock: if self.stream: self.stream.close() self.stream None super().close()3.5 测试验证多进程并发写入滚动后日志不丢不乱代码写完了但必须用真实的多进程写入验证一遍否则根本看不出锁有没有生效。我一般用multiprocessing.Pool同时起8个进程每个进程疯狂写几千条日志设置maxBytes1MB、whenS每秒滚动跑几分钟后统计日志总条数应当和写入总数完全一致所有滚动出来的备份文件格式统一没有出现文件内容互相覆盖的行。import logging import time from multiprocessing import Pool handler MultiProcessSafeSizeTimeRotatingFileHandler( test_multi.log, whenS, interval10, maxBytes1024 * 1024, backupCount30, ) logger logging.getLogger(multi_test) logger.setLevel(logging.INFO) logger.addHandler(handler) def worker(pid): for i in range(2000): logger.info(fprocess-{pid}-msg-{i}) return pid if __name__ __main__: with Pool(8) as p: results p.map(worker, range(8)) print(done, total processes:, len(results))跑完之后用命令统计行数cat test_multi.log.*.log test_multi.log | wc -l正常结果应该是8 * 2000 16000行一行不多一行不少。如果少于16000那就是滚动瞬间有日志被吞掉了如果多于16000说明某条日志被写了两次锁内逻辑还有漏洞。4. 配置落地把自定义Handler接到项目配置里的两种姿势自定义Handler写好了接下来要解决的是怎么接进现有项目。大多数项目用的是logging.config.dictConfig或fileConfig这里给出一个完整的接入示例。4.1 配置化接入dictConfig 的完整写法重点说一下class字段的写法模块名:类名的格式logging会通过import_string动态加载。如果你的Handler放在utils/logging_ext.py里就写成utils.logging_ext.MultiProcessSafeSizeTimeRotatingFileHandler。import logging.config LOGGING_CONFIG { version: 1, disable_existing_loggers: False, formatters: { standard: { format: %(asctime)s [%(levelname)s] %(name)s: %(message)s }, }, handlers: { app: { class: utils.logging_ext.MultiProcessSafeSizeTimeRotatingFileHandler, filename: /var/log/myapp/app.log, when: MIDNIGHT, interval: 1, maxBytes: 200 * 1024 * 1024, backupCount: 30, encoding: utf-8, formatter: standard, }, }, root: { handlers: [app], level: INFO, }, } logging.config.dictConfig(LOGGING_CONFIG)4.2 多进程服务里怎么挂Logger在gunicorn等部署场景里多个worker进程都会加载同一份配置、初始化自己的Handler实例。这套方案每个进程一份Handler实例不冲突因为文件锁才是仲裁者。但有两个使用细节要特别注意不要用multiprocessing.Queue或queue.Queue把日志聚合成单进程写——那套方案确实能避免文件竞争但会引入额外的队列满回压、进程崩溃日志丢失等问题不如直接文件锁来得简单直接。双Handler标准库组合不要用——一句话标准库的RotatingFileHandler和TimedRotatingFileHandler同时挂到同一个logger等于把两套滚动逻辑叠在一起报错都是小事日志翻倍重写才是大事。4.3 基于logging标准日志循环引用的一个问题自定义Handler里如果format出现异常比如某个字段缺失emit()会走handleError()默认行为是把错误输出到sys.stderr不会影响主流程。这个兜底机制别关一旦关了日志系统自身的故障会直接淹没在业务异常里排查起来更痛苦。5. 常见问题与排查技巧实录这部分全部来自我在真实环境里踩过的坑按优先级从高到低整理成速查表。5.1 为什么我配置了maxBytes文件还是无限增长最常见的三个原因backupCount没设置或设为0Handler没有挂到Root Logger上业务自己的Logger单独new了一个没接Handler写入的Logger名称和配置的Logger名称对不上导致走了默认的空Handler路径。最直接的排查方式在代码里print(logger.handlers)看一眼当前Logger到底挂了几个Handler以及Handler的实际参数是否等于配置值。5.2 为什么滚动之后日志文件不重建一直写到旧文件名里这个坑多发生在fileConfig接标准TimedRotatingFileHandler的场景下。上述方案已经通过“滚动后重新打开新文件”的逻辑规避了。但如果你还在用标准库Handler遇到这个现象大概率是delayFalse导致文件句柄被过早打开rename之后句柄还滞留在旧inode上。建议切到上述自定义Handler一劳永逸。5.3 为什么多进程跑起来后某个进程写日志时报“Bad file descriptor”典型的文件句柄失效错误发生在进程fork之后父进程已经打开了日志文件子进程直接继承了fd之后父进程滚动把文件rename了子进程还拿着旧fd写入此时内核可能报EBADF。解决方案就是方案里反复强调的每次写入都用os.open重新打开或比对inode不长期持有旧fd。5.4 排查技巧从“日志文件被锁”到“找到死锁”的最快路径如果怀疑文件锁没释放可以查看是否有进程长期持有文件锁lsof /var/log/myapp/app.log从输出里能看到持有该文件的进程PID和fd状态。正常滚动过程锁的持有时间应该在毫秒级如果看到某个进程长时间持有写锁跑py-spy dump --pid PID拿到它的当前栈基本上就能定位到是卡在文件IO还是卡在业务逻辑里。6. 一个容易被忽略的进阶细节滚动失败时的兜底策略真实生产环境里磁盘写满、权限被改、文件被外部脚本移动等意外情况几乎必然会发生。上面这套Handler在doRollover()里已经做了FileNotFoundError兜底但更彻底的方案是在试图rename时检测目标备份文件是否已存在如果存在就加一个毫秒级时间戳后缀保证备份文件绝不会互相覆盖def _generate_backup_name(self): ts datetime.now().strftime(%Y-%m-%d_%H-%M-%S) backup_name f{self.baseFilename}.{ts}.log # 如果同秒内发生两次滚动概率极低追加毫秒随机数避免覆盖 if os.path.exists(backup_name): ms datetime.now().strftime(%f) # 微秒 backup_name f{self.baseFilename}.{ts}_{ms}.log return backup_name这个兜底写不写看你对数据完整性的要求。日志这东西丢了能接受重复了也能接受但当你需要排查线上问题的时候发现某一条日志因为文件名覆盖而消失那才是真崩溃。这套多进程安全的日志切割方案我在几个需要长时间稳定运行的服务里用了很久从来没有因为滚动竞争丢过日志。核心心得其实就一句话多进程环境下的日志滚动本质是在把“一个进程内部的文件管理逻辑”升级成“多进程之间用锁协调的分布式文件操作”。理解了这个本质后面所有看似繁琐的加锁、比对inode、时间戳基准其实都是顺理成章的必要成本。如果你正在被多进程日志乱滚折磨不妨把这套代码直接拿过去跑一遍测试再根据你的实际场景改改when参数和备份数量应该会省掉很多自己摸索的时间。
阅读完成 · 觉得有帮助？
