Linux 系統程式設計 — Logging Shenanigans

Cover of the book “Linux System Programming“ from O’Reilly

本篇作者是 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 的情形。

Get the Medium app

A button that says 'Download on the App Store', and if clicked it will lead you to the iOS App store
A button that says 'Get it on, Google Play', and if clicked it will lead you to the Google Play store