解决 Django 多进程下,logging 记录日志错乱问题

本文涉及的产品
日志服务 SLS,月写入数据量 50GB 1个月
简介: 之前写过一篇文章 Django 中如何优雅的记录日志,本以为代码上线之后,就可以愉快的看日志,通过日志来分析问题了,但现实总是跟想象不同,两个异常现象纷纷挥起大手,啪啪地打在我的脸上。

之前写过一篇文章 Django 中如何优雅的记录日志,本以为代码上线之后,就可以愉快的看日志,通过日志来分析问题了,但现实总是跟想象不同,两个异常现象纷纷挥起大手,啪啪地打在我的脸上。


两个异常如下:

  1. 日志写入错乱;
  2. 日志并没有按天分割,而且还会丢失。


在网上查找一些资料,发现了原因所在:


Django logging 是基于 Python logging 模块实现的,logging 模块是线程安全的,但不能保证多进程安全。我的 Django 项目是通过 uwsgi 启的多进程,所以就发生了上述两个问题。


下面来详细描述一下这个异常过程,假设我们每天生成一个日志文件 error.log,每天凌晨进行日志分割。那么,在单进程环境下是这样的:

  1. 生成 error.log 文件;
  2. 写入一天的日志;
  3. 零点时,判断 error.log-2020-05-15 是否存在,如果存在则删除;如果不存在,将 error.log 文件重命名为 error.log-2020-05-15;
  4. 重新生成 error.log 文件,并将 logger 句柄指向新的 error.log。


再来看看多进程的情况:

  1. 生成 error.log 文件;
  2. 写入一天的日志;
  3. 零点时,1 号进程判断 error.log-2020-05-15 是否存在,如果存在则删除;如果不存在,将 error.log 文件重命名为 error.log-2020-05-15;
  4. 此时,2 号进程可能还在向 error.log 文件进行写入,由于写入文件句柄已经打开,所以会向 error.log-2020-05-15 进行写入;
  5. 2 号进程进行文件分割操作,由于 error.log-2020-05-15 已经存在,所以 2 号进程会将它删除,然后再重命名 error.log,这样就导致了日志丢失;
  6. 由于 2 号进程将 error.log 重命名为 error.log-2020-05-15,也会导致 1 号进程继续向 error.log-2020-05-15 写入,这样就造成了写入错乱。

原因清楚了,那么,有什么解决办法呢?两个方案:


使用 concurrent-log-handler 包


这个包通过加锁的方式实现了多进程安全,并且可以在日志文件达到特定大小时,分割文件,但是不支持按时间分割。

包的源码我并没有仔细研究,也就没办法再细说了,大家如果感兴趣的话可以自己找来看。

由于我的需求是按时间进行分割,显然就不能用了,自己写吧。


重写 TimedRotatingFileHandler


通过上面的分析可以知道,出问题的点就是发生在日志分割时,一是删文件,二是没有及时更新写入句柄。

所以针对这两点,我的对策就是:一是去掉删文件的逻辑,二是在切割文件时,及时将写入句柄更新到最新。


代码如下:


