Dive into Matrix's logging system

最近看到 Rain Wu 提到關於面試常見的問題 軟體工程實習求職見聞錄，印象中有一個就是怎麼設計 logging 系統，正好最近看 Matrix federation（也就是服務器間的共識），其中大量與異步 logging 相關，我想這將會是個相當好的切入點

context.py

在切入 federation 部份前，推薦先看過 context.py 裡面幾個很常用，用來確保呼叫順序與流程
這一節的內容主要來自 matrix logging 的文件 Log Contexts

Context 這個函式庫主要是用來幫助追蹤程式的執行狀況（主要是透過一個叫做 log context 的 thread-local 變數），這同時也可以統計 CPU 使用量
或者資料庫使用情況，可以在 request 層級作到類似 perf 的效果

如果只有同步調用的 logging

會需要讓這個上下文交互獨立出來的主要原因就是因為這個「異步執行」，對於一個普通的同步呼叫來說
Matrix 的實做可能會長的是這樣：

from synapse.logging import context         # omitted from future snippets

def handle_request(request_id):
    request_context = context.LoggingContext()

    calling_context = context.set_current_context(request_context)
    try:
        request_context.request = request_id
        do_request_handling()
        logger.debug("finished")
    finally:
        context.set_current_context(calling_context)

def do_request_handling():
    logger.debug("phew")  # this will be logged against request_id

log context 負責紀錄「當下的」函式狀況，在同步範例中，我們只有當 request 完成之後才會把 log context 設定成回 caller，也就是如果 do_request_handling() 不知道為什麼一直沒有回傳，那麼 log context 將不會執行到 finally 的區塊，導致 log context 維持在 callee 的狀態

上個範例可以簡化成

def handle_request(request_id):
    with context.LoggingContext() as request_context:
        request_context.request = request_id
        do_request_handling()
        logger.debug("finished")

def do_request_handling():
    logger.debug("phew")

主要是透過進入 with ... as ... 的時候設定 hook function （這好像是 C++ 用的名字，我不知道 python 的話叫啥）來幫你自動處理 log context 設定的部份

但是現實中還有異步調用

但是現實是，matrix 採用了 python twisted 異步執行的架構，這將會導致事情變得非常複雜

@defer.inlineCallbacks
def handle_request(request_id):
    with context.LoggingContext() as request_context:
        request_context.request = request_id
        yield do_request_handling()
        logger.debug("finished")

由於涉及到 python twisted 的東西，建議可以去看我之前寫的東西 Peek through python twisted – an asynchronize event handling

這邊遇到的問題就是，事實上 do_request_handling() 現在變成異步版本了，底下的 callback 不知道什麼時候才會觸發，舉例來說：

from twisted.internet.defer import inlineCallbacks, Deferred, returnValue, ensureDeferred
from twisted.python.failure import Failure

from twisted.internet import reactor, defer, threads


def callee(result):
	import time
	time.sleep(2)
	print("Callee finished: ", result)

def caller():
	import time
	time.sleep(2)
	print("Caller finished")
	d = defer.Deferred()
	d.addCallback(callee)
	reactor.callLater(1, d.callback, "hello") # stimulate a callback by manually trigger it after 1 second
	return d
	

@defer.inlineCallbacks
def handler():
	yield caller()
	print("Handler finished")

handler()

reactor.callLater(4, reactor.stop)
reactor.run()

print("Main finished")

由於回傳的只是一個 Deferred ，一個「回傳 callback chain」，而這個 callback chain 啥時候被觸發誰也不知道（事實上，有可能完全不會被調用，可以試試看把 reactor.callLater() 那行註解掉），由於 handler() 中的 yield 必須等到 caller 裡面那個 callee 的 callback 整個都結束後，才會執行 print("Handler finished")，同理搬到原本的範例，這類的 logging 應該在 callback 事件整體結束後才印出來

這同時也導致就算 do_request_handling() 成功回傳一個 Deferred 也不代表 Request 有成功被處理，這自然也代表我們不能用原本的處理邏輯

另外 Why is it wrong to use Deferred.result to get the result of a Twisted Deferred object? 這篇 stack overflow 上的問題 / 回答也側面回應了這個 context.py 想要解決的問題

