Django 中如何优雅的记录日志

日志是个好东西,但却并不是所有人都愿意记,直到出了问题才追悔莫及,长叹一声,当初要是记日志就好了。

但记日志却是个技术活,不能什么都不记,但也不能什么都记。如果记了很多没用的信息,反而给查日志排错的过程增加很多困难。

所以,日志要记录在程序的关键节点,而且内容要简洁,传递信息要准确。要清楚的反应出程序当时的状态,时间,错误信息等。

只有做到这样,我们才能在第一时间找到问题,并且解决问题。

logging 结构

在 Django 中使用 Python 的标准库 logging 模块来记录日志,关于 logging 的配置,我这里不做过多介绍,只写其中最重要的四个部分:LoggersHandlersFiltersFormatters

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 可以有不同的日志级别。这样就可以根据消息的重要性不同,来提供不同类型的输出。例如,你可以添加一个 HandlerERRORCRITICAL 消息发到你的 Email,再添加另一个 Handler 把所有的消息(包括 ERRORCRITICAL 消息)保存到文件里。

Filters

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

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

FilterLoggerHandler 中都可以添加,多个 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 来取值了。

以上就是在 Django 中记录日志的全部内容,希望大家都能好好记日志,因为一定会用得上。

参考文档:

https://docs.djangoproject.com/en/2.1/topics/logging/

https://www.dusaiphoto.com/article/detail/68/

https://juejin.im/post/5c34306cf265da616624a48c

https://www.xiaomastack.com/2019/01/11/record-api-log/

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 200,045评论 5 468
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 84,114评论 2 377
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 147,120评论 0 332
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 53,902评论 1 272
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 62,828评论 5 360
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,132评论 1 277
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,590评论 3 390
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,258评论 0 254
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,408评论 1 294
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,335评论 2 317
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,385评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,068评论 3 315
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,660评论 3 303
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,747评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 30,967评论 1 255
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 42,406评论 2 346
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 41,970评论 2 341

推荐阅读更多精彩内容