优雅的实现打印requestId

感谢关注天善智能，走好数据之路↑↑↑

欢迎关注天善智能，我们是专注于商业智能BI，人工智能AI，大数据分析与挖掘领域的垂直社区，学习，问答、求职一站式搞定！

本文作者：天善智能社区专家 Ljian1992

天善智能社区地址：https://www.hellobi.com/

前言

对于如何优雅的实现打印requestId这事情上，google了半天都没有找到一个满足我的需求的实现。唯有自己去实现一个，整个思路我觉得还挺有趣的，值得分享出来，所以就有了这文章。

需求

我负责的子系统有：IP管理系统，爬虫管理系统，爬虫系统。这个只是整个系统的其中一部分。这个时候，如果某个请求或者某个服务出错了，需要定位问题的原因就比较复杂了。为了快速定位问题，很核心的一个点日志规范，而日志规范中最最最重要的一点就是要有个requestId来跟踪整个整一个请求或服务的调用链路。需求来了，为每一条日志都加上requestId这个参数。这个需求再抽象一下，就是为每一个日志都增加一个前缀。这个前缀可以有requestId, server_name等等信息。这样抽象之后呢，如果还需要增加其他参数也方便。ps：requestId的生成可以简单粗暴的uuid来，也可以让它带有信息（IP，服务名等等），这个不是本文的重点，最好就由一个专门的函数来生成，以后有变化改起来也方便。正如某名言说的那样，用一个稳定的东西来包装一个不稳定的东西以提供一个稳定的服务。

实现思路

不用动脑子想到的实现方式

类的初始化参数&函数参数都提供一个参数专门来传递log前缀

做一个装饰器给需要打印业务log的方法或函数使用

对于方式1，这个实现起来巨恶心，入侵过大，偶合过大我的内心是拒绝的。对于方式2稍微好了一点，传说当中的切面编程，对代码没有入侵性，但是粒度太大，函数或者方法内的log无法加上前缀，肯定是不行的，所以只能放弃。所以此时又把目光放到方式1上，此时大脑冒出了一个大胆的想法，给整个系统的类或函数打补丁。补丁的作用就是为类的初始化方法添加上log前缀的可选参数，函数参数添加上log前缀的可选参数。然后还居然真的有相关的模块可以获取方法或者类的参数信息，并修改，这个高级功能只存在python3之中。准备撸起袖子就开干的时候，还是被恶心到了，即便实现了，还是需要将log前缀层层传递，代码将会变得很难看。前面说的层层传递，抽象一下就是在每个调用间共享一个变量，此时大脑想起了threading模块中的local类，但是但是我们的服务部署一般是gevent的模式，threading的local模块并不是一个协程安全的东西。万能的google再次拯救我，在werkzeug实现了一个协程安全Local类，celery当中也实现了，实现方式都差不多，连注释都一毛一样。

最终的实现方式

暂时想到的最优的实现方式：在服务的开头出在local对象中设置上log的前缀，出口处删掉，每条log都从Local对象处获取前缀打印。这都是由框架来做，具体的业务代码是无感知的。这样做的好处就是对代码几乎是无入侵的，扩展性强，大家都开心的方式。在细化一下具体实现方式，本质上还是添加中间层来实现。对没错，任何计算机问题均可以通过增加一个中间层来解决。

http请求：在header处添加上requestID这参数，然后中间件来做统一处理

celery异步任务：任务消息带上log前缀，任务开始前做添加上前缀，任务返回后删掉

现核心过程

一点说明，代码中有部分配置信息，这个我赖得改直接就粘贴复制过来了，不是什么重点内容 ，忽略就好。另外的，必要的一下基础知识 ，我并没有进行讲解，一来嘛，不是重点，二来嘛，我感觉我会写得没别人好，但会给出有帮助的文章链接。

django 中间件

给application添加Local对象清理的中间件

有参考价值的文章: 关于werzeug模块中对的Local对象的使用的中文文章

文件wsgi.py

from werkzeug.local import Local, LocalManager

local = Local()

local_manager = LocalManager([local])

# 请求结束后对当前线程或者协程中的local对象中的变量进行清除

application = local_manager.make_middleware(application)

自定义django的中间件

将django中间件怎么做的文章: django中间件。代码没啥好说的，核心点就是设置给Local对象设置上一个dict对象，里面包含了需要的前缀信息。

from xxx import local

class LogPrexiMiddleware(MiddlewareMixin):

def process_request(self, request):

log_data = self._get_log_data(request)

attr_name = getattr(settings, LOCAL_LOG_ATTR_NAME, DEFAULT_LOCAL_LOG_ATTR_NAME)

setattr(local, attr_name, log_data)

def _get_log_data(self, request):

log_header_key = getattr(settings, LOG_HEADER_KEY_SETTING, None)

log_data = {}

if log_header_key and log_header_key in request.META:

log_data = {"requestId": request.META.get(log_header_key)}

