Django 1.8 日志处理

Django 日志

我们做一个系统,需要对一些时间留下痕迹以便调试很正常,这个时候我们会需要在 django 中记录日志。

开始的做法是自己写一个日志的 model,后来发现不应该这样做,在 Django 1.8 版本中早就有了 Logging 的支持,具体看下面这篇文档,这里只是对阅读过程中的一些摘要进行记录。

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


一、核心概念

  • Loggers
  • Handlers
  • Filters
  • Formatters

Loggers

logger 简单来说就是访问日志的入口,一个 Logger 会被配置一个 log level (后称日志等级),日志等级有如下这些:

  • DEBUG: 用于调试的日志信息
  • INFO: 通用系统信息
  • WARNING: 表示产生了一个小问题 (minor problem)
  • ERROR: 表示产生了一个大问题 (major problem)
  • CRITICAL: 表示产生了一个严重问题 (critical problem)

写到 logger 中的每条信息被称作 Log Record (后称日志记录),每条日志记录也有一个 日志等级,每条日志记录也可以包含一些有用的 metadata (元数据),用于描述被日志的事件。这里可以放一些调用堆栈或者错误码之类的东西。

当一条日志信息写进 logger 的时候,这条信息的日志等级就会跟 logger 的日志等级比较,如果超出 logger 的等级,就会做进一步的处理,否则这条信息就会忽略。

一旦 logger 决定一条日志信息要被处理,它就会被传到一个 Handler(处理器)中。

Handler

处理器是用来定义发生错误时触发的日志行为的,例如将信息输出到屏幕、写入文件或者通过网络传输。

Handler 也有一个日志等级,如果日志记录的等级低于 Handler 的等级,就会被忽略。

一个 Logger 可以对应多个 Handler,每个 Handler 有不同的日志等级,这样的话,就可以对传入的不同等级的信息做出不同的处理。

例如,我们可以安装一个处理器来处理 ERROR 和 CRITICAL 的信息,然后另作一个处理器处理所有级别的日志供详细的分析。

Filter

过滤器用来对传递给 Logger 或者 Handler 的日志信息提供附加的控制。

默认情况下,所有满足级别的日志信息都会被处理,但是我们可以通过 filter 来过滤掉 CRITICAL 级别的日志,然后仅允许 ERROR 级别的日志通过。

filter 也可以被用来对前面被忽略掉的日志进行修改,例如,我们可以在一定条件下将 ERROR 日志降级为 WARNING 日志。

过滤器可以安装在 logger 或者 handler 上,多个过滤器可以形成一个链来接连产生作用。

Formatters

最终一个日志是要被渲染成文本的,formatter 描述了文本的格式,一个 formatter 通常包括了含有 LogRecord attributes python 格式化字符串,你也可以自己扩展特定的格式化规则。


二、使用日志

举个例子即可,不废话:

# import the logging library
import logging

# Get an instance of a logger
logger = logging.getLogger(__name__)

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

命名 Logger

通过 logging.getLogger() 可以获取(如不存在先创建)一个 logger,通过传入的名称参数来确定一个单独的 logger.

方便起见,一般用 __name__ 作为传入的参数,它会获取到当前的 python module 名称。这样可以方便地按照模块区分,如果觉得这样不好,可以自己写一个用点分割的 logger 标识符。

# Get an instance of a specific named logger
logger = logging.getLogger('project.interesting.stuff')

像上面这个例子定义了一个分层的 logger,project.interesting logger 被认为是 project.interesting.stuff logger 的父 logger,以此类推。

为什么分层很重要?因为 logger 可以被设置为冒泡到他们的父亲,这样的话我们就可以为这一堆 logger 树的根 logger 定义 handler,能够捕获所有后代 logger 的日志信息。

冒泡默认是开的,如果不想冒泡可以手动关闭。

调用 logger

每个日志等级都有一个单独的调用语句:

  • logger.debug()
  • logger.info()
  • logger.warning()
  • logger.error()
  • logger.critical()

还有两种调用方式:

  • logger.log(): 手工指定日志等级
  • logger.exception(): 创建一个 ERROR 级别的日志信息,带上当时的异常调用栈。

日志的配置

