gunicorn 起了 8 个 worker,logging 用 FileHandler 指向同一个 app.log,压测后文件里出现半行 JSON 和错位的时间戳,行数比实际请求少三成,改成 RotatingFileHandler 后切割时还会丢一整段。
一开始怀疑是「日志行超过一次 write 的系统调用上限,被拆成两段写入」,查了一圈,方向不对。
真正麻烦的地方在于,几个原因的现象几乎一样。多个进程各自持有文件描述符,写入位置互相覆盖。也可能是RotatingFileHandler 在切割时各进程各自改名,句柄指向已删除的 inode。
不容易想到的是,容器里同时挂了 stdout 采集,两份输出混在一起。
上来先确认是不是多进程同时写一个文件
python -c "import os;print(os.getpid(), open('/proc/self/fd/1').readlink())"
随后改成按进程分文件再合并思路验证
python -c "print('app.log.%d' % __import__('os').getpid())"
再往下换用 WatchedFileHandler 交给 logrotate
python -c "import logging.handlers;print(logging.handlers.WatchedFileHandler('app.log'))"
或改成只写 stdout 由容器统一采集
python -c "import logging;logging.basicConfig(stream=__import__('sys').stdout);print('ok')"
改完先别撤,确认这几项。同一时段日志行数与网关访问数一致,没有半行记录,切割后旧文件完整保留,时间戳单调递增。
容易忽略的是,多进程写同一文件本质上是并发写,加锁只能缓解,最稳的做法是每个进程写自己的流,交给采集端拼接。改动前把原配置备份一份,出问题能马上回滚,这比任何技巧都实用。
