謹防猴子補丁以及Python中排查技巧

時間 2019-11-06

原文原文鏈接

背景

前兩天晚上線上系統突發故障，在立馬打開線上錯誤日誌以後，卻只能獲得一堆毫無心義的程序調用棧(traceback)的輸出，因而團隊成員陷入漫長而又抓瞎的問題排查過程當中。問題很幸運地獲得瞭解決，可是我一直想不明白爲何日誌裏打印的調用棧毫無心義，按照經驗，它應該打印的是異常產生過程當中的調用棧纔是。在通過後續的源碼分析和排查以後，我才發現實際上是由於項目中一個老舊的代碼使用了猴子補丁致使，這也是這篇文章想要討論的內容。html

什麼是猴子補丁

猴子補丁是一種用來在運行時修改（增長、變動、刪除等）系統軟件行爲的編程方式。在動態語言裏有普遍的猴子補丁應用的影子，好比 Ruby 的打開類的特性支持運行時擴展類的定義甚至替換方法的實現，Python 的方法或者函數因爲能夠在運行時進行替換而使得猴子補丁的應用很是方便，其餘像 JavaScript 語言一樣能夠應用猴子補丁。python

猴子補丁是把雙刃劍

猴子補丁以其靈活性，能夠實現補丁代碼和應用代碼的徹底分離，同時使得應用代碼在調用方式上保持調用方式始終不變。
從應用代碼的角度來看，它調用的就是某個模塊的原始定義的方法或者函數；而從被調用的方法或者函數的角度來看，猴子補丁的存在對它是透明的存在，如下展現一個 Python 語言的 Demo：redis

咱們從一個極簡例子開始，向這個美好的世界問好：shell

def greet():
    print("Hello World!")

if __name__ == "__main__":
    greet()

假如執行以上腳本，獲得的結果是：django

$ python demo.py
Hello World!

這個很簡單，接下來假如打一個猴子補丁：咱們擴充原來的 greet 的行爲，如今除了打印信息，還要打印下當前的時間：編程

from datetime import datetime
def greet():
    print("Hello World!")

# monkey patch
original_greet = greet
def greet_with_time():
    original_greet()
    print(datetime.now())
greet = greet_with_time  # replace the implementation
# monkey patch

if __name__ == "__main__":
    greet() # 這裏的調用和原來沒有變化

運行它，獲得的結果是：ruby

$ python demo.py
Hello World!
2019-09-21 23:40:42.575782

咱們獲得了預期的結果！
從代碼分析，咱們添加了一個新的函數 greet_with_time，其會調用原來的 greet 函數，而後打印當前時間，最後將 greet 函數經過將函數賦值給變量的方式完成對 greet 函數的替換。而對於最後的 greet 函數的調用，卻無需任何改動，以此達到了一樣仍是調用 greet 函數，行爲卻截然不同的目的。
上面的 demo 只是限於篇幅簡化了代碼，真實項目裏的猴子補丁代碼老是在另外的模塊或者文件裏。想象在一個複雜的大型工程裏，若是你的代碼裏猴子補丁氾濫，可想對於系統的行爲分析以及問題排查，將是一種災難性的挑戰。app

如今對猴子補丁有了必定的瞭解以後，咱們再來看看我在實際項目中遇到的例子。python2.7

一堆毫無心義的堆棧信息

我在本地重現了我開頭提到的咱們所遇到的異常，如下是和線上環境一致的堆棧信息：異步

