本篇作者是 Magisk 開發者；Magisk 是一套開源的 Android 刷機工具。文章中僅會提到 Linux 系統程式設計，與 Android 本身無太大關聯。
Logging 幾乎是所有程式必用的功能，是搜集資料跟 debug 極度重要的工具之一。如此「基本」的功能，在多線程 (multi-thread)、多程序 (multi-process) 的程式中竟暗藏巨大陷阱？
(本篇內的 pseudo code 語法介於 Python 跟 JavaScript 之間)
問題
Magisk 所有的核心功能是由一個多線程的背景程式 (daemon) 提供。我時不時會收到有人回報某某功能不正常運作，但不僅我這邊無法重現，用戶提供的日誌中只看到 daemon 突然「停止運行」，絲毫沒有任何 crash 的痕跡。
終於，有人用 LLDB 去 debug 停止運行的 daemon，拿到完整 stack trace (#3976) 才真相大白：出乎意料，竟然是在 logging function 內發生 deadlock，導致整個程式直接死掉 🤔。
分析
來看看 Magisk 中的 logging function 是怎麼實作的吧。Android 本身提供的 logging API 並沒有將訊息寫入到檔案的功能，僅是把日誌放進系統分配的 ring buffer 中。這無法達到我期望使用者回報問題時能附上 logging 資訊的需求。因此，在 Magisk 中除了使用 Android 內建的 logging API，額外還會將日誌寫入到文件中：
function magisk_log(msg):
android_log_print(msg)
date = get_current_date()
date_str = format_date_string(date)
write_file(logfile, date_str + msg)Android 的 logging API 本身會記錄日誌時間，但是我們的 write_file function 並不會，所以這裡要手動獲取當前時間並轉換成文字。
get_current_date 實際上會使用到 localtime_r(3p)。花了點時間去爬 Android libc 的原始碼後，可以非常概要的用以下 pseudo code 表示:
function get_current_date():
time = get_current_time()
lock_tz_data()
date = convert_to_date(time)
unlock_tz_data()
return date要正確獲取現在的日期，首先得知道時區資訊 (tzdata)，而這個時區資料庫因為是整個程式共用的，為了避免 race condition 內部實作會在存取之前「上鎖」相對應的 mutex (也就是 pseudo code 中的 lock_tz_data) ，以此保證不會有超過一個 thread 同時存取這個資料庫。
簡單解釋 mutex 的原理：一個 mutex 一旦被某人 lock 之後， 當下一個人也想要 lock 時，必須等到它被前一個人 unlock 才能繼續，類似排隊的概念，是最基本用來 synchronize multi-thread program 的工具之一。
根據 call hierarchy ，我們畫出以下流程圖，其中黃色 block 是所謂的 “critical region”，也就是被 mutex lock 保護的地方。
先快速介紹 signal handler 的概念：在 Linux 中 thread 可以接收各種不同的 signal，針對各個 signal 我們可以設定自定義的 handler。當某 thread 接收到 signal 且設有相對應的 handler 時，會暫時停止一切，直接跳去執行 signal handler，結束後再回到本來暫停的地方繼續執行。
所以，magisk_log 到底問題出在哪裡？試想以下情況：執行 critical region 到一半的時候，突然有外部 signal 進來導致程式直接轉跳至先前設定好的 signal handler 中。在這個 signal handler 裡面，如果我們又呼叫 magisk_log 進行 logging，那就會變成以下情況：
前面介紹 mutex 時提到，下一個人想要重新 lock 前，必須等待上一個人 unlock 才能繼續。這裡有一個細節：mutex 是不會認人的！也就是說，如果同一個人 lock 兩次，在第二次的時候仍會被要求等待前一個人 unlock；問題是前一個人就是自己，導致進入「死結」(deadlock)，將會永無止境的等下去。(備註 1)
Reentrancy
在牽扯到 mutex lock 的程式，一個很重要的概念是 reentrancy：一個 function 是否可以重入。以下用兩段遞迴函數舉例：
function reentrant_method(count):
if count > 0:
reentrant_method(count - 1)global mutexfunction non_reentrant_method(count):
lock(mutex)
if count > 0:
non_reentrant_method(count - 1)
unlock(mutex)# No problem
reentrance_method(2)# Will cause deadlock!
non_reentrance_method(2)
由此可以看出，任何 function 只要有使用到外部的 mutex lock 就會是 non-reentrant，因為重複進入會導致「自己鎖自己」變成 deadlock。
在 magisk_log 中，我們並沒有使用任何遞迴，所以在一般情況下是不會有問題的。但是當有外部 signal 攪和時，就會如同剛剛提到的例子，不小心導致 non-reentrant function 被 reentry 而 deadlock。
知道問題的癥結點後，最簡單的解決方法，就是在 magisk_log 裡面暫時擋掉所有的 signal，收工！
function magisk_log(msg):
block_all_signal()
android_log_print(msg)
date = get_current_date()
date_str = format_date_string(date)
write_file(logfile, date_str + msg)
restore_signal_mask()進階篇
使用上述方法修復之後，我又花了不少時間思考，最終發現這樣其實以 Magisk 的情況，仍然不能阻止 deadlock 的發生。這又是為什麼？Magisk 的 daemon 時不時會 fork 創造新的程序。當一個 multi-thread process fork 時，僅有呼叫 fork 的那個 thread 會在子程序中存活，其他所有的 thread 則會瞬間「憑空消失」。
那麼來試想以下情況：某 thread 1 先 lock 一個 global mutex，但是在它 unlock 釋放這個 mutex 之前，另外一個 thread 2 突然呼叫了 fork。在子程序中，僅有 thread 2 會存活，thread 1 已經人間蒸發了。如果此時 thread 2 嘗試去 lock 這個 mutex，本來拿鎖的人早已不在人世 (淡淡的哀傷…?)，結果便只能永無止境等待下去，也就是 deadlock。以下的流程圖會更清楚的表達上述的情形。
所以結論：在一個 multi-thread 的 process 中，任何現存的 mutex 在 fork 過後都絕對不能碰，否則子程序有機率會進到 deadlock (父程序不受影響)。也就是說，magisk_log 如果想要能夠在任意 thread 、任意 process 中被使用 (這是必要條件，否則稱不上是 logging…)，那麼在這個 function 中完全不能有 mutex locking 存在。
哎呀，這下頭痛了…
結論
最終，完美解決方法頗為複雜，關鍵是使用 atomic operations：
- 啟動常駐線程專門處理 date formatting 跟 log writing，確定 lock 永遠只會發生在同一個 thread 上
- 使用
socketpair(2)配合 vectored I/O 來進行跨 thread/process 的溝通。讓 Linux 內核幫忙保證資訊傳遞是 atomic 😁 - 需要共享的資訊 (socket 的 file descriptor) 不使用 lock 保護，必須得用 atomic variable
因篇幅關係加上遠遠超出本次想討論的主題，我就不詳述細節了。有興趣的話，merge 進 Magisk 的 commit 在這：https://github.com/topjohnwu/Magisk/commit/43c1105d62916a3031bd13ba0cd0e30d6a1fa4db
總之，真的不能小看 logging 這個最基本的 function 啊啊啊！
備註 1:
其實，只要 mutex 能夠記住 lock 住它的 thread 是誰，然後在下次要求 lock 時：如果是同一個 thread，則記住它已經要了幾次並放行；如果是不同 thread，則跟一般 mutex 無異，要求它排隊。如此一來，就算是同一個 thread 重複 lock 同一個 mutex，只要 unlock 相對應的次數，仍然可以釋放這個 mutex 給其他人，而且重複 lock 不會造成 deadlock。這就是所謂的 “reentrant lock”。由前述可知，reentrant lock 是 non-trivial 的，所以使用較為底層的 pthread API 時，除非特別設定，否則預設都是 non-reentrant。
以這次情況為例，因為 lock 不是發生在自己的 code，而是在 localtime_r 這個 libc function 中，沒辦法把 lock 改用成 reentrant，所以才需要用各種方法去避免 deadlock。而且就算改用 reentrant mutex，一樣無法解決 fork 後 deadlock 的情形。