Python全链路日志追踪-支持协程和多线程

一、需求背景

在WEB服务中,查看日志是排查和定位问题的主要方法。然而,在面对大量日志时,使用常规搜索来定位问题通常是相当麻烦的。由于不同用户、不同进程、不同线程、不同协程的日志都混在一起输出,很难筛选出与特定请求相关的日志。我们只能依靠请求时间、进程号和线程号等信息逐步进行排查,缺乏统一的流水号。

二、解决思路

为了更好地追踪每个请求的相关日志,我们可以在WEB服务中引入一个唯一的UUID标识符(称为traceid)来标识每个请求。这样一来,无论是不同用户、不同进程、不同线程还是不同协程,我们都可以通过这个traceid来关联和追踪与该请求相关的所有日志,并且无需改动业务代码。

为了实现这个目标,我们可以对日志打印模块进行扩展,在所有的日志中统一加入traceid进行标识。这样,当排查问题时,我们可以根据特定的traceid来筛选出与该请求相关的日志信息,从而更方便地定位和解决问题。

三、实现方案

1. 利用contextvars实现管理上下文变量

Python 3.7 的时候引入了一个模块:contextvars,从名字上很容易看出它指的是上下文变量(Context Variables),所以在介绍 contextvars 之前我们需要先了解一下什么是上下文(Context)。

Context 是一个包含了相关信息内容的对象,举个例子:"比如一部 13 集的动漫,你直接点进第八集,看到女主角在男主角面前流泪了"。相信此时你是不知道为什么女主角会流泪的,因为你没有看前面几集的内容,缺失了相关的上下文信息。

所以 Context 并不是什么神奇的东西,它的作用就是携带一些指定的信息,可用于管理、存储和访问上下文相关的状态。

重要: contextvars 上下文变量应该在顶级模块中创建,且永远不要在闭包中创建。 Context 对象拥有对上下文变量的强引用,这可以让上下文变量被垃圾收集器正确回收。

import contextvars
trace_id_context = contextvars.ContextVar('traceId', default="defaultTraceId")

2. 自定义WEB中间件

中间件可以理解为是介于 HttpRequest 与 HttpResponse 处理之间的一道处理过程。可以是请求中间件也可以是响应中间件,其处理逻辑大致如下:

HttpRequest -> Middleware -> View -> Middleware -> HttpResponse

  1. 请求 request
  2. 执行 request 处理前的中间件
  3. 执行 request 业务逻辑
  4. 接收 response
  5. 执行 response 返回前的中间件
  6. 返回 response

所以我们可以在步骤 2 中设置上下文变量 traceId 的值。

  • FastAPI:在函数顶部使用装饰器 @app.middleware("http"),即可创建中间件。
  • Flask:在函数顶部使用装饰器 @app.before_request,即可创建中间件。
  • Django:在settings.MIDDLEWARE中添加中间件, 类继承MiddlewareMixin并重写process_request方法。

3. 扩展日志组件

我们可以在日志配置的formatters中添加一个名为"traceId"的关键字,以便在每条输出的日志中显示请求的唯一标识。通过设置logging.Filter,我们可以确保每次记录日志时都会自动添加traceId信息。

 "formatters": {
    "verbose": {
        "format": "[%(asctime)s][%(levelname)s][%(traceId)s][%(filename)s][%(funcName)s:%(lineno)d][p:%(process)d][t:%(thread)d]: %(message)s",
        "datefmt": "%Y-%m-%d %H:%M:%S"
    }
}

4. 多线程优化

当使用多线程时,子线程无法直接访问主线程的上下文变量。但我们可以通过以下逻辑将主线程的上下文变量传递给子线程,以便子线程也能够拥有主线程的上下文变量:

  1. 在创建子线程之前,获取主线程的上下文变量。
  2. 将主线程的上下文变量作为参数传递给子线程的函数或方法。
  3. 在子线程中,接收传递的参数,并将其保存到子线程的局部变量中。
  4. 子线程即可在自己的上下文中使用这些拷贝的主线程的上下文变量。

具体实现可以通过继承ThreadPoolExecutor类并重写submit和map方法来在线程启动前执行初始化操作,即设置上下文变量traceId的值,通过这种方式,在每个子线程启动之前,都会先执行初始化操作,从而达到传递traceId的目的,需要注意的是,重写submit和map方法时,要确保不影响原有的逻辑。

5. 展示效果

已运用到实际生产项目中,web服务中同一个http请求下的所有日志都是同一个流水号,支持协程和异步多线程。


6. 代码实现(关#注#同#名#V)

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

推荐阅读更多精彩内容