logging

flask celery logging 翻车记

虽然前面自己写过一个 Python Logging 的各种玩法(折腾 Python logging 的一些记录),结果没两个月,自己就在之前特意叮嘱过的地方翻了车

事情是这样的,我们的项目使用 Flask 作为业务框架,用 Celery 作为异步任务框架,按上篇里提到的,我们加了个 Filter 来加入 request_id 用于跟踪同一个 Web 请求或同一个 Task。所以,我们的 logging.conf 一开始是这样的,在 logfile 这个 Handler 里加入 request_id 并打印到日志文件,我们用阿里云的 logtail 把所有部署实例的日志文件都收集到一起,这一层 app Logger 往上抛是让终端都打印所有的日志,并且用 sentry 这个 Handler 在最上面收集各种异常报错

logging_conf = {
    "version": 1,
    "disable_existing_loggers": True,
    "filters": {
        "addRequestId": {
            "()": "app.utils.logging.request_filter.ContextFilter"
        }
    },
    "formatters": {
        "standard": {
            "format": "[%(asctime)s][%(levelname)s][%(pathname)s:%(lineno)s][%(funcName)s]: %(message)s"
        },
        "withRequestId": {
            "format": "[%(asctime)s][%(levelname)s][%(relpath)s:%(lineno)s][%(funcName)s][%(request_id)s]: %(message)s"
        }
    },
    "handlers": {
        "console": {
            "level": "DEBUG",
            "class": "logging.StreamHandler",
            "formatter": "standard"
        },
        "logfile": {
            "level": "DEBUG",
            "class": "logging.handlers.WatchedFileHandler",
            "filters": ["addRequestId"],
            "formatter": "withRequestId",
            "filename": "log/app.log"
        },
        "sentry": {
            "level": "ERROR",
            "class": "raven.handlers.logging.SentryHandler",
            "dsn": "DSN_URI",
            "string_max_length": 512000
        }
    },
    "loggers": {
        "app": {
            "level": "DEBUG",
            "handlers": ["logfile"],
            "propagate": True
        }
    },
    "root": {
        "level": "DEBUG",
        "handlers": ["console", "sentry"]
    }
}

后来,为了把 Celery 调度信息等也通过 logtail 收集到阿里云,我们就把 logtail 的源从日志文件改成了 stdout/stderr 输出,不同时收集日志文件是因为同样的日志在 logfileconsole 里会出现两次,没有必要。但是只改 stdout/stderr 又会导致收集到的信息没有我们辛苦加进去的 relpathrequest_id,一个很直接的思路就是,在 app 这层 Logger 上加一个 consoleWithIdStreamHandler,并且 formatter 用 withRequestId 不就好了,然后限制 app Logger 的 propagate 为 False 禁止上抛,问题应该完美解决?等会,这里有好几个问题

第一个问题是,如果 app Logger 不往上抛,那万一异常了,sentry Handler 也收集不到错误?头疼医头脚疼医脚,那就给 app Logger 也挂上 sentry Handler 不就解决问题

第二个问题是,handlers 的处理顺序是不是严格按我们配置的顺序来?如果不是的话,consoleWithId 进入的时候,可能 addRequestId 这个 Filter 还没执行,出现了输出时拿不到 relpathrequest_id 那不就挂了?这个简单,把 Filter 移到 Logger 这一层不就解决了。至此,配置如下(只摘录改动部分)

    # ...
    "handlers": {
        # ...
        "logfile": {
            "level": "DEBUG",
            "class": "logging.handlers.WatchedFileHandler",
            "formatter": "withRequestId",
            "filename": "log/app.log"
        },
        "consoleWithId": {
            "level": "DEBUG",
            "class": "logging.StreamHandler",
            "formatter": "withRequestId"
        },
        # ...
    },
    "loggers": {
        "app": {
            "level": "DEBUG",
            "filters": ["addRequestId"],
            "handlers": ["logfile", "consoleWithId", "sentry"],
            "propagate": False
        }
    },
    # ...