仅仅会写入日志是不够的,下面讲如何配置 handler, filter 和 formatter 等

python 的日志类库提供了多种方式来配置日志,从程序接口到配置文件都有,django 使用的是 dictConfig 格式。

于是我们通过为 LOGGING 设置一个字典值来进行配置。这些配置描述了所有的 logger, handler, filter, formatter 的信息,和其他你想要的 logger 组件。

如果 LOGGING 配置了 disable_existing_logger 为 True (默认),所有的默认 logger 配置会被关掉,注意只是关掉而不是删掉,这些原来定义的 logger 还会存在,但不处理任何消息。但是小心这个配置,这一般不是你所期待的结果,你可以手动将其设置为 False。

你也可以将 LOGGING_CONFIG 设置为 None 然后自己管理日志.

日志模块一般在 Django 默认安装中加入,因此,你可以确定你的框架里面有这个功能(而不是安装第三方 app)。

配置范例

完整的配置说明见: https://docs.python.org/2/library/logging.config.html#configuration-dictionary-schema

1. 将 django.request logger 写入本地文件
LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'file': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'filename': '/path/to/django/debug.log',
        },
    },
    'loggers': {
        'django.request': {
            'handlers': ['file'],
            'level': 'DEBUG',
            'propagate': True,
        },
    },
}

注意 filename 指定的文件应该对运行 django 的用户开放写入权限。

2. 将错误输出到控制台 (console)

这个例子设置 django.requestdjango.security 这两个 logger 不去冒泡日志信息,这对本地开发而言很有用。

默认情况下,这个配置只会将 INFO 级别或以上的日志信息输出到控制台, Django 不会记录太多这样的信息,将 DJANGO_LOG_LEVEL (环境变量)配置为 DEBUG,你就可以看到日志会非常冗长,包括了所有的数据库查询。

import os

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
        },
    },
    'loggers': {
        'django': {
            'handlers': ['console'],
            'level': os.getenv('DJANGO_LOG_LEVEL', 'INFO'),
        },
    },
}
3. 一个大而全的例子
LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'verbose': {
            'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'
        },
        'simple': {
            'format': '%(levelname)s %(message)s'
        },
    },
    'filters': {
        'special': {
            '()': 'project.logging.SpecialFilter',
            'foo': 'bar',
        }
    },
    'handlers': {
        'null': {
            'level': 'DEBUG',
            'class': 'logging.NullHandler',
        },
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'simple'
        },
        'mail_admins': {
            'level': 'ERROR',
            'class': 'django.utils.log.AdminEmailHandler',
            'filters': ['special']
        }
    },
    'loggers': {
        'django': {
            'handlers': ['null'],
            'propagate': True,
            'level': 'INFO',
        },
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': False,
        },
        'myproject.custom': {
            'handlers': ['console', 'mail_admins'],
            'level': 'INFO',
            'filters': ['special']
        }
    }
}

关于这个配置的一些参数说明:

  • 指定了配置使用 dictConfig version 1 这种配置格式,目前其实只有这种。
  • 定义了两种 formatter
    • simple: 只输出日志级别和消息。完整配置格式
    • verbose: 还输出时间、进程、线程和错误产生的模块
  • 定义了一个过滤器 project.logging.SpecialFilter,名称是 special【下面这段不太懂: 如果这个过滤器在构造的时候需要附加的参数,他们可以通过在 filter 的键里面取值,例如再这个例子里面,如果需要参数 foo,那么就可以得到一个 bar 的值】
  • 定义了三个 handler:
    • null,将 DEBUG 以上的日志写到 /dev/null 黑洞;
    • console,将所有的 DEBUG 以上的日志写到 stderr,使用 simple 的 formatter
    • mail_admins,将所有 ERROR 以上的日志邮件发送给站点管理员,这个 handler 使用 special 的 filter
  • 定义了三个 logger:
    • django,将所有 INFO 以上的日志写到 null 处理器
    • django.request,将所有 ERROR 以上的日志写到 mail_admins 处理器,而且不再冒泡,也就是说 django 这个 logger 不会接到 django.request 产生的日志信息
    • myproject.custom,将所有 INFO 以上的日志,通过 special 过滤器之后发送类 console 和 mail_admins 处理其,也就是说 INFO 以上的会打印到控制台,ERROR 和 CRITICAL 日志信息会同时通过 email 发送。