# 解决多进程日志写入混乱问题
import os
import time
from logging.handlers import TimedRotatingFileHandler
class CommonTimedRotatingFileHandler(TimedRotatingFileHandler):
    @property
    def dfn(self):
        currentTime = int(time.time())
        # get the time that this sequence started at and make it a TimeTuple
        dstNow = time.localtime(currentTime)[-1]
        t = self.rolloverAt - self.interval
        if self.utc:
            timeTuple = time.gmtime(t)
        else:
            timeTuple = time.localtime(t)
            dstThen = timeTuple[-1]
            if dstNow != dstThen:
                if dstNow:
                    addend = 3600
                else:
                    addend = -3600
                timeTuple = time.localtime(t + addend)
        dfn = self.rotation_filename(self.baseFilename + "." + time.strftime(self.suffix, timeTuple))
        return dfn
    def shouldRollover(self, record):
        """
        是否应该执行日志滚动操作:
        1、存档文件已存在时,执行滚动操作
        2、当前时间 >= 滚动时间点时,执行滚动操作
        """
        dfn = self.dfn
        t = int(time.time())
        if t >= self.rolloverAt or os.path.exists(dfn):
            return 1
        return 0
    def doRollover(self):
        """
        执行滚动操作
        1、文件句柄更新
        2、存在文件处理
        3、备份数处理
        4、下次滚动时间点更新
        """
        if self.stream:
            self.stream.close()
            self.stream = None
        # get the time that this sequence started at and make it a TimeTuple
        dfn = self.dfn
        # 存档log 已存在处理
        if not os.path.exists(dfn):
            self.rotate(self.baseFilename, dfn)
        # 备份数控制
        if self.backupCount > 0:
            for s in self.getFilesToDelete():
                os.remove(s)
        # 延迟处理
        if not self.delay:
            self.stream = self._open()
        # 更新滚动时间点
        currentTime = int(time.time())
        newRolloverAt = self.computeRollover(currentTime)
        while newRolloverAt <= currentTime:
            newRolloverAt = newRolloverAt + self.interval
        # If DST changes and midnight or weekly rollover, adjust for this.
        if (self.when == 'MIDNIGHT' or self.when.startswith('W')) and not self.utc:
            dstAtRollover = time.localtime(newRolloverAt)[-1]
            dstNow = time.localtime(currentTime)[-1]
            if dstNow != dstAtRollover:
                if not dstNow:  # DST kicks in before next rollover, so we need to deduct an hour
                    addend = -3600
                else:           # DST bows out before next rollover, so we need to add an hour
                    addend = 3600
                newRolloverAt += addend
        self.rolloverAt = newRolloverAt
复制代码


在 settings handles 中引入上面 class 即可。

生产环境已经上线了两周,运行稳定,没有再发生异常。

以上。


相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
目录
相关文章
|
3月前
|
存储 监控 数据库
Django 后端架构开发:高效日志规范与实践
Django 后端架构开发:高效日志规范与实践
59 1
|
19天前
|
监控 应用服务中间件 网络安全
#637481#基于django和neo4j的日志分析系统
#637481#基于django和neo4j的日志分析系统
31 4
logging 日志 模块
logging 日志 模块
|
3月前
|
消息中间件 JSON 自然语言处理
Python多进程日志以及分布式日志的实现方式
python日志模块logging支持多线程,但是在多进程下写入日志文件容易出现下面的问题: PermissionError: [WinError 32] 另一个程序正在使用此文件,进程无法访问。 也就是日志文件被占用的情况,原因是多个进程的文件handler对日志文件进行操作产生的。
|
3月前
|
存储 安全 Python
[python]使用标准库logging实现多进程安全的日志模块
[python]使用标准库logging实现多进程安全的日志模块
|
3月前
|
JavaScript 开发工具
Electron 开发过程中主进程的无法看到 console.log 输出怎么办
Electron 开发过程中主进程的无法看到 console.log 输出怎么办
|
4月前
|
消息中间件 JSON 自然语言处理
python多进程日志以及分布式日志的实现方式
python日志在多进程环境下的问题 python日志模块logging支持多线程,但是在多进程下写入日志文件容易出现下面的问题: PermissionError: [WinError 32] 另一个程序正在使用此文件,进程无法访问。 也就是日志文件被占用的情况,原因是多个进程的文件handler对日志文件进行操作产生的。
|
4月前
|
Python
Django日志配置(4)
【7月更文挑战第4天】在Django中配置日志的方法非常简单,只需要在 setting 文件中添加配置项,系统会自动生成相应的日志文件,也可以配置调试时显示内容,报错发送邮件等操作。
79 0
|
6月前
|
安全 Python
Python 多进程日志输出到同一个文件并实现日志回滚
Python 多进程想要实现将日志输出到同一个文件中,使用同一个日志句柄,且日志需要按照日期,大小回滚。
|
6月前
|
存储 JSON 运维
【运维】Powershell 服务器系统管理信息总结(进程、线程、磁盘、内存、网络、CPU、持续运行时间、系统账户、日志事件)
【运维】Powershell 服务器系统管理信息总结(进程、线程、磁盘、内存、网络、CPU、持续运行时间、系统账户、日志事件)
141 0