翻车就翻在「这个简单」上,按这个思路配置后,跑起来还是在 consoleWithId 的 Handler 上输出报错,而且报的就是 relpathrequest_id 字段不存在。怀疑自己的配置有问题,跑到代码里打日志的地方用 logging.getLogger(__name__) 看拿到的到底是哪个 Logger,以及上面挂了哪些 Handler,还有 Logger 和 Handler 的 Filters 都配的啥,发现除了 app 根上,如果是 app.foo 这样的路径,拿到的都是一个叫 celery.utils.log.ProcessAwareLogger 的 Logger,而且没有任何 Handler 和 Filter 挂在上面,所以,Celery 你这个坏人,到底对我的代码做了什么?

跑去翻 celery.utils.log.ProcessAwareLogger 这个东西的源码都没看出个所以然,似乎只是为了保证 Flask 的 signal handler 机制正常,排查思路也断掉,再跑去看看我们那个 app.utils.logging.request_filter 的处理,有没有哪里不对的,在这个自定义的 filter 里裸用 print 打印,发现这个 filter 压根没被调用到?嗯?没被调用到?

回去看自己的上一篇,果然里面自己就提到过这里有坑(主流程解释的第 5 步)

如果开启了日志往上传递,则判断当前 Logger 是否有父 Logger,如果有的话,直接将当前 LogRecord 传给父 Logger 从 4 开始处理(跳过 1/2/3,注意此处级别控制 1 会不生效,绑定在父 Logger 上的 Filter 也不执行)

WTF!果然坑都是自己不掉一遍,别人说千万遍也不会记得的,哪怕说的这个人是自己。那好咯,把 addRequestId 这个 Filter 还是从 app Logger 上移到 Handler 层面上好了,每个需要的 Handler 都给挂上,多点性能开销就多点吧

不过这样配的感觉还是怪怪的,比如有些错误会被 sentry 收集两次,因为在 app 里一直往上抛会被 app Logger 里的 sentry 收集,如果这个错误还继续往上抛到了框架层面,框架的错误还会被 rootLogger 的 sentry 又收集一次。而且,既然 app 的里面和外面都有终端和 sentry,为啥不在最外面一次处理好,中间拦着不往上抛没有任何意义。调整了下,直接把 standard 这个 Formatter 和 console 这个 Handler 给去掉,在 rootLogger 上挂 consoleWithIdsentry 就好,最后完整的配置如下

logging_conf = {
    "version": 1,
    "disable_existing_loggers": True,
    "filters": {
        "addRequestId": {
            "()": "app.utils.logging.request_filter.ContextFilter"
        }
    },
    "formatters": {
        "request": {
            "format": "[%(asctime)s][%(levelname)s][%(relpath)s:%(lineno)s][%(funcName)s][%(request_id)s]: %(message)s"
        }
    },
    "handlers": {
        "logfile": {
            "level": "DEBUG",
            "class": "logging.handlers.WatchedFileHandler",
            "filters": ["addRequestId"],
            "formatter": "request",
            "filename": "log/app.log"
        },
        "consoleWithId": {
            "level": "DEBUG",
            "class": "logging.StreamHandler",
            "filters": ["addRequestId"],
            "formatter": "request"
        },
        "sentry": {
            "level": "ERROR",
            "class": "raven.handlers.logging.SentryHandler",
            "dsn": "DSN_URI",
            "string_max_length": 512000
        }
    },
    "loggers": {
        "app": {
            "level": "DEBUG",
            "handlers": ["logfile"],
        }
    },
    "root": {
        "level": "DEBUG",
        "handlers": ["consoleWithId", "sentry"]
    }
}

因为 Logger 的 propagate 默认就是 True,所以相对于第一版在 app 这个 Logger 上去掉了这条配置也没关系

最后,因为 addRequestId 这个 Filter 还是会被调两次,想优化下性能,就在 Filter 做完后加一个标记,下次再进来如果看到有这个标记就直接跳过,以及,对于非项目内的日志就不要用项目内的相对路径而用绝对路径替代。代码如下

# coding: utf8

import logging
import os.path

from celery import current_task
from flask import g, has_app_context, has_request_context


_proj_root_path = os.path.abspath(os.path.join(__file__, './../../../../'))
_proj_root_length = len(_proj_root_path)