自定义日志配置

如果不想使用 python 的 dictConfig 格式来配置 logger,可以制定自己的配置架构。

LOGGING_CONFIG 配置定义了用来配置 django logger 的可调用函数,默认的情况下这是 Python 的 logging.config.dictConfig() 函数。然而,如果想用一个不同的配置过程,你可以使用任意的函数,调用有且仅有一个参数,然后当日志执行配置的时候 LOGGING 的设置值会被传入这个函数。

禁用日志配置

如果你根本不想配置日志(或者自己来手动记录日志),你可以将 LOGGING_CONFIG 设置为 None。这样可以禁用 Django 默认的日志配置过程。下面有一个例子禁用了 Django 的日志配置然后手动配置日志:

# settings.py
LOGGING_CONFIG = None

import logging.config
logging.config.dictConfig(...)

LOGGING_CONFIG 设置为 None 仅仅意味着自动的日志配置过程被禁用,但是日志本身并没有被禁用。如果你禁用了配置过程,Django 依旧会执行调用记录日志,然后将日志配置退化到默认的日志记录行为。


Django 的日志扩展

Django 提供了一系列的工具用于处理在 WEB 服务环境中一些经常出现的日志需求。

Loggers

Django 提供了一些内置的 logger:

django

django 是一个捕获所有的根 logger,没有信息会直接发布到这个 logger 上面。

django.request

这个 logger 记录 HTTP 请求的处理,5XX 响应会抛出 ERROR 的日志,4XX 响应抛出 WARNING 日志。

这个 logger 接收的日志会带有如下的附加上下文:

  • status_code: HTTP 响应码
  • request: 产生日志的请求对象
django.db.backends

关于数据库交互的日志信息,例如每个应用级别的请求内部的 SQL 语句执行会将 DEBUG 级别的日志信息提交到这个 logger

这个 logger 捕获的信息会包括如下的额外上下文:

  • duration: SQL 语句执行的时间
  • sql: 执行的 sql 语句
  • params: SQL 语句里面调用的参数

出于性能考虑,SQL 日志只有在 settings.DEBUG 为 True 的时候才会生效,而不管对应 logging level 的 handler 有没有安装。

这个日志不包括框架级别的初始化(例如 SET TIMEZONE)或者事务处理查询(例如 BEGIN, COMMIT 和 ROLLBACK)。如果你想查看所有的数据库查询,请在你的数据库里面打开查询日志记录。

django.security.*

这个安全 logger 会接收到任意 SuspiciousOperation 异常出现时发出的信息。日志的等级取决于异常在何处被处理。大部分被日志的情况是 WARNING,当任意 SuspiciousOperation 被上抛到 WSGI 处理的时候,会被日志为一个 ERROR。

例如,当一个 HTTP Host 头提交的时候不匹配 ALLOW_HOSTS 的设置时,Django 会响应一个 400 响应,然后一个错误日志信息会被记录到 django.security.DisallowedHost 的 logger 中。

默认情况下,只有父 logger django.security 会被配置,然后所有子 logger 都会冒泡到这个父 logger。django.security logger 和 django.request logger 是被配置成一样的,任意 ERROR 事件都会发邮件给管理员。产生 400 的 SuspiciousOperation 请求会记录到 django.security 而不记录到 django.request logger。

如果禁止某一个特定的 SuspiciousOperation,你可以用下面例子的方式覆盖指定的 logger:

'loggers': {
    'django.security.DisallowedHost': {
        'handlers': ['null'],
        'propagate': False,
    },
},
django.db.backends.schemea

发生 Migrate 的时候被记录,注意不会记录通过 RunPython 执行的查询

Handler(处理器)

Django 提供了一个由 Python 提供的 handler。

class AdminEmailHandler(include_html=False, email_backend=None)

这个 handler 将接收到的所有日志消息发送 django 的站点管理员。

如果日志记录包含有 request 属性,整个请求的细节都会在右键中发送。

