优雅的实现打印requestId

前言

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

需求

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

实现思路

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

  1. 类的初始化参数&函数参数都提供一个参数专门来传递log前缀
  2. 做一个装饰器给需要打印业务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,那天我觉得自己分析能力有了一个台阶的上升后,撸一篇如果分析的文章。

推荐阅读更多精彩内容