在整理完【閒談軟體設計 2014 — 2024】電子書後,有好一陣子沒有寫技術部落格了,主要是開始認真找下一份工作,畢竟還是要想辦法讓自己有收入,大概到 2024 的六月底,有了幾份還不錯的 offers,但猶豫了好一陣子後,決定再闖一次,跟朋友一起從零開始一家新公司,接下來的文章,主要是這段時間系統從 0 到 1 的過程中,我覺得有趣的設計決策。
新公司初期只有我一個開發者,系統開發最初的三個月都集中在後端,加上沒有上到雲端 (也因此,省了三個月的雲端費用),全靠涵蓋率超過九成的單元測試確保功能正確性,在這情況下,自然用不到日誌,真遇到問題,有更好追蹤流程的 debugger,日誌就被放在 backlog 中的後面。
直到 app/web 的開發者加入,為了能協作,才終於把後端上到雲端作為 beta 環境 (production 環境是等到要送審 app 時才上雲端),這下就真的需要日誌了,趁系統的複雜度還在可控範圍,是該好好規劃下日誌該怎麼做了,當時在設計文件中寫下幾個要滿足的 criteria
- 關聯式查詢。這是最重要的,可以將相關的日誌簡單地用一個條件,就全部找出來,這樣可以把完整的情境重建,更好地找出複雜問題的原因。
- 支援雲生態。Java 有很多日誌的套件,要上雲其實很容易,只要找到合適的 appender 就行。
- 富含情境。有時候日誌不是單單印出一句話,這樣對於查找問題並沒有幫助,而是要將當初的情境記錄下來,但不太可能把所有的資料都記錄下來,那些資料是有用的,這完全得靠開發者決定。
- 結構化日誌。純文字日誌 (plain logs) 並不是沒有用,只是我個人沒有很愛在終端機上 command 去找日誌,反而比較常用 GCP 的介面,根據結構下條件,例如
context.merchantId = "xyz"。 - 和商業邏輯核心保持距離。不要讓商業邏輯核心為上述的 criteria 服務,最好是能做到:對商業邏輯核心來說上面的 criteria 幾乎透明。要寫日誌,取得一個 logger 物件,放入必要的情境和敘述就完事。
要滿足第一個 criteria,我立馬就想到 correlation ID,這是之前看 書摘《建構微服務》時注意到的,當時的系統已經複雜到一定的程度,加上值班時或是系統出現問題時,查找問題都要花上不少時間,還不見得能把所有相關的日誌都關聯起來,因此特別特別,雖然慢慢在既有的系統加入類似的概念,但總覺得是東補西補,沒有很漂亮。
ThreadLocal
老實說,書中對於 correlation ID 的描述很簡單,大意是用 UUID 然後往後帶。但要怎麼帶到後面給所有相關的日誌?一個簡單的作法,把 correlation ID 塞進 logger 物件,然後把 logger 往下傳,但這會有個問題,函式都會多一個與功能毫不相關的參數,弱型別的語言,把 logger參數放在最後一個,測試時不帶無所謂,但這次我選的是強型別語言,這招不管用,更別說,強型別語言也無法隨意把 correlation ID 塞進 logger 中。
那把 correlation ID 放到某個靜態變數裡?那就是危險的全域變數了,一個 web application,效能再怎麼差,同時也要處理數十個請求,correlation ID 放全域變數,那不就被改來改去,根本沒法用。
還好 Java 有 ThreadLocal 可以用,ThreadLocal 可以視作一個全域變數的儲存池,但只有放進去池子的執行緒可以取得跟修改放進去的資料,其他執行緒是看不到也無法修改,也就是說,只要一件任務不會有二或多個執行緒交替執行來完成,那就很適用放在 ThreadLocal 裡。恰巧,我這次沒有使用任何 async 或是 reactive 框架,完全是靠 virtual threads 來衝負載 (參閱 閒談軟體設計:Java virtual thread),每個請求都是建一個 virtual thread 來處理,完全不用擔心跨 thread 的問題。
富含情境
因此,首先先來個 Loggers 作為 factory,讓產品的程式碼沒有與任何日誌框架有直接的耦合。接著,在 Loggers 加入一個可以塞入任意 key-value 的 context 函式,而這個函式的實作也很單純,取得一個 ThreadLocal 物件,然後把東西塞進去。塞進去的資料可以透過 flush 清除,但只有當初放進去的執行緒才能清除對應的資料。
然後,提供 logger 函式取得一個 Logger 物件。Logger 本身沒有什麼複雜的邏輯,主要是管理 local context,和提供 debug、info、warning 和 error 等函式的常用參數 overloading 實作。這次除了用 ThreadLocal 提供全域的 context,還加入了僅限於該物件的 local context,以及寫日誌時當下的 context,最終三個 context 會被合併送給 appender。
到這邊為止,算是已經有一個富含情境的日誌框架了,但還沒有滿足最一開始說的關聯式查詢,只是幫 correlation ID 找到一個地方儲存。
關聯式查詢
接下來便是確保 correlation ID 在正確的時機都被放到入 context 中。若仔細想想整個後端系統的運作,會發現一件任務的發動大概就幾種情況 (閒談軟體設計:多種 work 類型 ):
- API 請求
- 定時執行 (cronjob)
- 事件驅動
也就是說,只要在這些任務發動時,產生或沿用 correlation ID 放到 context 中,那就可以把相關聯的日誌都透過 correlation ID 關聯起來。
針對 API 請求,先幫所有 API 請求加上 before handler,這裡 context 參數是 Javalin 的請求物件,先看看請求者是否提供 request ID,如果有,就把該 request ID 作為 correlation ID,如果沒有,就產生一個 UUID。
改天再聊為什麼沒有使用 Spring boot 而選用 Javalin
接著是定時執行,在目前的設計裡,所有的 cronjob 都有 setup、run 和 clean 三個函式,setup 和 clean 負責初始化資源和清理資源,因此,只需要在 setup 執行時將 jobId 視作 correlation ID 即可。
事件驅動稍微麻煩一點,API 請求和 cronjob 執行時往往都在一個程序 (Process) 裡,但事件驅動卻是常常跨程序,例如有個處理登入的 API 請求,在完成後發出一個 authenticated 事件,然後另一個應用程序接收到事件後開始處理,這時 correlation ID 若沒有跟著傳送到處理事件的程序,那該程序寫入的日誌就關聯不起來。
當初,為了與框架保持距離寫的 EventCenter 抽象層,此時,正好可以發揮額外的功能,將 correlation ID 加在事件信封的 metadata 中
然後在收到事件時,從 metadata 取出 correlation ID 放到 context 後,才將信封中真正的事件交給訂閱者,如此,correlation ID 便跨越程序的邊界。
到這裡,滿足了關聯式查詢的 criteria,如圖,只需要 correlation ID 就能將兩個不同程序相關聯的日誌全部找出來。