if not log_data and getattr(settings, GENERATE_REQUEST_ID_IF_NOT_IN_HEADER_SETTING, False):

# 通过一个函数生成request_id

request_id = gen_request_id()

log_data = {"requestId": request_id}

return log_data

log的filter

关于python log处理模块的文章：python log基础知识。

from xxx import local

class PrefixFilter(Filter):

def filter(self, record):

log_data = getattr(local, settings.LOCAL_LOG_ATTR_NAME, {})

log_prefix = "".join(["[{}={}]".format(key, value) for key, value in log_data.items()])

# log format: [%(log_prefix)s][%(asctime)s,%(msecs)d][%(levelname)s]

record.log_prefix = log_prefix

return True

celery异步任务

这个是整个实现的难点所在，也是值得借鉴的地方，这部分必须唠叨的解释一下，因为这部分网上没啥好的文章给我贴出来，而且有的部分被迫自己实现的，说来都是泪啊，差点弄我一个通宵。前面所说的，任务消息带上log前缀，任务开始前做添加上前缀，任务返回后删掉。难点是在于如何优雅的做到不入侵原先的代码。

任务消息带上log前缀

马上想到的方式在异步任务的参数上带上，但是感觉不太优雅，直觉上celery框架应该有提供携带额外信息的参数。翻了一下celery官网文档，有一个headers的参数放出刺眼的光芒引起了我的注意，测试了一下还真的可以，这样仅仅需要将log前缀信息放在headers中即可。ps：测试的时候还顺便更加理解amqp这协议，celery的一下额外的控制参数例如task_id都是存放在消息的headers中的，然后在接收到消息后做统一的处理。

任务开始前做添加上前缀，任务返回前删掉

直觉上celery框架是有留出有相关的接口做这事，还是去翻文档。翻到有一个after_return的handler, 但是但是没有一个pre_execute的handler。只找到一个task_prerun的信号，这货是个全局性的东西，感觉上粒度太大，我不好控制。这时候冒出大胆的想法，去翻源码，看看怎么添加上pre_execute的handler，再利用monkey_patch给celery这个包打补丁。直接翻源码还是挺痛苦的，有点晕，此时想到了pycharm是可以断点调试的，断点观察整个调用过程+全局关键字搜索来找添加的入口。最后在celery/app/trace.py文件中找到了build_tracer这个函数，一个任务执行所有的流程控制都在里面。真的是牛逼啊，用一个流程控制的方法来控制整个流程，思路很好，值得借鉴，大神们的软件架构思路无比膜拜。所要做的就很简单，按照里面的规则照葫芦画瓢的添加一个pre_execute的处理，然后mokey_patch搞起来即可。

具体的一下代码

from xxx import local, local_manager

class BaseTask(app.Task):

def apply_async(self, args=None, kwargs=None, task_id=None, producer=None,

link=None, link_error=None, shadow=None, **options):

"""

自动根据local变量中的log相关的信息，设置去message的headers中，让异步任务根据设置的log信息设置log

"""

# 自动把log prefix 信息添加到消息的headers中

log_data = getattr(local, settings.LOCAL_LOG_ATTR_NAME, {})

headers = options.get("headers", {})

headers.update({settings.LOCAL_LOG_ATTR_NAME: json.dumps(log_data)})

options["headers"] = headers

super(BaseTask, self).apply_async(args=args, kwargs=kwargs, task_id=task_id, producer=producer,

link=link, link_error=link_error, shadow=shadow, **options)

def pre_execute(self, status, retval, task_id, args, kwargs, einfo):

# 任务开始前将headers中的log前缀信息，给添加到local变量里面

log_data = {}

if hasattr(self.request, settings.LOCAL_LOG_ATTR_NAME):

try:

log_data = json.loads(getattr(self.request, settings.LOCAL_LOG_ATTR_NAME))

except ValueError as why:

sm_log.debug("异步任务设置log的出错", exc_info=True)

setattr(local, settings.LOCAL_LOG_ATTR_NAME, log_data)

def after_return(self, status, retval, task_id, args, kwargs, einfo):

# 清理变量，其实不清理也没什么影响，毕竟部署都是进程池或者是协程池的，不会有很多。

super(BaseTask, self).after_return(status, retval, task_id, args, kwargs, einfo)

local_manager.cleanup()

# 使用说明

方式一：粒度可控的

@app.task(bind=True, base=BaseTask, max_retries=3)

def debug_t(self, a):

pass

方式二：全局的

app.Task = BaseTask

最后的唠叨

人上了年纪，容易发出一些感慨。这个东西实现后，总结的体会是：1. 越来越意识到抽象是一样多么重要的事情，如果没有去抽象出共性，我可能就被迫用最恶心的方式1来实现了。2. 编程这工作虽然说是偏文科，以知识和经验为主，但是良好的分析思路却能很好的弥补上知识和经验上的不足。在分析能力的提高这部分还是要经过有意识的训练才行，这里立个flag，那天我觉得自己分析能力有了一个台阶的上升后，撸一篇如果分析的文章。