其中 include_html 参数用来控制当 DEBUG 为 True 的时候,是否将整个调试页面作为 HTML 附件发送。如果在配置中需要设置这个参数,将这个参数包含在 django.utils.log.AdminEmailHandler 中:

'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        'class': 'django.utils.log.AdminEmailHandler',
        'include_html': True,
    }
},

注意邮件的 HTML 版本包含了一个完整的回溯记录,包括各级调用栈的局部变量,然后还有你 django 的设置值。这个信息一般很敏感,你可能不想让它通过邮件发送出去。考虑使用 Sentry 之类的工具来让事情变得合理一些。你可能会手动屏蔽掉某些错误报告里面的信息,可以参考 Filtering error reports 以获得更多信息。

通过设置 AdminEmailHandleremail_backend 参数,可以通过覆盖 handler 的 email backend 设置来实现:

'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        'class': 'django.utils.log.AdminEmailHandler',
        'email_backend': 'django.core.mail.backends.filebased.EmailBackend',
    }
},

默认情况下,EMAIL_BACKEND 指定的 email 后台实例会被使用。

send_mail(subject, message, *args, **kwargs)

(这是 AdminEmailHandler 的方法),用来发送邮件给管理员,如果需要自定义它的行为,你可以派生 AdminEmailHandler 类,然后重写这个方法。

Filters(过滤器)

Django 提供了两个由 Python 提供的日志过滤器模块。

class CallbackFilter(callback)

这个过滤器接受一个回调函数(应当接收一个参数:被日志的记录)然后对每个记录执行一次。如果这个回调函数返回 False 的话,这个日志记录就不会被处理。

例如,我们需要在管理员邮件中滤掉 UnreadablePostError (当一个用户取消一个上传的时候产生),我们需要创建一个过滤函数:

from django.http import UnreadablePostError

def skip_unreadable_post(record):
    if record.exc_info:
        exc_type, exc_value = record.exc_info[:2]
        if isinstance(exc_value, UnreadablePostError):
            return False
    return True

然后这样将它加到日志配置中:

'filters': {
    'skip_unreadable_posts': {
        '()': 'django.utils.log.CallbackFilter',
        'callback': skip_unreadable_post,
    }
},
'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        'filters': ['skip_unreadable_posts'],
        'class': 'django.utils.log.AdminEmailHandler'
    }
},

class RequireDebugFalse

这个过滤器只有在 settings.DEBUG 为 False 的时候放行。

这个过滤器在默认的 LOGGING 配置里面被用来确保 AdminEmailHandler 仅当 DEBUG 为 False 的时候允许发送。

'filters': {
    'require_debug_false': {
        '()': 'django.utils.log.RequireDebugFalse',
    }
},
'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        'filters': ['require_debug_false'],
        'class': 'django.utils.log.AdminEmailHandler'
    }
},

class RequireDebugTrue

一样的,自行脑补。

Django 的默认日志配置

默认情况下,Django 配置如下的日志:

当 DEBUG 为 True 的时候:

  • django logger 将所有的 INFO 级别日志写到控制台。在这个时候 Django 不会产生这样的日志调用(所有的记录都是 DEBUG 级别的或者已经被 django.request 和 django.security 处理)
  • py.warnings logger,处理 warnings.warn() 抛出的警告,输出到控制台。

当 DEBUG 为 False:

  • django.requestdjango.security logger 发送 ERROR 或者 CRITICAL 级别的日志到 AdminEmailHandler。这些 logger 会忽略所有 WARNING 级别以下的日志记录,并且不会冒泡(即使当 DEBUG = True 的时候,它们也不会冒泡到 django 的顶级 Logger)

后记

本想稍微记录一下,不料边读边翻译居然把整篇文章翻译下来了,字数达到一万之巨,阿弥陀佛。

目前看来,我实际的需要是规划一个关于业务逻辑的 logger 树,然后通过文件写入的方式将日志写到文件中,然后在业务流程的节点上,构造这些 logger 并且择机记录。


【转载请附】愿以此功德,回向 >>

原文链接:https://www.huangwenchao.com.cn/2015/09/django-1-8-logging.html【Django 1.8 日志处理】

发表评论

电子邮件地址不会被公开。 必填项已用*标注