結構化日誌和支援雲生態
接著,要如何滿足結構化日誌和支援雲生態?其實剛剛的 cronjob 範例程式碼中藏有玄機,在初始化日誌時,有用到一個 GCPLogAppender,這物件很單純只做一件事,將資訊轉成 GCP 要求的格式,例如將 log level 改成 severity。最後,以 JSON 格式印到 system out。
就這樣,GCP 當發現 system out 裡有類似 JSON 的訊息,會自動解析,最後在 GCP 的搜尋介面可以看到結構化的資料。

和商業邏輯核心保持距離
最後一個 criteria,和商業邏輯核心保持距離,實際上,已經完成了,由於商業邏輯層只使用 Loggers 和 Logger 這兩個自訂抽象層:
商業邏輯層除了提供情境,上述其他如滿足關聯式查詢和結構式日誌等實作細節,商業邏輯層完全不需要知道如何達成,使用時也不用做任何事,假設哪天要將程式改上到 AWS 環境,最多只需要提供一個 AWSLogAppender,然後在最外層,也就是應用程式的進入點換上去就搞定,商業邏輯層完全不需要更動。
前世今生
到這邊,本來以為整個設計已經很夠用了,但使用一陣子後,突然發現有個情況要處理。故事是當初在追某個 long polling 下來的事件,發現無法找到當初發出這個事件的過程。原因是發出事件的 Request A,其 correlation ID 會一路到到後面 (下圖藍色路徑),這邊都符合預期,但發起 long polling 的 Request B,自己的 correlation ID (下圖橘色路徑),在原有的設計 Request B 在 subscribe 的當下,其 correlation ID 會被 Request A 的 correlation ID 取代掉了,於是用 Request B 的 correlation ID 查詢時,其實是找不到什麼東西的。

那怎麼辦?兩者只能選一個嗎?小孩子才做選擇,當然是兩者都留下來啊,透過檢查 context 是否已經有 correlation ID,如果有,就將其合併。
於是可以發現,當用 Request B 的 correlation ID 查詢時,會看到 context 被合併了。

打開對應的內容可以看到 correlation ID 有兩筆,其中一個是 Request B 的,另一個就是 Request A 的。

於是就可以用 Request A 的 correlation ID,找到當初產生該事件的過程了。

如果把藍色路徑當成是前世,橘色路徑當成是金生,透過合併 correlation ID 的方式,就把前世和金生給串起來了。
小結
上面所有的設計,程式碼其實沒有多少行,加上 GCP 自動會解析類似 JSON 的文字,也沒有用到 Java 常見的日誌框架 (SLFJ 或 Logback,只有相依的套件,像是 GCP 套件有用到)。少少的程式碼,就滿足了五個我覺得相當重要的 criteria,想想真的是蠻划算的。






















