django 中如何优雅的记录日志

logging 结构

在 Django 中使用 Python 的标准库 logging 模块来记录日志，关于 logging 的配置，不做过多介绍，只写其中最重要的四个部分：Loggers、Handlers、Filters 和 Formatters。

Loggers

Logger 即记录器，是日志系统的入口。它有三个重要的工作：

• 向应用程序（也就是你的项目）公开几种方法，以便运行时记录消息
• 根据传递给 Logger 的消息的严重性，确定消息是否需要处理
• 将需要处理的消息传递给所有感兴趣的处理器 Handler

每一条写入 Logger 的消息都是一条日志记录，每一条日志记录都包含级别，代表对应消息的严重程度。常用的级别如下：

• DEBUG：排查故障时使用的低级别系统信息，通常开发时使用
• INFO：一般的系统信息，并不算问题
• WARNING：描述系统发生小问题的信息，但通常不影响功能
• ERROR：描述系统发生大问题的信息，可能会导致功能不正常
• CRITICAL：描述系统发生严重问题的信息，应用程序有崩溃的风险

当 Logger 处理一条 消息时，会将自己的日志级别和这条消息配置的级别做对比。如果消息的级别匹配或者高于 Logger 的日志级别，它就会被进一步处理，否则这条消息就会被忽略掉。

当 Logger 确定了一条消息需要处理之后，会把它传给 Handler。

Handlers

Handler 即处理器，它的主要功能是决定如何处理 Logger 中的每一条消息，比如把消息输出到屏幕、文件或者 Email 中。

和 Logger 一样，Handler 也有级别的概念。如果一条日志记录的级别不匹配或者低于 Handler 的日志级别，则会被 Handler 忽略。

一个 Logger 可以有多个 Handler，每一个 Handler 可以有不同的日志级别。这样就可以根据消息的重要性不同，来提供不同类型的输出。例如，你可以添加一个 Handler 把 ERROR 和 CRITICAL 消息发到你的 Email，再添加另一个 Handler 把所有的消息（包括 ERROR 和 CRITICAL 消息）保存到文件里。

Filters

Filter 即过滤器。在日志记录从 Logger 传到 Handler 的过程中，使用 Filter 来做额外的控制。例如，只允许某个特定来源的 ERROR 消息输出。

Filter 还被用来在日志输出之前对日志记录做修改。例如，当满足一定条件时，把日志级别从 ERROR 降到 WARNING 。

Filter 在 Logger 和 Handler 中都可以添加，多个 Filter 可以链接起来使用，来做多重过滤操作。

Formaters

Formatter 即格式化器，主要功能是确定最终输出的形式和内容。

实现方式

说了这么多理论，是时候来看看具体怎么实现了。

其实最简单的方式就是直接在文件开头 import，然后程序中调用，像下面这样：

# import the logging library
import logging

# Get an instance of a logger
logging.basicConfig(
    format='%(asctime)s - %(pathname)s[%(lineno)d] - %(levelname)s: %(message)s',
    level=logging.INFO)
logger = logging.getLogger(__name__)

def my_view(request, arg1, arg):
    ...
    if bad_mojo:
        # Log an error message
        logger.error('Something went wrong!')

但这种方式并不好，如果在每个文件开头都这样写一遍，第一是麻烦，第二是如果哪天要改变输出日志格式，那每个文件都要改一遍，还不累死。

很显然，如果能封装成一个类，用的时候调用这个类，修改的时候也只需要修改这一个地方，是不是就解决这个问题了呢？

自定义类

下面来看看具体这个类怎么封装：

class CommonLog(object):
    """
    日志记录
    """
    def __init__(self, logger, logname='web-log'):
        self.logname = os.path.join(settings.LOGS_DIR, '%s' % logname)
        self.logger = logger
        self.logger.setLevel(logging.DEBUG)
        self.logger.propagate = False
        self.formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s: %(message)s', '%Y-%m-%d %H:%M:%S')

    def __console(self, level, message):
        # 创建一个FileHandler，用于写到本地
        fh = logging.handlers.TimedRotatingFileHandler(self.logname, when='MIDNIGHT', interval=1, encoding='utf-8')
        # fh = logging.FileHandler(self.logname, 'a', encoding='utf-8')
        fh.suffix = '%Y-%m-%d.log'
        fh.setLevel(logging.DEBUG)
        fh.setFormatter(self.formatter)
        self.logger.addHandler(fh)

        # 创建一个StreamHandler,用于输出到控制台
        ch = logging.StreamHandler()
        ch.setLevel(logging.DEBUG)
        ch.setFormatter(self.formatter)
        self.logger.addHandler(ch)

        if level == 'info':
            self.logger.info(message)
        elif level == 'debug':
            self.logger.debug(message)
        elif level == 'warning':
            self.logger.warning(message)
        elif level == 'error':
            self.logger.error(message)

        # 这两行代码是为了避免日志输出重复问题
        self.logger.removeHandler(ch)
        self.logger.removeHandler(fh)
        # 关闭打开的文件
        fh.close()

    def debug(self, message):
        self.__console('debug', message)

    def info(self, message):
        self.__console('info', message)

    def warning(self, message):
        self.__console('warning', message)

    def error(self, message):
        self.__console('error', message)

这是我在项目中还在用的一段代码，生成的文件按天进行切分。

当时写这段代码，有个问题折腾了我很久，就是显示代码报错行数的问题。当 formatter 配置 %(lineno)d 时，每次并不是显示实际的报错行，而是显示日志类中的代码行，但这样显示就失去意义了，所以也就没有配置，用了 %(name)s 来展示实际的调用文件。

