Day 24：庫存扣減的併發正確性，用資料庫機制取代分散式鎖 收尾時老實承認了一件事：樂觀鎖的版本衝突實際上發生得頻不頻繁，悲觀鎖的等待實際上會讓請求卡多久，這些問題目前完全沒有任何方式可以觀察到。資料本身正確了，但整個過程仍然是一團迷霧。

資料正確之後，換一個新的命題要處理

樂觀鎖與悲觀鎖各自的判斷依據、程式碼寫法，Day 24 都交代清楚了，StockRepository 的 deductOneWithVersionCheck 與 findByIdForUpdate 搭配 deductOne，兩條路都能守住庫存不被錯誤修改。但「守住正確性」跟「知道這套機制實際運作得好不好」，是兩件完全不同的事。一套系統就算資料從來沒有出過錯，也不代表它值得信任，如果連基本的執行過程都無法被記錄下來，出問題的時候只能憑猜測辦案，更進階的監控、追蹤、告警都無從談起。

今天要處理的，是可觀測性裡最基本、也最容易被輕忽的一塊：日誌。不是因為日誌多先進，恰恰相反，正因為它太基本、太理所當然，才容易讓人以為協程情境下沿用舊有做法應該也沒問題。事實不是這樣。

一個熟悉但在協程情境下會失效的做法

寫過傳統 Java 或 Kotlin 後端服務的讀者，多半用過 MDC 這類機制。做法很直覺：請求剛進來的時候，把一個請求識別碼放進與當前執行緒綁定的某個儲存空間，之後這條執行緒印出的每一筆日誌，都會自動帶上這個識別碼。等到系統出狀況，只要拿著這個識別碼去搜尋日誌，就能把同一個請求從頭到尾的完整軌跡拼湊出來。多年來，這套做法在 Thread-per-Request 模型底下運作得相當可靠，沒理由讓人多想。

問題出在它背後藏著一個沒有明講的假設：處理同一個請求的邏輯，自始至終都跑在同一條執行緒上。這個假設在 Day 07：Dispatchers，協程實際跑在哪條執行緒上 已經被推翻過一次。Dispatcher 背後維護的是一組數量有限的執行緒資源，協程只是輪流借用，一旦協程暫停後需要恢復執行，排到哪一條執行緒完全由 Dispatcher 決定，不保證是原本那一條。傳統 MDC 依賴的儲存空間跟著執行緒走，協程本身卻不跟著任何一條執行緒走，這兩件事一旦搭在一起，關聯就斷了。具體來說，協程在某個掛起點暫停之前，MDC 裡確實還帶著正確的請求識別碼，但恢復執行時如果換了一條執行緒，那條新執行緒的 MDC 儲存空間裡，可能根本沒有這筆資料，或者更麻煩的，裡面殘留著另一個請求早先寫入、還沒被清乾淨的識別碼。

這還只是單一協程換執行緒的情況。Day 13：協程搭配訊息佇列與外部 API 呼叫的常見模式 建立過另一種更常見的情境：一個請求底下同時展開多個平行協程，例如扣庫存成功後，用 async 同時發起確認優惠資格與發送通知這兩個呼叫。這兩個協程從一開始就可能被 Dispatcher 排到不同的執行緒上執行，如果日誌關聯機制依賴的是執行緒本身，這兩條原本屬於同一個請求的日誌，會從一開始就散落在不同的執行緒儲存空間裡，各自為政，沒有任何一種依賴執行緒的機制能把它們自動兜回同一個請求。

把這個失效的樣貌具體化一次。訂單查詢與扣庫存服務如果在促銷高峰期間打開日誌檔案，會看到大量交錯的日誌行，查詢訂單的、確認庫存的、確認優惠資格的、發送通知的，同時有數百個請求在跑，每一行看起來都差不多。如果日誌沒有帶上任何能標示「這幾行屬於同一個請求」的資訊，想從中揪出某個異常請求發生了什麼事，只能靠猜時間點、猜訂單編號，一行一行人工比對，這在高併發情境下幾乎是不可能的任務。