• 我們根本不知道 Deferred 值什麼時候才會有效（真正被 callback chain 處理回傳之前，它的值 deferred.result 都會是 AttributeError）
• 就算進入了 callback chain，由於 callback chain 可能會接到很長，中間都是用 Deferred 傳遞，因此我們也不會知道進行到 callback chain 的哪個階段

為了處理這個問題，matrix 提出幾個原則（也可以說是 coding rule ?）

使用 log context 的原則

對任何一個調用（可能是同步或異步，反正 Twisted 架構下常常都要包裝成 Deferred 回傳）

• 如果該 Deferred 回傳前就已經完成它的 callback，則該調用不需要更改當前 log context 就可回傳
• 但是如果該 Deferred 再回傳前還沒完成，該調用必須再回傳之前 清除 log context 回歸到呼叫前的狀態；直到該 deferred 結束並打算開始執行它的 callback 前，它需要再把 log context 設定回呼叫後的狀態

第一個原則挺好理解的，把它當成同步調用就好了（ Python twisted 可以讓同步調用回傳 Deferred.succeed()）

第二個原則是比較 tricky 的部份，為什麼我們要先把 log context 清掉呢？因為我們不想污染 log context 紀錄，首先 inlinecallback wrapper 這個東西實際上就是在 yield incomplete Deferred 的時候，幫你把後面的程式包起來變成 callback 加在 yield 回來的 incomplete Deferred 後面，然後我們就可以繼續處理其他的 request，反正剛剛那個 incomplete Deferred 在完成後會自己跑去呼叫 inlinecallback wrapper 幫我們包好的後面程式，這邊的話就是 logger.debug("finished") 的部份

但是如果我們在 Deferred 還沒完成的時候啥也不做就繼續處理下一個，那麼就 log context 來說它會一直紀錄新的新的 log context（儘管某些並沒有被完成），這導致整體調用完成順序會變得相當混亂，同時我們也無法區分 log context 是否完成執行，logger.debug("finished") 也會在很奇怪的 log context 下出現

一般函式看到 Deferred 回傳的原則

對所有的函式，只要它不是原始 Deferred 任務發起者，負責 log context 維護；那麼只要看到有調用函式回傳 Deferred，對於有用 inlineCallback 這個 decorator 的函式來說，你需要越早 yield 越好（如果你函式後面沒有其他事情要做，那麼就可以不用 inlineCallback 加上 yield，你可以直接 return 就好 ），也就是說，啥事情都不要做（包含 logging，其他有的沒的後續處理，或甚至調用其他函式）先把控制權交回去，反正下面的處理邏輯會被加到回傳 Deferred 的 callback 裡面

如果大家都遵守這個規則，那麼最終這個 Deferred 會被轉交到 caller （任務發起者）上，並由它來先把 log context 環境改完，再接下去處理有的沒的
可想而知的是，如果有人忘記這個規則，那麼很有可能在錯誤發生時，由於有人沒有把 Deferred 傳回去修改 log context 導致輸出變得混亂

如果你需要自己產生 Deferred 的原則

通常來說，你會因為調用 Synapse 的某些函式而拿到 Deferred （然後請遵守上面那個「總是 yield 拿到的 Deferred」規則），但是少數時候，你會想自己生成 Deferred，又或是從其他非 Synapse 的外部呼叫拿到 Deferred

假設我們今天有這樣一個需要回傳 Deferred 的函式（基本上就是等一段時間後觸發 callback）

# not a logcontext-rules-compliant function
def get_sleep_deferred(seconds):
    d = defer.Deferred()
    reactor.callLater(seconds, d.callback, None)
    return d

這個函式並沒有「登記在案」，也就是說當這個函式調用出錯時，log context 將無法追蹤到這部份，為了讓這個函式在 log context 中能夠被看見，我們可以選擇在外面加一層 inlineCallback wrapper

@defer.inlineCallbacks
def sleep(seconds):
    with PreserveLoggingContext():
        yield get_sleep_deferred(seconds)

透過 inlineCallback wrapper，我們知道它會幫我們把後續處理包成回傳 Deferred的 callback，這邊的後續處理就是 with 離開的調用，這邊的話會把 log context 改成調用完的狀態；事實上在 Synapse 原始碼裡面的確非常多這類東西

背景執行的原則