其实，如果只是为了排错方便，记录一些日志，这个类基本可以满足要求。但如果要记录访问系统的所有请求日志，那就无能为力了，因为不可能手动在每个接口代码加日志，也没必要。

这个时候，很自然就能想到 Django 中间件了。

Django 中间件

中间件日志代码一共分三个部分，分别是：Filters 代码，middleware 代码，settings 配置，如下：

local = threading.local()


class RequestLogFilter(logging.Filter):
    """
    日志过滤器
    """

    def filter(self, record):
        record.sip = getattr(local, 'sip', 'none')
        record.dip = getattr(local, 'dip', 'none')
        record.body = getattr(local, 'body', 'none')
        record.path = getattr(local, 'path', 'none')
        record.method = getattr(local, 'method', 'none')
        record.username = getattr(local, 'username', 'none')
        record.status_code = getattr(local, 'status_code', 'none')
        record.reason_phrase = getattr(local, 'reason_phrase', 'none')

        return True


class RequestLogMiddleware(MiddlewareMixin):
    """
    将request的信息记录在当前的请求线程上。
    """

    def __init__(self, get_response=None):
        self.get_response = get_response
        self.apiLogger = logging.getLogger('web.log')

    def __call__(self, request):

        try:
            body = json.loads(request.body)
        except Exception:
            body = dict()

        if request.method == 'GET':
            body.update(dict(request.GET))
        else:
            body.update(dict(request.POST))

        local.body = body
        local.path = request.path
        local.method = request.method
        local.username = request.user
        local.sip = request.META.get('REMOTE_ADDR', '')
        local.dip = socket.gethostbyname(socket.gethostname())

        response = self.get_response(request)
        local.status_code = response.status_code
        local.reason_phrase = response.reason_phrase
        self.apiLogger.info('system-auto')

        return response

settings.py 文件配置：

MIDDLEWARE = [
    'django.middleware.security.SecurityMiddleware',
    'django.contrib.sessions.middleware.SessionMiddleware',
    'django.middleware.common.CommonMiddleware',
    'django.middleware.csrf.CsrfViewMiddleware',
    'django.contrib.auth.middleware.AuthenticationMiddleware',
    'django.contrib.messages.middleware.MessageMiddleware',
    'django.middleware.clickjacking.XFrameOptionsMiddleware',
      # 自定义中间件添加在最后
    'lib.log_middleware.RequestLogMiddleware'
]

LOGGING = {
    # 版本
    'version': 1,
    # 是否禁止默认配置的记录器
    'disable_existing_loggers': False,
    'formatters': {
        'standard': {
            'format': '{"time": "%(asctime)s", "level": "%(levelname)s", "method": "%(method)s", "username": "%(username)s", "sip": "%(sip)s", "dip": "%(dip)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'
        }
    },
    # 过滤器
    'filters': {
        'request_info': {'()': 'lib.log_middleware.RequestLogFilter'},
    },
    'handlers': {
        # 标准输出
        'console': {
            'level': 'ERROR',
            'class': 'logging.StreamHandler',
            'formatter': 'standard'
        },
        # 自定义 handlers，输出到文件
        'restful_api': {
            'level': 'DEBUG',
            # 时间滚动切分
            'class': 'logging.handlers.TimedRotatingFileHandler',
            'filename': os.path.join(LOGS_DIR, 'web-log.log'),
            'formatter': 'standard',
            # 调用过滤器
            'filters': ['request_info'],
            # 每天凌晨切分
            'when': 'MIDNIGHT',
            # 保存 30 天
            'backupCount': 30,
        },
    },
    'loggers': {
        'django': {
            'handlers': ['console'],
            'level': 'ERROR',
            'propagate': False
        },
        'web.log': {
            'handlers': ['restful_api'],
            'level': 'INFO',
            # 此记录器处理过的消息就不再让 django 记录器再次处理了
            'propagate': False
        },
    }
}

通过这种方式，只要过 Django 的请求就都会有日志，不管是 web 还是 Django admin。具体记录哪些字段可以根据项目需要进行获取和配置。

有一点需要注意的是，通过 request.user 来获取用户名只适用于 session 的认证方式，因为 session 认证之后会将用户名赋值给 request.user，所以才能取得到。

假设用 jwt 方式认证，request.user 是没有值的。想要获取用户名可以有两种方式：一是在日志中间件中解析 jwt cookie 获取用户名，但这种方式并不好，更好的方法是重写 jwt 认证，将用户名赋值给 request.user，这样就可以在其他任何地方调用 request.user 来取值了。

本以为代码上线之后，就可以愉快的看日志，通过日志来分析问题了，但现实总是跟想象不同，两个异常现象纷纷挥起大手，啪啪地打在我的脸上。

两个异常如下：

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 即可。

视图函数中使用log

import logging
log = logging.getLogger('middleware')
log.debug("......")

生产环境已经上线后，运行稳定，没有再发生异常。

以上。

__EOF__

本文作者：amgulen
本文链接：https://www.cnblogs.com/amgulen/p/16688859.html
关于博主：评论和私信会在第一时间回复。或者直接私信我。
版权声明：本博客所有文章除特别声明外，均采用 BY-NC-SA 许可协议。转载请注明出处！
声援博主：如果您觉得文章对您有帮助，可以点击文章右下角【推荐】一下。您的鼓励是博主的最大动力！