2019-09-19 17:30:11.103|CRITICAL|138:140147476383488|log.py:282|log.log|Task command.celery.crontab_task.some_task[538ddb72-89b0-45fe-811e-107202dc665b] INTERNAL ERROR: AttributeError("'long' object has no attribute 'insert'",)
Traceback (most recent call last):
  File "/usr/local/bin/celery", line 10, in <module>
    sys.exit(main())
  File "/usr/local/lib/python2.7/dist-packages/celery/__main__.py", line 30, in main
    main()
  ...... 限於篇幅，這裏省略不少無心義的內容
  File "/usr/local/lib/python2.7/dist-packages/celery/worker/job.py", line 384, in on_success
    return self.on_failure(ret_value)
  File "/usr/local/lib/python2.7/dist-packages/celery/worker/job.py", line 443, in on_failure
    self._log_error(exc_info, send_failed_event=send_failed_event)
  File "/usr/local/lib/python2.7/dist-packages/celery/worker/job.py", line 511, in _log_error
    'internal': internal}})
  File "/usr/local/lib/python2.7/dist-packages/celery/utils/log.py", line 282, in log
    return Logger.log(self, *args, **kwargs)
None

從這個堆棧信息看，它打印的其實是調用了 Logger.log 函數的堆棧，其中根本沒有任何代碼看到有 .insert 相關字眼，其與 AttributeError("'long' object has no attribute 'insert'",) 根本毫無關係，這樣的堆棧信息，有和沒有基本一個樣。因而乎，我接着經過編輯器經過源碼進行了更多的探索。

首先仍是藉助上面的堆棧去分析到底哪裏出了問題，因此我先看了 celery/worker/job.py:504-511 處的代碼：

context = {
            'hostname': self.hostname,
            'id': self.id,
            'name': self.name,
            'exc': exception,
            'traceback': traceback,
            'args': sargs,
            'kwargs': skwargs,
            'description': description,
        }

        logger.log(severity, format.strip(), context,
                   exc_info=exc_info,
                   extra={'data': {'id': self.id,
                                   'name': self.name,
                                   'args': sargs,
                                   'kwargs': skwargs,
                                   'hostname': self.hostname,
                                   'internal': internal}})

這裏調用了 logger.log 方法（logger 的來源在 Celery 的代碼裏可分析，可是不是這篇文章的重點，故此不展開）而且經過 context 對象傳入了兩個重要的信息：exception 和 traceback。在對 logger.log 源碼的進一步閱讀中，我確認了這塊日誌打印的核心依賴於對 traceback.print_exception 函數的調用：

def formatException(self, ei):
        """
        Format and return the specified exception information as a string.

        This default implementation just uses
        traceback.print_exception()
        """
        sio = io.StringIO()
        tb = ei[2]
        traceback.print_exception(ei[0], ei[1], tb, None, sio)

因而乎，我回到了 celery/worker/job.py:504-511 處的代碼，在 logger.log 前面插入了兩種打印錯誤堆棧信息的代碼：

