django 多进程下日志写入错乱问题

B-ug

2025-05-16

问题记录

python, django

问题

django在配置TimedRotatingFileHandler切割日志时，输出的日志会在当日和昨日的日志文件中打印

原因

django logging 的实现，是基于python logging模块实现，而logging模块仅仅是线程安全的；而使用uwsgi启动项目时，如使用gunicorn启动多个worker，是启动多个进程的；logging模块并没有保证多进程安全

如果我们设定每个小时生成一个logger文件，设定写入的logger文件为info.log。这样他们的执行流程为：
在1个进程下，日志的写入原理是：

生成info.log；
写入1小时日志；
1小时之后，判定info.log-2018-11-30-1文件是否存在；如果存在则删除，然么重命名info.log为info.log-2018-11-30-1；
重新生成info.log并将logger的文件句柄指向新的info.log文件；

在2个进程下，日志的写入就会出现下面的现象：

生成info.log；
写入1小时日志；
1号进程先判定info.log-2018-11-30-1文件是否存在，如果存在则删除，然么重命名info.log为info.log-2018-11-30-1；
此时可能2号进程还在向info.log文件进行写入，由于写入流已经打开，所以他会继续向info.log-2018-11-30-1中写入。
等到2号进程开始重命名操作，此时info.log-2018-11-30-1已经存在，然后他会进行删除操作，这样就会导致日志丢失。
2号进程此时将info.log重命名为info.log-2018-11-30-1，也会导致1号进行继续向info.log-2018-11-30-1写入，这样就导致了日志错乱。

解决方案

使用logrotate （该方法不适用Windows）

通过logrotate切割日志文件

首先修改django日志配置

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'standard': {
            'format': '{"time": "%(asctime)s", "level": "%(levelname)s", "method": "%(method)s", "employee_id": "%(employee_id)s", "path": "%(path)s", "status_code": "%(status_code)s", "reason_phrase": "%(reason_phrase)s", "func": "%(module)s.%(funcName)s:%(lineno)d",  "message": "%(message)s"}',
            'datefmt': '%Y-%m-%d %H:%M:%S'
        },
    },
    'handlers': {
        'restful_api': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'filename': os.path.join(BASE_DIR, 'log/project.access.log'),
            'formatter': 'standard',
            'encoding': 'utf-8',
        },
    },
    # ... loggers 配置保持不变 ...
}

创建 logrotate 配置文件

sudo vim /etc/logrotate.d/blog

编辑以下内容，your_log_path更改为django的日志目录

/your_log_path/*.log {
    # 每天轮转
    daily
    # 保留30天
    rotate 30
    # 如果日志不存在则不报错
    missingok
    # 不压缩旧日志
    nocompress
    # 使用日期作为后缀
    dateext
    # 日期格式
    dateformat -%Y%m%d
    # 空文件不轮转
    notifempty
    # 备份并清空
    copytruncate
}

创建logrotate状态文件

# 创建状态文件目录
sudo mkdir -p /var/lib/logrotate

# 创建状态文件
sudo touch /var/lib/logrotate/logrotate.status

# 设置适当的权限
sudo chmod 644 /var/lib/logrotate/logrotate.status

测试配置

# 测试配置
sudo logrotate -d /etc/logrotate.d/blog

配置crontab

# 编辑 crontab
sudo crontab -e

# 添加以下行，设置在每天凌晨 0 点执行
0 0 * * * /usr/sbin/logrotate /etc/logrotate.d/blog

参考：
django 多进程下，日志写入错乱问题