用協程上下文攜帶請求識別碼

問題根源找到了，答案其實不需要另外發明新機制。

Day 08：Coroutine Context 與例外處理，協程出錯了誰負責 已經定案 Coroutine Context 是協程攜帶的一組上下文元素集合，這組集合會隨著協程一起被傳遞，不受執行緒切換影響。既然如此，只要把請求識別碼放進 Coroutine Context，讓它成為這組集合裡的其中一個元素，就能讓識別碼跟著協程本身走，而不是跟著執行緒走。協程暫停後換了執行緒恢復也好，父範圍底下同時衍生出多個平行子協程也好，只要它們共享同一個父範圍衍生出的 Context，就能攜帶同一份請求識別碼資訊。

具體的時機點，落在請求剛進來、建立這次請求對應的 Coroutine Scope 的那一刻。Day 05：Coroutine Scope，協程住在哪裡、活多久 談過，合理的做法是讓一次請求相關的所有協程共用同一個 Scope，這個 Scope 的生命週期與請求的生命週期綁在一起。今天要做的事，是在建立這個 Scope 的同時，把一個包含請求識別碼的自訂 Context 元素放進去，之後這個 Scope 底下啟動的所有子協程，無論最終被 Dispatcher 排到哪條執行緒，都能存取到這個識別碼。這裡只需要建立這層概念性理解，自訂 Context 元素背後如何攔截執行緒切換、如何在暫停恢復之間正確搬移狀態，屬於協程框架整合日誌函式庫時才會深入的實作細節，不是今天要展開的範圍。

把這個概念落到 Day 22：收斂進一個具名專案，訂單服務實戰整合版啟動 建立的骨架上看一次。OrderController.getOrder 目前的樣子是接收路徑參數、呼叫 OrderService.getOrderDetail、把結果原封不動回傳出去，今天要在這個既有方法的基礎上，於進入 Service 層之前先產生一個請求識別碼，並把它放進協程執行環境：

@RestController
@RequestMapping("/orders")
class OrderController(
    private val orderService: OrderService,
) {
    @GetMapping("/{orderId}")
    suspend fun getOrder(@PathVariable orderId: Long): OrderDetailResponse {
        val requestId = RequestId(UUID.randomUUID().toString())
        return withContext(requestId) {
            orderService.getOrderDetail(orderId)
        }
    }
}

這裡的 RequestId 是一個實作了 CoroutineContext.Element 的自訂型別，代表請求識別碼本身作為協程上下文裡的一個元素存在，withContext(requestId) 把這個元素併入目前的 Coroutine Context，讓區塊內部啟動的協程都能存取到它。getOrder 的方法簽章與 orderId、OrderDetailResponse 完全沒有變動，新增的只有產生識別碼與包一層 withContext 這兩件事，延續 Day 22 起「在既有方法基礎上新增，不重新展示完整骨架」的做法。

有了這個識別碼放進 Context 之後，OrderService.getOrderDetail 內部印出日誌時，就能從協程執行環境中把它取出來：

@Service
class OrderService(
    private val orderRepository: OrderRepository,
    private val stockClient: StockClient,
) {
    private val log = LoggerFactory.getLogger(OrderService::class.java)

    suspend fun getOrderDetail(orderId: Long): OrderDetailResponse {
        val requestId = coroutineContext[RequestId]?.value
        log.info("requestId={} 開始查詢訂單 orderId={}", requestId, orderId)

        val order = checkNotNull(orderRepository.findById(orderId))
        val stockStatus = stockClient.checkStock(orderId)

        log.info("requestId={} 查詢完成 orderId={} stockAvailable={}", requestId, orderId, stockStatus.available)
        return OrderDetailResponse(
            orderId = order.id,
            status = order.status,
            stockAvailable = stockStatus.available,
        )
    }
}