class ContextFilter(logging.Filter):
    def filter(self, record):
        # ignore duplicate filter
        if hasattr(record, 'filter_by_yewen'):
            return True

        # request_id for flask web or celery task
        request_id = 'Standalone'

        if has_app_context():
            if has_request_context():
                request_id = g.get('request_id', 'UnknownRequest')
            elif current_task:
                request_id = current_task.request.id or 'UnknownTask'

        record.request_id = request_id

        # handle log_decorator pass
        record.funcName = getattr(record, 'orig_funcName', record.funcName)
        record.pathname = getattr(record, 'orig_pathname', record.pathname)
        record.lineno = getattr(record, 'orig_lineno', record.lineno)

        # relative path
        if record.pathname.startswith(_proj_root_path):
            record.relpath = record.pathname[_proj_root_length:]
        else:
            record.relpath = record.pathname

        record.filter_by_yewen = True

        return True

折腾 Python logging 的一些记录

Python 自己有成熟的日志模块 logging,使用中遇到一些原生组件无法满足的功能,或有一些使用方式上的坑,记录一下

0. 复习一下 logging 的实现

Python 官网对 logger flow 的定义如下图(来源 https://docs.python.org/3/howto/logging.html

Python logging flow

源码在 python 自己的 lib/logging/ 下,主要内容都在 __init__.py 里,先注意下几个定义

  • Logger,可以挂载若干个 Handler,可以挂载若干个 Filter,定义要响应的命名空间,和日志级别 (1)
  • Handler,可以挂载一个 Formatter,可以挂载若干个 Filter,定义了要响应日志级别 (2),和输出方式(流、文件等)
  • Filter,过滤器(其实也可以在里面搞更多事情)
  • Formatter,最终日志的格式化字符串
  • LogRecord,单条日志的结构体,所有信息都会存在这里

然后对着流程图来说,主流程如下

  1. 日志打印请求到 Logger 后,先判当前 Logger 是否要处理这个级别,不处理的直接扔掉(级别控制 1)
  2. 生成一条 LogRecord,会把包括调用来源等信息都一起打包好,传给 Logger 挂载的 Filter 挨个过滤
  3. 如果有 Filter 返回是 False,则丢弃这条日志
  4. 否则传给 Logger 挂载的 Handler 挨个处理(右上角子图)
  5. 如果开启了日志往上传递(propagate,不知道怎么翻译更精准),则判断当前 Logger 是否有父 Logger,如果有的话,直接将当前 LogRecord 传给父 Logger 从 4 开始处理(跳过 1/2/3,注意此处级别控制 1 会不生效,绑定在父 Logger 上的 Filter 也不执行)

右上角的子图是 Handler 内部的流程

  1. 判当前 Handler 是否要处理这个级别,不处理的直接扔掉(级别控制 2)
  2. 把收到的 LogRecord 交给挂载的 Filter 挨个过滤
  3. 如果 Filter 没有阻止,按挂载的 Formatter 格式化输出

这里面有一些比较好玩的地方

0.1 LogRecord 的生成

在生成之前其实 Logger 先干了两件事,一是找到原始的调用源(文件名 filename,方法名 funcName,行号 lineno),二是根据参数决定是否需要获取运行信息 exc_info

找原始调用源就是在 Python 的调用栈里一层一层往上找,直到找到调用文件不是当前文件(**/lib/logging/__init__.py)退出。印象中 C/C++ 的日志是直接编译时把当前的 __line__ 什么的展开得到,在 Python 里这么做应该还是因为 Python 是解析性语言。另外可能要注意的是这里的 filename 其实是文件绝对路径,传到 LogRecord 里后会变成 pathname,再分割得到文件名 filename 和模块名 module(这个就是 filename 去掉后缀)

生成好 LogRecord 后还会把传入的 extra 字典也挂上去,这里会限制 extra 里的字段不能和 LogRecord 原生字段冲突,否则会直接报错

0.2 不要被名字骗了的 Filter

从名字上看,Filter 应该就是一个过滤器,对输入的 LogRecord 做判断,返回 True/False 来决定挂载的 LoggerHandler 是否要处理当前日志,但是,这个东西不仅可以读 LogRecord,还可以改写,这里就有很多好玩的事情发生了(后面的很多事情都是在这里做的),而且只要被 Filter 改过的 LogRecord,都还会继续往后传递给其他的 Filter/Handler/Logger

0.3 没有被提到过的 adapter

在 Python 官方的 logging Cookbook 里,提到加上下文信息已开始推荐的是用 logging.LoggerAdapter 来做,这个东西其实是对 Logger 多了层封装,多包了一个 extra 字典进去,并且接管了 Loggerprocess 方法,实际用起来这个东西并不好用,所以在前面定义部分没说这个,官方的图也没提这块

0.4 为什么 log 还是要用 % 来格式化

Python 新一点的版本都支持 {} 格式化字符串,到 Python3.6 里更是有 literal template 这种不要太方便的字符串输出,那为什么 log 里还是坚持要用 % 加 args 的方式来处理呢?而且 pylint 等也都会对其他格式化方法报警告

没有太细究,大概想了下可能是因为这一整套 Logger 机制其实不仅仅是 Python 在用,其他语言也有在用,那么保持一致性是一个原因。另外还有查到说法是如果这条日志的等级不需要被处理,或者 Filter 直接就拦掉了,那么就不会走到 Formatter 那一步,可以减少格式化开销,不过这个原因也有站不住脚的地方,如果某条日志确定要被多个 Handler 处理,在用户端格式化就只用做一次,在 Formatter 里格式化就每个 Handler 都要重复做一次了

1. 对 logging 增加功能

1.1 增加相对路径

原生 LogRecord 里只有 filename (文件名)和 pathname (绝对路径),然而 filename 太短,我们可能在不同的目录下都有同名文件,而绝对路径又太长,把一堆有的没的都带上来,所以我们想打印出相对于项目的相对路径

一开始用了各种人肉魔改,包括接管整个 Logger 来自己做,后来发现可以简单加一个 logging.Filter 来解决。前面提到过 Filter 不仅可以过滤决定是否要输出日志,还可以改传入的 LogRecord,这样就很简单了,在我们的 Filter 里,记录下项目的根路径(这个很容易通过当前文件的 __file__ 往上指定层推出来),然后在 LogRecord 添加一个 relpath 的属性,取 LogRecord.pathname 截断掉前面非项目的部分就行了

1.2 自定义的 Filter 进配置

有了自定义 Filter 后,还需要能挂载到对应的 HandlerLogger

这里略坑的是 logging.config.fileConfig 这样的文件配置并不支持自定义 Filter,只能用 dictConfig。那么配置要么写 Python 变成原生 dict,要么用 json 写,在初始化配置的地方 json.load 读进来变成 dict。从「配置文件归配置文件」的角度说,用 json 会更合适,如果考虑到不同的环境用不同配置,用基类加继承微调的方式,可能写 Python 原生字典会更方便

1.3 保证 Formatter 匹配 Filter

增加的 relpath 可以直接在 Formatter 里用 %(relpath)s 的方式输出,但是这里也得保证,有 relpathFormatter 拿到的一定是被处理过的 LogRecord,不然就崩了

考虑到 Formatter 是一一绑定在 Handler 上的,所以我个人认为比较好的方法是在 Handler 里配置 Filter,保证如果用了自定义字段的 Formatter,一定要加上对应的 Filter,就算这个 Filter 在多个 Handler 上被多次执行,最多增加点性能开销,并不会对结果产生改变

1.4 打印 Flask 请求 ID

对于 Flask 应用,我们希望对一次请求所打的日志能有一个统一的 request_id 把所有日志串起来,方便追查。那么在 Web 请求的 app.before_request 里先加了个 g.request_id,把 request.path 拼上一个随机串记到上下文 g 里,然后在 logging.Filter 里判断是否有 app 上下文,有的话去取这个字段,并追加到 LogRecord 里,后面在 Formatter 里直接写 %(request_id)s 就可以输出了

5. 打印 celery task id

同上,对于异步任务,celery task 自己就有个 request.id 字段,直接判断是否存在上下文,摸出来挂到 LogRecord 上就行了

2. 增加易用性

2.1 log_decorator

很多时候我们希望知道一个方法的入参和返回值,如果在每个需要处理的方法前后都人肉写,未免太不 Pythonic,很自然就想到对方法调用加上装饰器,自动打调用参数和返回结果

对于怎么写装饰器,怎么摸被修饰方法的参数名和值等,之前写的几篇关于 Python 装饰器的 blog 已经写的很详细了,此处不重复

唯一需要注意的是如果不做特殊处理,打印的日志里,文件名、行号、方法都是 log_decorator 里打日志的那行,而不是原始方法。所以在这里需要先摸到原始方法的文件路径、方法名、行号,写到 log 的参数 extra 里用于构建 LogRecord,这里还特别注意因为 MakeRecord 的时候限制了不允许覆盖 LogRecord 已有的字段,所以这里必须改个名字,等到 Filter 里再去尝试看有没有自己加的字段,如果有则替换已有的

我们在实际工程中还对这里做了一些优化,支持传入方法来对入参和返回做处理后输出,特别是对复杂结构很有必要,另外对过长的 tuple/list/set/dict 也做了截断处理

2.2 before_request / after_request

有了 log_decorator 可以对方法的入参和返回很容易记录,那么对于 Web 请求,应该也可以更容易的做调用参数和返回值的记录。对于 Flask 应用,可以在 appblueprint 上往 before_requestafter_request 里增加打日志的方法来记录入参和返回

此处暂时没有很好解决的是文件路径、方法名和行号还是记录的打日志这个方法里调 log 语句时的数据,并不是最终处理 route 的方法,暂时还没去研究是否有办法可以实现,有 request.path 可以根据路由表去查,其实也还好

2.3 sentryHandler

对于用了 sentry 的项目,除了抛异常,某些时候也希望有一些错误信息能被记录到 sentry 上。最土的方法就是生成一个 raven_client 实例,然后 captureMessagecaptureException

其实 sentry 有提供 sentryHandler,就是一个 logging.Handler,直接配到 logging 的配置里,挂载到 rootLogger 上,初始化的时候就可以自动挂载上去,后面要用的时候直接 logger.error 打日志就是(什么?你需要只打 sentry 不打 log?你都打 sentry 了这么大的事情都不打条日志?也不是不可以,单独配个 logger 只挂 sentryHandler 就是,但还是不建议这么做)

如果需要打调用信息,在 log 时加上参数 exc_info=True,需要打堆栈就加 extra={"stack": True},比自己人肉搞不知道高到哪里去了

更详细的请见官方文档:https://docs.sentry.io/clients/python/integrations/logging/

3. 关于 Sentry 的补充

3.1 flask to sentry

在 Flask 应用里用 Sentry 可以参考官方文档 https://docs.sentry.io/clients/python/integrations/flask/ ,从 raven.contrib.flask 里 import 一个 Sentry 过来就行,实例化后在 init_app 的时候指定上对应的 sentry_dsn,这样就可以用这个 sentry 实例来 captureMessagecaptureException

其实这里配置好了更大的意义是在 Flask 应用抛了没有人接的异常时能往 sentry 打异常报告,这个地方一开始我配置好 sentryHandlerlogging.rootLogger 后得意忘形的把初始化 Sentry 给去掉了,然后就捕获不到异常了,弄明白怎么回事后老老实实加回来,最后异常捕获走 raven.contrib.flask.Sentry,日志走 rootLogger.sentryHandler,各行其是

这里还发现了个特别浪的操作,既然我们在 logging.rootLogger 上已经配好了 sentry_dsn,那是不是就有现成的 raven_client 可以用呢?实际上是可以的… 参考下方代码,初始化的时候直接写 Sentry(app, client) 就行,里面会自动完成 init_app 的操作的

def getRavenClient():
    _logger = logging.getLogger()
    for handler in _logger.handlers:
        if isinstance(handler, SentryHandler) and handler.client.is_enabled():
            return handler.client
    return None

3.2 celery to sentry

同样,对于 celery 异步任务,也可以参考官方文档 https://docs.sentry.io/clients/python/integrations/celery/ 来配置往 Sentry 打日志或捕获异常,因为我们已经在 logging.rootLogger 上配过 sentryHandler,所以官方文档里的 register_logger_signal 可以忽略,只要从 ravan.contrib.celery 里 import 这个 register_signal 方法并初始化就行,初始化 client 一样可以参考上面从 rootLogger 里去摸