前言

對(duì)于如何優(yōu)雅的實(shí)現(xiàn)打印requestId這事情上，google了半天都沒有找到一個(gè)滿足我的需求的實(shí)現(xiàn)。唯有自己去實(shí)現(xiàn)一個(gè)，整個(gè)思路我覺得還挺有趣的，值得分享出來，所以就有了這文章。

需求

我負(fù)責(zé)的子系統(tǒng)有：IP管理系統(tǒng)，爬蟲管理系統(tǒng)，爬蟲系統(tǒng)。這個(gè)只是整個(gè)系統(tǒng)的其中一部分。這個(gè)時(shí)候，如果某個(gè)請(qǐng)求或者某個(gè)服務(wù)出錯(cuò)了，需要定位問題的原因就比較復(fù)雜了。為了快速定位問題，很核心的一個(gè)點(diǎn)日志規(guī)范，而日志規(guī)范中最最最重要的一點(diǎn)就是要有個(gè)requestId來跟蹤整個(gè)整一個(gè)請(qǐng)求或服務(wù)的調(diào)用鏈路。需求來了，為每一條日志都加上requestId這個(gè)參數(shù)。這個(gè)需求再抽象一下，就是為每一個(gè)日志都增加一個(gè)前綴。這個(gè)前綴可以有requestId, server_name等等信息。這樣抽象之后呢，如果還需要增加其他參數(shù)也方便。ps：requestId的生成可以簡(jiǎn)單粗暴的uuid來，也可以讓它帶有信息（IP，服務(wù)名等等），這個(gè)不是本文的重點(diǎn)，最好就由一個(gè)專門的函數(shù)來生成，以后有變化改起來也方便。正如某名言說的那樣，用一個(gè)穩(wěn)定的東西來包裝一個(gè)不穩(wěn)定的東西以提供一個(gè)穩(wěn)定的服務(wù)。

實(shí)現(xiàn)思路

不用動(dòng)腦子想到的實(shí)現(xiàn)方式

1. 類的初始化參數(shù)&函數(shù)參數(shù)都提供一個(gè)參數(shù)專門來傳遞log前綴
2. 做一個(gè)裝飾器給需要打印業(yè)務(wù)log的方法或函數(shù)使用

對(duì)于方式1，這個(gè)實(shí)現(xiàn)起來巨惡心，入侵過大，偶合過大我的內(nèi)心是拒絕的。對(duì)于方式2稍微好了一點(diǎn)，傳說當(dāng)中的切面編程，對(duì)代碼沒有入侵性，但是粒度太大，函數(shù)或者方法內(nèi)的log無法加上前綴，肯定是不行的，所以只能放棄。所以此時(shí)又把目光放到方式1上，此時(shí)大腦冒出了一個(gè)大膽的想法，給整個(gè)系統(tǒng)的類或函數(shù)打補(bǔ)丁。補(bǔ)丁的作用就是為類的初始化方法添加上log前綴的可選參數(shù)，函數(shù)參數(shù)添加上log前綴的可選參數(shù)。然后還居然真的有相關(guān)的模塊可以獲取方法或者類的參數(shù)信息，并修改，這個(gè)高級(jí)功能只存在python3之中。準(zhǔn)備擼起袖子就開干的時(shí)候，還是被惡心到了，即便實(shí)現(xiàn)了，還是需要將log前綴層層傳遞，代碼將會(huì)變得很難看。前面說的層層傳遞，抽象一下就是在每個(gè)調(diào)用間共享一個(gè)變量，此時(shí)大腦想起了threading模塊中的local類，但是但是我們的服務(wù)部署一般是gevent的模式，threading的local模塊并不是一個(gè)協(xié)程安全的東西。萬能的google再次拯救我，在werkzeug實(shí)現(xiàn)了一個(gè)協(xié)程安全Local類，celery當(dāng)中也實(shí)現(xiàn)了，實(shí)現(xiàn)方式都差不多，連注釋都一毛一樣。

最終的實(shí)現(xiàn)方式

暫時(shí)想到的最優(yōu)的實(shí)現(xiàn)方式：在服務(wù)的開頭出在local對(duì)象中設(shè)置上log的前綴，出口處刪掉，每條log都從Local對(duì)象處獲取前綴打印。這都是由框架來做，具體的業(yè)務(wù)代碼是無感知的。這樣做的好處就是對(duì)代碼幾乎是無入侵的，擴(kuò)展性強(qiáng)，大家都開心的方式。在細(xì)化一下具體實(shí)現(xiàn)方式，本質(zhì)上還是添加中間層來實(shí)現(xiàn)。對(duì)沒錯(cuò)，任何計(jì)算機(jī)問題均可以通過增加一個(gè)中間層來解決。

• http請(qǐng)求：在header處添加上requestID這參數(shù)，然后中間件來做統(tǒng)一處理
• celery異步任務(wù)：任務(wù)消息帶上log前綴，任務(wù)開始前做添加上前綴，任務(wù)返回后刪掉

實(shí)現(xiàn)核心過程

一點(diǎn)說明，代碼中有部分配置信息，這個(gè)我賴得改直接就粘貼復(fù)制過來了，不是什么重點(diǎn)內(nèi)容 ，忽略就好。另外的，必要的一下基礎(chǔ)知識(shí) ，我并沒有進(jìn)行講解，一來嘛，不是重點(diǎn)，二來嘛，我感覺我會(huì)寫得沒別人好，但會(huì)給出有幫助的文章鏈接。