coroutineContext[RequestId] 這個寫法，是拿 RequestId 這個元素的 Key 去 Coroutine Context 這個集合裡查找對應的值，取得的結果不受這行程式碼實際跑在哪條執行緒上影響，因為它查的是協程本身攜帶的資料，不是任何一種執行緒儲存空間。就算 getOrderDetail 這段邏輯在等待資料庫或下游服務回應時暫停、恢復後換了一條執行緒，這裡取出的 requestId 依然是同一個值。放進 Day 13 那個確認優惠資格與發送通知平行協程的情境裡也一樣成立，只要這兩個 async 區塊都衍生自同一個帶有 RequestId 的父範圍，各自印出的日誌都能取到同一份識別碼，即使它們原本就分散在不同執行緒上執行。這正是今天真正解決掉的問題：識別碼跟著協程走，不再跟著執行緒走。

結構化日誌，讓日誌本身更容易被查詢與分析

光是把請求識別碼正確帶進日誌還不夠，前面範例裡 log.info 印出的訊息，本質上仍然是一串純文字敘述，識別碼跟其他資訊混在同一行字串裡，日後想寫程式去解析、篩選，還是得靠字串比對或正規表示式，麻煩且容易出錯。

結構化日誌處理的正是這個問題。相對於純文字敘述式的日誌，結構化日誌把請求識別碼、時間戳記、日誌等級、訊息內容各自當成獨立欄位記錄下來，通常會輸出成 JSON 這類固定格式，而不是一句自然語言拼接出來的句子。這樣的格式，人眼讀起來或許不如一句完整的話直覺，但對日誌收集工具來說，每個欄位的邊界清清楚楚，解析與查詢都輕鬆很多。這裡只需要建立這一層概念，特定日誌格式標準該怎麼選、日誌收集工具鏈該怎麼串接，不在今天的範圍內展開。

把這件事放回訂單服務的情境想一次會更具體。如果訂單服務印出的日誌都帶有結構化的請求識別碼欄位，某次促銷活動高峰期間，有個使用者反映他的訂單查詢結果看起來怪怪的，只要有那筆請求的識別碼，就能直接依照這個欄位查詢，把這個請求從查詢訂單、確認庫存，一路到 Day 13 那段確認優惠資格與發送通知的完整過程，一次拼湊出來，不需要在滿是交錯日誌的檔案裡大海撈針。這套機制解決的正是本篇一開頭那個失效場景的反面：日誌不再各自散落，而是能被正確地串接回同一個請求。

看得到過程了，但看不到系統整體的健康狀況

今天把協程情境下日誌關聯失效的根源講清楚了：傳統依賴執行緒的日誌關聯機制，背後假設處理同一個請求的邏輯自始至終跑在同一條執行緒上，這個假設在 Day 7 建立的 Dispatcher 執行緒切換認識、以及 Day 13 建立的平行協程情境下都不成立。解法也不需要另起爐灶，直接把請求識別碼放進 Day 8 定案的 Coroutine Context，讓識別碼跟著協程本身傳遞，搭配結構化日誌，讓一次請求橫跨多個協程、甚至跨越多條執行緒時，日誌依然能被正確地串接回同一個請求。

但這裡也該老實面對下一個問題。日誌能讓我們回頭追查個別請求發生了什麼事，這對除錯與異常調查很有幫助，但如果想知道的是整個系統長期的健康狀況，例如平均有多少請求進來、逾時的比例是多少、Day 24 那兩種鎖機制版本衝突的頻率究竟高不高，一筆一筆翻日誌並不是一件有效率的事。日誌回答的是「這一個請求發生了什麼」，回答不了「這個系統整體長什麼樣子」。

下一篇要導入能回答這類問題的工具。

《Day 26：Metrics 與監控，量化你的協程效能表現》 見。