Month: 3 月 2019

折腾 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 里去摸

莫言莫语 6

小朋友快三岁了,好久没记,其实好玩的事情超级多

好吧
不好吧

不知道什么时候开始,回答好或不好都要加一个「吧」,听起来就特别的客气,有商有量的。「我们出去玩吧」「好吧」,「我们回去了好不好」「不好吧」

我喜欢亮亮的,我不要黑黑的

晚上不想睡觉,不让关灯

我喜欢黑黑的,我不要亮亮的,我还要睡觉

早上不想起床,要睡懒觉不让拉开窗帘

晚上不太好吧,晚上没有月亮不太好

过年时说现在还没到元宵节,晚上没有月亮,小家伙就开始掰为什么不喜欢晚上

亲我。这边

过年期间带莫莫出去玩,抱着他在电梯上会开玩笑让他亲亲爸爸,亲了后会要求爸爸来亲亲他,这边亲了要换一边再亲一口。坐一层扶梯能从下面一路亲到上面,看的爷爷都笑死了

不许走!

因为妈妈过年期间医院要值班,所以是叫爷爷奶奶过来过年了,小家伙经常也会来一句「我很想回湖南老家的」,等到爷爷奶奶要回去的时候,直接堵在门口,大喊不许走

看侏罗纪吧,我不怕的,我会保护你的

小男孩对恐龙还是有各种热爱,妈妈给看过一点侏罗纪公园后,就老缠着还要看,跟他说恐龙太可怕了,他表示我不怕的,会保护我们的,然而实际看到恐龙比较恐怖的画面时还是会害怕,紧紧抓着陪他看的人的手。小朋友还是嘴上说说啦,还是要搂着看好好给他安全感的

吃完饭喝果汁吧

家里没人喝酒,过年的时候给大家喝果汁,小朋友尝到甜头后就一直惦记着了,跟他说吃完饭才可以喝,等下一顿才开始吃时,想起来这事立马先约定一下

我已经慢慢慢慢长大了

小小的人儿偶尔不让叫他「莫莫」了,会说「莫莫」是我小时候的名字,我现在长大了我叫 ***,问他你什么时候长大的呀,会很正经的如是说

你再放高点我就拿不到了

小朋友看书是挺爱看书的,不过也很喜欢把各种绘本丢的满地都是,然后拿书的时候还会顺着电视柜往上拿到不想让他无限制吃的饼干糖果啥的,某天回去一看「莫你怎么又把糖拿下来了,我放那么高你都拿得到?」,小家伙抬头一看,往上再指一格,很认真的建议

Python decorator 库和 gevent 冲突的情况

去年写了两篇分析 decorator 的 blog:

在线上项目里一直也没有用 pypi 的 decorator 库去替换自己的实现,最近替换后撞上了一些问题,整个问题追查过程也各种艰辛,记录一下

我们线上用的 flask 0.11.1 + celery 3.1.25 + gevent 1.2.2 在跑任务队列,broken 用的阿里云 redis 2.8,某个周末突然发现 worker 工作不正常,有大量的 db 连接报错,在简短排查后没找到原因,重启整个服务,暂时跳过这个问题,其实后面还在有其他错误,但也没有解决思路

等周一到公司,团队的人对比了下问题现场和思路,只能发现是 celery worker 会莫名卡死,跑到我们的 k8s 集群上看,对应的 pod 是 running,但是 flower 上看监控是 offline,直接切进 pod 看日志,好几个最后都断在 requests 发请求出去的地方,N 脸懵逼,我们又没升级系统又没动依赖,怎么就会冒出来这个问题

既然最后死在 requests 那,虽然看后面的 Changelog 没发现有跟我们直接习惯的,但还是先把 requests 版本从 2.19.0 升到 2.21.0,并把依赖的库也同步升级。然而并没有解决问题,还是一样的死,还是一样的错

后面多看了几个问题现场,只能协助定位还可能会卡死在 db 读写的地方,这个时候开始怀疑 gevent,因为这货帮忙做了 IO 异步优化,强行协程化,而且这个版本也有点老,期间看也有一些可能相关的 Issue,升级 1.4.0 后发现服务起不来,查了下看需要把 celery 升级到 4.x,但 4.x 的 celery 参数序列化从 pickle 改成 json,还要改挺多代码的,只能先搁置

后面还查了下 celery 的版本问题,我们用的 3.x 是有点老了,但 4.x 那个参数结构该动那个有大所以一直没动,另外也查用 redis 做 broken 的锅,没有任何有效的相关信息

出问题前我在代码里替换了一版 lock 的实现,以及 lock_decorator 的实现,但是往这边怀疑也不对,因为有的出错的地方并没有用到锁,而且看日志和报错也跟锁没有关系

等过了一周,第二个周末的时候开脑洞说好像现在有问题的方法都有修饰器包着,而且这些修饰器都用了 decorator 库,也许这里可能有问题?我们的 decorator 用的是 4.3.0,最新的版本是 4.3.2,大致看了下 Changelog,似乎提到有修复协程问题,但是是 python 3.5 的,不过反正不用改代码,先升了再说

升完后问题真的消失了,那么就来看看到底哪里可能有问题吧。对比期间的变更记录 https://github.com/micheles/decorator/compare/4.3.0…4.3.2,除了一些文档变化和对 py3.5 的协程修复,比较值得怀疑的是 https://github.com/micheles/decorator/commit/eb890d98739196b83f1ecb5cb7bcfe9739a9502c 这个提交,decorator 的原理是在内存里新建一个虚拟文件,把要修饰的方法的相关属性写到这个虚拟文件里,然后通过虚拟文件里的同名方法调装饰器逻辑,装饰器方法里再去调到最终的方法,而这个虚拟文件如果只用 itertools.count(),在 gevent 的协程调度下可能会重名,然后整个代码体系就崩了