與前面提到的「當回傳 incomplete Deferred 時記得要先清空 log context」的原則不同，前面會這麼說是因為 Deferred 在沒回傳之前都不算是在做 callback 處理，因此不得不把 callback 的 log context 先清空（等到 Deferred 回傳後輪到執行它的 callback 之後我們就可以幫它把 log context 設定回去了）

但是在這邊，我們講究的是背景執行，我們可能會希望在這個背景執行之上的所有呼叫都能夠在這個 log context 裡，舉例來說，這會是一個失敗的寫法：

@defer.inlineCallbacks
def do_request_handling():
    yield foreground_operation()

    # *don't* do this
    background_operation()

    logger.debug("Request handling complete")

@defer.inlineCallbacks
def background_operation():
    yield first_background_step()
    logger.debug("Completed first step")
    yield second_background_step()
    logger.debug("Completed second step")

首先在 do_request_handling() 裡，我們很乖一開始先把 foreground_operation() yield 出去，因為它回傳了一個 Deferred ，這符合我們前面的原則，「總是 yield 拿到的 Deferred」，這很棒， 但是下面這樣寫的架構就會有點問題了：

• 萬一 background_operation() 回傳了 incomplete Deferred 了呢？
  根據前面提到的原則，我們需要馬上 yield 這個 Deferred（因此在 do_request_handling() 那邊其實是要補上 yield 的），並且因為它是未完成的，log context 會在 do_request_handling 的呼叫者那回復原始的狀態，最後 logger.debug("Request handling complete") 會作為 callback 在完成時被呼叫，然而由於這邊並沒有對背景執行做任何特別的 log context，導致這邊的 logging 會沒有對應的 log context

• 那如果背景執行與一般執行一樣在成功回傳時設定 log context 呢？
  這樣情況會更加尷尬，由於回傳的時間不固定，並且有沒有相對應的 callback 處理，因為回傳而被設定的 log context 很有可能被隨意接到其他環境裡

很抱歉我這邊理解的真的不好，我實在不太能夠理解它想表達的改動以及導致的影響，這類異步執行又牽扯到它本身框架的東西我也不太容易寫點測試

希望有其他看得懂的大佬解釋一下

會發生這一切的原因，就我理解，跟「背景」與「前景」任務性質不同有關，作為背景任務，我們希望所有跟背景執行任務「同時」進行的前景任務都能夠認知到背景任務的存在（這邊的「同時」是比較另類的定義，只要起始時間到結束時間重疊就算，但是要記得它還是單執行緒的），而前景任務我們更想知道明確的時間（舉例來說，如果收發封包是一個前景任務，那我們大多在意的是「發包」跟「收包」這兩個時間點的處理，但是如果他是作為一個背景任務，我們就會更關注中間的間隔）

Matrix 因此讓背景任務採取跟前面「收到 incomplete Deferred 時需要清除 log context」相反的原則，背景任務就算回傳 incomplete（其實也挺正常，畢竟是背景執行），log context 也不會清除掉，反而是在完成時，會透過完成時呼叫的 callback 清除掉背景執行的 log context

後記

原本其實是邊看原文邊寫的，但是後來發現不少東西是連貫的概念，索性想說直接看完，但是後面對背景執行 pseudo code 理解遇到了些問題，所以就跑去他們討論的群組問了下（不過很可惜的是沒有回應）

寫到一半碩論實驗又很爆炸，軟體模擬的精度太差了，想來想去實在沒啥好辦法，只好看看能不能想辦法合理的講故事移到硬體上，硬體編譯又遇到各種五花八門的心累體驗，花了一堆時間搞一個我覺得意義不明的實驗，實驗做完還要想演算法，感覺真的很差，回宿舍之後都沒啥心力只想耍廢了

只是因為最近終於比較熟硬體編譯的玩法，終於比較有心情了弄這些了，跟同學討論完的結果還是應該要先發點 PR 再混熟比較有用，但是一想到我只是想跑個 matrix 實驗就要用實驗室機器（它這個說是會消耗大量記憶體，我不太敢跑在筆電上），然後最讓人不爽的還是實驗室網路還不能用，我要自己手動翻牆（然後學校內部網站也限內網才能用，搞的我要換來換去），不得不說我是一個沒什麼耐心的人，感覺在牆內弄 matrix 真的就是在自討苦吃