django 中間件

給application添加Local對(duì)象清理的中間件

有參考價(jià)值的文章: 關(guān)于werzeug模塊中對(duì)的Local對(duì)象的使用的中文文章

文件wsgi.py

from werkzeug.local import Local, LocalManager
local = Local()
local_manager = LocalManager([local])

# 請(qǐng)求結(jié)束后對(duì)當(dāng)前線程或者協(xié)程中的local對(duì)象中的變量進(jìn)行清除
application = local_manager.make_middleware(application)

自定義django的中間件

將django中間件怎么做的文章: django中間件。代碼沒啥好說的，核心點(diǎn)就是設(shè)置給Local對(duì)象設(shè)置上一個(gè)dict對(duì)象，里面包含了需要的前綴信息。

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):
            
            # 通過一個(gè)函數(shù)生成request_id
            request_id = gen_request_id()
            log_data = {"requestId": request_id}

        return log_data

log的filter

關(guān)于python log處理模塊的文章：python log基礎(chǔ)知識(shí)。

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異步任務(wù)

這個(gè)是整個(gè)實(shí)現(xiàn)的難點(diǎn)所在，也是值得借鑒的地方，這部分必須嘮叨的解釋一下，因?yàn)檫@部分網(wǎng)上沒啥好的文章給我貼出來，而且有的部分被迫自己實(shí)現(xiàn)的，說來都是淚啊，差點(diǎn)弄我一個(gè)通宵。前面所說的，任務(wù)消息帶上log前綴，任務(wù)開始前做添加上前綴，任務(wù)返回后刪掉。難點(diǎn)是在于如何優(yōu)雅的做到不入侵原先的代碼。

任務(wù)消息帶上log前綴

馬上想到的方式在異步任務(wù)的參數(shù)上帶上，但是感覺不太優(yōu)雅，直覺上celery框架應(yīng)該有提供攜帶額外信息的參數(shù)。翻了一下celery官網(wǎng)文檔，有一個(gè)headers的參數(shù)放出刺眼的光芒引起了我的注意，測(cè)試了一下還真的可以，這樣僅僅需要將log前綴信息放在headers中即可。ps：測(cè)試的時(shí)候還順便更加理解amqp這協(xié)議，celery的一下額外的控制參數(shù)例如task_id都是存放在消息的headers中的，然后在接收到消息后做統(tǒng)一的處理。

任務(wù)開始前做添加上前綴，任務(wù)返回前刪掉

直覺上celery框架是有留出有相關(guān)的接口做這事，還是去翻文檔。翻到有一個(gè)after_return的handler, 但是但是沒有一個(gè)pre_execute的handler。只找到一個(gè)task_prerun的信號(hào)，這貨是個(gè)全局性的東西，感覺上粒度太大，我不好控制。這時(shí)候冒出大膽的想法，去翻源碼，看看怎么添加上pre_execute的handler，再利用monkey_patch給celery這個(gè)包打補(bǔ)丁。直接翻源碼還是挺痛苦的，有點(diǎn)暈，此時(shí)想到了pycharm是可以斷點(diǎn)調(diào)試的，斷點(diǎn)觀察整個(gè)調(diào)用過程+全局關(guān)鍵字搜索來找添加的入口。最后在celery/app/trace.py文件中找到了build_tracer這個(gè)函數(shù)，一個(gè)任務(wù)執(zhí)行所有的流程控制都在里面。真的是牛逼啊，用一個(gè)流程控制的方法來控制整個(gè)流程，思路很好，值得借鑒，大神們的軟件架構(gòu)思路無比膜拜。所要做的就很簡(jiǎn)單，按照里面的規(guī)則照葫蘆畫瓢的添加一個(gè)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):
        """
        自動(dòng)根據(jù)local變量中的log相關(guān)的信息，設(shè)置去message的headers中，讓異步任務(wù)根據(jù)設(shè)置的log信息設(shè)置log
        """
        
        # 自動(dòng)把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):
        # 任務(wù)開始前將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("異步任務(wù)設(shè)置log的出錯(cuò)", exc_info=True)

        setattr(local, settings.LOCAL_LOG_ATTR_NAME, log_data)
    
    def after_return(self, status, retval, task_id, args, kwargs, einfo):
        # 清理變量，其實(shí)不清理也沒什么影響，畢竟部署都是進(jìn)程池或者是協(xié)程池的，不會(huì)有很多。
        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 

最后的嘮叨

人上了年紀(jì)，容易發(fā)出一些感慨。這個(gè)東西實(shí)現(xiàn)后，總結(jié)的體會(huì)是：1. 越來越意識(shí)到抽象是一樣多么重要的事情，如果沒有去抽象出共性，我可能就被迫用最惡心的方式1來實(shí)現(xiàn)了。2. 編程這工作雖然說是偏文科，以知識(shí)和經(jīng)驗(yàn)為主，但是良好的分析思路卻能很好的彌補(bǔ)上知識(shí)和經(jīng)驗(yàn)上的不足。在分析能力的提高這部分還是要經(jīng)過有意識(shí)的訓(xùn)練才行，這里立個(gè)flag，那天我覺得自己分析能力有了一個(gè)臺(tái)階的上升后，擼一篇如果分析的文章。