记一个 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 作为锁,无伤大雅。



记一个 Python logging 多进程 rotate 问题”已经有一条评论

Leave a comment

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