记一个 Python logging 多进程 rotate 问题

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

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

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "root": {"handlers": ["file"], "level": "INFO"},
    "formatters": {
        "verbose": {
            "format": "%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s"
        }
    },
    "filters": {
        "require_debug_true": {"()": "django.utils.log.RequireDebugTrue"},
        "require_debug_false": {"()": "django.utils.log.RequireDebugFalse"},
    },
    "handlers": {
        "file": {
            "level": "INFO",
            "filters": ["require_debug_false"],
            "class": "mrfh.MultiprocessRotatingFileHandler",
            "filename": "/var/log/django.log",
            "maxBytes": 1024 * 1024 * 100,  # 100MB
            "backupCount": 100,  # total = 100 x 100 M = 10G
            "formatter": "verbose",
            "encoding": "utf-8",
        },
    },
}

这个配置基本上是没有问题的。我把 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 之后，日志里面出现一下错误提示，竟然直接不转了。

unable to rotate log: rename(): No such file or directory [core/logging.c line 549]

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

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

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

"class": "mrfh.MultiprocessRotatingFileHandler"

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