# context  = ...

        ################################################################
        import traceback as _traceback
        # Method 1: like what logger.log does
        _traceback.print_exception(*exc_info)

        # Method 2: use `format_exception` instead
        print(''.join(_traceback.format_exception(*exc_info)))
        ################################################################

        logger.log(....

從新啓動 celery 後，執行異步任務後，獲得的第一種錯誤堆棧和前面我貼出來的堆棧信息是徹底一致的，這個倒也好理解，畢竟這裏的 print_exception 函數的調用就是 logger.log 裏的核心實現。而 format_exception 的調用給了我真正有意義的錯誤堆棧信息：

Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/celery/app/trace.py", line 283, in trace_task
    uuid, retval, SUCCESS, request=task_request,
  File "/usr/local/lib/python2.7/dist-packages/celery/backends/base.py", line 271, in store_result
    request=request, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/celery/backends/base.py", line 505, in _store_result
    self.set(self.get_key_for_task(task_id), self.encode(meta))
  File "/usr/local/lib/python2.7/dist-packages/celery/backends/redis.py", line 161, in set
    return self.ensure(self._set, (key, value), **retry_policy)
  File "/usr/local/lib/python2.7/dist-packages/celery/backends/redis.py", line 150, in ensure
    **retry_policy
  File "/usr/local/lib/python2.7/dist-packages/kombu/utils/__init__.py", line 246, in retry_over_time
    return fun(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/celery/backends/redis.py", line 170, in _set
    pipe.execute()
  File "/usr/local/lib/python2.7/dist-packages/redis/client.py", line 2879, in execute
    return execute(conn, stack, raise_on_error)
  File "/usr/local/lib/python2.7/dist-packages/redis/client.py", line 2785, in _execute_transaction
    response.insert(i, e)
AttributeError: 'long' object has no attribute 'insert'

好傢伙，這下就清晰了，原來這個代碼的異常真正出處是這裏！
可是問題就來了，爲何print_exception和 format_exception給出的堆棧信息不同呢？我充滿疑問地去查找了官方文檔，可是困惑更重了：

traceback.format_exception(etype, value, tb[, limit])
Format a stack trace and the exception information. The arguments have the same meaning as the corresponding arguments to print_exception(). The return value is a list of strings, each ending in a newline and some containing internal newlines. When these lines are concatenated and printed, exactly the same text is printed as does print_exception().

重點在最後一句，Python 官方文檔說了，兩個函數輸出的錯誤堆棧是同樣(exactly the same text)的！

揪出猴子補丁

其實，問題的真正排查過程耗費了我好多時間，我一直沒有往猴子補丁上想，最後卻是在出門赴朋友的飯約的地鐵上靈機一動，用手機翻看了公司 GitLab 上的項目代碼，一下找到了元兇。

def _patch_print_exception():
    import traceback

    def custom_print_exception(etype, value, tb, limit=None, file=None):
        exc_info = sys.exc_info()
        stack = traceback.extract_stack()
        # ... omit other source codes 

    traceback.print_exception = custom_print_exception

從補丁代碼看，補丁直接覆蓋了原版的代碼，而且實現上也直接粗暴地無視了傳入的幾個異常信息參數！因此纔會出現這麼大的烏龍，出現毫無關係的異常堆棧信息！(╯‵□′)╯︵┻━┻

排查猴子補丁的技巧

猴子補丁這類編程技巧當然會利弊共存，使用上必然須要額外慎重，但也並不是須要敬而遠之，重點是掌握必要的排查技巧，如下我針對此次的教訓又去找下一些可能有幫助的方法：

1. 經過函數或方法自身屬性檢查方法或者函數的信息

衆所周知，Python 的全部對象都有一堆內置的屬性，函數也不例外，以我項目中的例子：

# django shell
In [1]: traceback.print_exception.func_code
Out[1]: <code object custom_print_exception at 0x109e9f030, file "/Users/boy/work_area/project/project-source/lib/common/logger.py", line 295>

一看就知道，這個函數的真實代碼其實就是項目中的補丁代碼！

2. 藉助 inspect 包來檢查

Python 自身提供的工具包很是多，inspect 天然也是利器之一，其能夠用來對幾乎全部類型作運行時的檢查，仍是以個人實際例子：

# django shell
In [1]: import inspect
In [2]: inspect.getfile(traceback.print_exception)
Out[2]: '/Users/boy/work_area/project/project-source/lib/common/logger.py'

In [3]: inspect.getsource(traceback.print_exception)
Out[3]: '\tdef custom_print_exception(etype, value, tb, limit=None, file=None): ......\n'

In [4]: print inspect.getsource(traceback.print_exception)
Out[4]: def custom_print_exception(etype, value, tb, limit=None, file=None):disable=redefined-builtin
            if file is None:
                file = sys.stderr
            exc_info = sys.exc_info()
            stack = traceback.extract_stack()
            ...

總之，若是趕上代碼行爲與預期不符卻又沒法和官方文檔或者官方源碼對應，那麼可能就是依賴的方法或者函數被打了猴子補丁，而最快速確認猴子補丁的方式，就是第一時間檢查所調用的函數或者方法的實際定義，即應用上述方法便可！

題外話

作 Ruby 開發時，我也遇到過猴子補丁的陷阱，Ruby 裏也有相似的方法：

file, line = A.new.method(:foo).source_location
puts "Method foo is defined in #{file}, line #{line}"
# => "Method foo is defined in temp.rb, line 2"

參考連接

相關標籤/搜索

每日一句

每一个你不满意的现在，都有一个你没有努力的曾经。