记一个 Python logging 多进程 rotate 问题

线下环境的日志轮转一直工作的很奇怪,今天必须要解决一下了。

我们 Django 的 settings 里面 LOGGING 配置了日志轮转,满了 100M 就开新的文件。奇怪的是我每次去看日志,发现都有很多 log 才几 M,根本没到 100M 就“轮转”了。实际的配置简化如下。

这个配置基本上是没有问题的。我把 maxBytes 改成 30M,然后观察文件的大小。发现刚开始是正常的,/var/log/django.log 一直在打,逐渐到了 30M。这个时候神奇的事情发生了,到了轮转的时刻,旧日志被 rename 成了 django.log.1 ,然后又被 rename 成了 django.log.2 ,突然,十几个文件都开始写入了,这些文件 last_modify 时间一直在更新,也一直在变大。

思考片刻,我觉得问题出在 Python 的 logging 模块并没有去处理多进程的问题。我的 Django 应用是用 uwsgi 跑的,开了 16 个进程。当日志快要超过 maxBytes 的时候,第一个进程执行了 rename、新开文件 A 的操作(这个具体的流程,看一下文档里对 rotate 的流程描述就明白了),开始朝新开的文件 A 写入;这时候第二个进程将第一个进程打开的新文件给 rename 了,然后自己又新开一个文件 B 写入。但是第一个进程依然持有文件 A 的句柄的,所以依然可以往 A 里面写入。以此类推,就导致 16 个进程大家都持有了一个文件句柄,大家同时向不同的文件写入。(这段流程是我根据现象推测的,如果不正确请指正)。

Python 自身的 logging 模块不关心多进程写文件的问题,我觉得是可以接受的。一个 Python 程序就是一个进程实例,无须关心所在的环境是什么样子。我考虑开始通过其他的方案解决这个问题。

尝试了 uwsgi 的 daemonize,遇到了两个问题:1)uwsgi 的日志和 django 的日志混在一起了 2)原本 uwsgi 的 log 是可以 rotate 的,结果我加上 daemonize 之后,日志里面出现一下错误提示,竟然直接不转了。

考虑到引入 syslog 这种第三方 log 进程或者 rotate,会增加运维的复杂度。而且得重新考虑 rotate、删除、写入不同文件等的方案,所以也没有去考虑用第三方进程的方式。

这个问题实际上是 rotate 操作执行的时候,导致了竞争条件,被执行了多次的问题。所以自然而然就想到,如果在执行这个操作的时候,能加一个锁就好了。只有一次 rotate 会被执行。找到了一个实现了这个功能 mrfh 的库。代码只有几百行,里面继承了 BaseRotatingHandler 实现了自己的一个 Handler,做的事情很简单,就是在 rotate 的时候增加一个基于文件的锁(基于 fcntl),保证 rotate 能只做一次就好了。

引入也很简单,只是安装好依赖,然后将 logging 配置的 handler 改成此库里面的 handler 就好了。

现在打出来的日志都是整整齐齐的 100M 了,另外他会在日志目录下生成一个 .filename.log.lock 作为锁,无伤大雅。

Leave a comment

电子邮件地址不会被公开。 必填项已用*标注