使用 Async-hooks 串聯 HTTP 請求上下文

時間 2019-11-10

標籤使用 async hooks 串聯 http 請求上下文欄目 HTTP/TCP 简体版

原文原文鏈接

開門見山，以前在寫業務要求的時候，有一個記錄慢查詢和慢請求的耗時並上報至 ES 的需求，一樣也會有其餘類型的日誌須要記錄上報，起初並無統一字段，各類類型的日誌的字段比較鬆散，如今須要統一日誌字段。這個需求提及來也算是簡單，提取一些公用的字段，好比 type、timeTaken、data 等字段，另外還有一些共有的字段，好比 username、method、url 等，這些共有字段並不須要外部傳進來，只需從請求上下文中獲取便可。html

若是上述方法能完美的解決需求，這篇專欄文章就能夠立刻發佈了，可現實老是要比想象的複雜。node

因爲上報日誌的方法 (下文稱爲 sendLog) 已經被多處使用，且起初並無傳遞 req 對象，也就是說若是要使用上述方案，那麼必須給 sendLog 添加參數，這個 req 對象就必須在請求處理的 handler 裏面層層傳遞至 sendLog，對於一個已經上線了十個月的項目來講，這樣改造起來比較比較繁瑣，也不夠優(zhuang)雅(bi)～mysql

那麼有沒有一種不用傳遞 req 對象且能方(you)便(ya)的獲取請求上下文的方法呢？git

轉戰 Google 和 Stack Overflow 許久以後找到了一個 NPM 包express-http-context，此包每週有 30k+ 的下載量，看介紹裏面描述以爲足夠優雅好用，瞬間以爲這下應該穩了。github

一頓常規操做以後，居然跑起來了，不用傳遞 req 對象也能獲取到共有的參數，本地各類測試 case 各來一發，結果就是一個字——完美！這就叫專業，這就叫 Perfect！sql

本着負(neng)責(run)盡(jiu)職(xing)的態度，抓緊測試上線。先上一波測試環境，觀察一段時間以後沒問題，而後就發到生產環境了，觀察一段時間以後，發現日誌正常，CPU 和 RAM 也正常，關機下班。數據庫

背景

上述那麼一大堆就是背景。express

新問題

發佈上線許久以後，某天從日誌裏發現，MySQL 慢查詢的日誌裏面的共有字段全是空的，問題是使用的姿式不對？又或者是上下文丟失了？一頓搜索以後，發現這不是一個新鮮的問題，再一頓搜索以後發現，大多數項目的數據庫鏈接都先於 HTTP 服務啓動，致使回調裏面的 ScopeId 無法和 HTTP 請求關聯，也就是說在 MySQL 的查詢回調裏面，沒法獲取請求上下文。繼續搜索的時候在Context lost after mysql query、mysql2 requests aren't being attached to root scope #946和Async Hooks do not recognize execution contexts created when processing thenables #22360裏發現能夠用 util.promisify 規避這個問題。npm

拆包

express-http-context內部並無多少代碼，邏輯簡單到就是給cls-hooked套了一個殼子，將它封裝成 Express 的中間件，下面簡單看下cls-hooked，核心邏輯在cls-hooked/blob/master/context.js裏面，大體是利用了 NodeJS v8 內置的async_hooks模塊的異步鉤子特性，基於此封裝了一個命名空間來管理請求上下文，並無發現什麼明顯的漏洞，百思不得解，一頓搜索以後在專欄上搜索到了一篇相關的文章——《使用 Async-hooks 集成 Envoy 和咱們的 RPC 庫（二）》，這篇專欄裏提到的問題一和問題三應該就是上述問題的解釋：api

在 async_hooks 的生命週期內，before、after是可能沒有的，祖先的destory可能會比後代早。

關於 async_hooks 的介紹能夠參考本文末尾連接的文章。

瞭解到上述緣由以後，單純的利用 async_hooks 的生命週期鉤子並不能確保上下文不會丟失，因此一個簡單的思路就是隻使用 init 鉤子函數來記錄調用棧，而後在必定時間後清除這些調用棧。

造輪子

大致思路上面已經提到，這裏簡單總結一下：

使用 async_hooks 的 init 方法來記錄調用棧。
找到某個特徵將一個請求的調用棧串起來。
定時清除調用棧。

第1步須要在 init 方法中記錄調用方和被調用方的映射關係便可，這些映射關係就組成了調用棧的依賴樹，一層一層的自上而下的調用下去。細節就是創建異步調用的 asyncId 和 executionAsyncId 之間的映射關係，type 參數是爲了標識異步資源的類型，主要是爲了區分 TCPWRAP 實例，__tm 是記錄調用棧的創建時間，以便後續清除。

asyncHooks.createHook({
  init (asyncId, type) {
    const executionAsyncId = asyncHooks.executionAsyncId()

    callstackMap[asyncId] = {
      id: executionAsyncId,
      isTCP: type === TCPWRAP_NAME,
      __tm: Date.now()
    }
  }
}).enable()

第3步用定時器去清除過時的調用棧便可。

第2步就是如何在茫茫如海的調用棧中將一個請求全部相關的調用棧串起來，最終請求都會通過這個中間件，如何在 Express 或者 Koa 這種框架的模型下組織請求上下文？寫個 Express 和 async_hooks 組合的例子，看看 init 方法的參數：

const fs = require('fs')
const asyncHooks = require('async_hooks')
const express = require('express')

asyncHooks.createHook({
  init (asyncId, type, triggerAsyncId) {
    const eid = asyncHooks.executionAsyncId()
    fs.writeSync(1, `${type}(${asyncId}): trigger: ${triggerAsyncId} execution: ${eid}\n`)
  }
}).enable()

const app = express()

app.all('*', (req, res) => {
  res.send('Hello World!')
})

app.listen(3001)

請求三次後查看打印以下：

TCPWRAP(6): trigger: 1 execution: 1
TickObject(7): trigger: 6 execution: 1
TCPWRAP(8): trigger: 6 execution: 0
TIMERWRAP(9): trigger: 6 execution: 6
Timeout(10): trigger: 6 execution: 6
HTTPPARSER(11): trigger: 6 execution: 6
HTTPPARSER(12): trigger: 6 execution: 6
TickObject(13): trigger: 6 execution: 6
TIMERWRAP(14): trigger: 12 execution: 12
Timeout(15): trigger: 12 execution: 12
TickObject(16): trigger: 8 execution: 12
WRITEWRAP(17): trigger: 8 execution: 12
TickObject(18): trigger: 12 execution: 12
TickObject(19): trigger: 12 execution: 12
TickObject(20): trigger: 16 execution: 16
TIMERWRAP(21): trigger: 16 execution: 16
TickObject(22): trigger: 19 execution: 19
TickObject(23): trigger: 20 execution: 20
TickObject(24): trigger: 20 execution: 20
TickObject(25): trigger: 20 execution: 20
TickObject(26): trigger: 8 execution: 8
TickObject(27): trigger: 8 execution: 8
TCPWRAP(28): trigger: 6 execution: 0
Timeout(29): trigger: 6 execution: 6
HTTPPARSER(30): trigger: 6 execution: 6
TickObject(31): trigger: 6 execution: 6
TIMERWRAP(32): trigger: 30 execution: 30
TickObject(33): trigger: 28 execution: 30
WRITEWRAP(34): trigger: 28 execution: 30
TickObject(35): trigger: 30 execution: 30
TickObject(36): trigger: 30 execution: 30
TickObject(37): trigger: 33 execution: 33
TickObject(38): trigger: 36 execution: 36
TickObject(39): trigger: 37 execution: 37
TickObject(40): trigger: 37 execution: 37
TickObject(41): trigger: 37 execution: 37
TickObject(42): trigger: 28 execution: 28
TickObject(43): trigger: 28 execution: 28
TCPWRAP(44): trigger: 6 execution: 0
Timeout(45): trigger: 6 execution: 6
HTTPPARSER(46): trigger: 6 execution: 6
TickObject(47): trigger: 6 execution: 6
TickObject(48): trigger: 44 execution: 46
WRITEWRAP(49): trigger: 44 execution: 46
TickObject(50): trigger: 46 execution: 46
TickObject(51): trigger: 46 execution: 46
TickObject(52): trigger: 48 execution: 48
TickObject(53): trigger: 51 execution: 51
TickObject(54): trigger: 52 execution: 52
TickObject(55): trigger: 52 execution: 52
TickObject(56): trigger: 52 execution: 52
TickObject(57): trigger: 44 execution: 44
TickObject(58): trigger: 44 execution: 44

其中第1-2行的日誌在我沒有請求的時候就已經有了，因此請求產生的日誌是從第三行開始的，仔細觀察就會發現，每一次請求都會有一個類型爲TCPWRAP的調用棧記錄，NodeJS 官方文檔裏這樣解釋：

The TCPWRAPis the new connection from the client. When a new connection is made, the TCPWrapinstance is immediately constructed. This happens outside of any JavaScript stack. (An executionAsyncId()of 0means that it is being executed from C++ with no JavaScript stack above it.) With only that information, it would be impossible to link resources together in terms of what caused them to be created, so triggerAsyncIdis given the task of propagating what resource is responsible for the new resource's existence.

簡而言之就是每接收到一個來自客戶端的請求，當這個請求鏈接創建的時候，這個 TCPWrap 實例就馬上被建立。

經過以上發現，咱們能夠利用 TCPWRAP 來標誌一個請求的開始，這個標誌也就能夠做爲這個請求調用棧的根。下面就須要將 TCPWRAP 和中間件關聯起來，咱們經過中間件執行時的 executionAsyncId 和 init 裏記錄的調用棧來向上尋找最近的 TCPWRAP 實例對應的 executionAsyncId，這個 TCPWRAP 實例對應 executionAsyncId 就是這個請求的根。

既然有了這個能夠標誌根的 executionAsyncId，暫且叫它 rootId，那麼請求在進入下一個中間件的時候，均可以根據自身的 executionAsyncId 來向上尋找，直到找到 rootId。每次 set、get 的時候，都會根據對應的 rootId 找到對應的上下文，這樣就將一個請求的上下文串起來了。

因爲 rootId 是在中間件執行的時候肯定的，因此在 TCPWRAP 實例建立以後到中間件之間，不該該有任何異步的操做，簡而言之就是將該中間件放置在其他含有異步操做的中間件的最前面，該中間件以前不該有任何包含異步操做的中間件。

由於從 TCPWRAP 實例建立到進入中間件是同步的，因此在進入中間件的時候，只需按照中間件對應的 executionAsyncId 向前遞歸查找最近的 TCPWRAP 實例對應的 asyncId 便可，也就找到了此次請求對應的 rootId。以後給 rootId 對應的調用棧初始化一個空的上下文，

// middleware logic
const middleware = () => {
  const executionAsyncId = asyncHooks.executionAsyncId()
  const rootId = findTCPWrapAsyncId(executionAsyncId)
  callstackMap[rootId].data = {}
  callstackMap[executionAsyncId] = {
    id: rootId,
    __tm: Date.now()
  }
}

// find rootId
const findTCPWrapAsyncId = asyncId => {
  if (callstackMap[asyncId]) {
    if (callstackMap[asyncId].type === TCPWRAP_NAME) {
      return asyncId
    }
    return findTCPWrapAsyncId(asyncId - 1)
  }
}

優化

總以爲第3步用定時器清除調用棧的操做不夠優雅，出於能儘可能儘快的刪除無用調用棧的考慮，能否在某些時刻主動刪除，而不是一股腦的都在定時器裏刪除。

首先想到的就是利用前文所說的 destory 鉤子方法，可是考慮到上文說起到的問題，須要在 TCPWRAP 實例銷燬的時候清除對應調用棧。還有一種方法就是在 http.ServerResponse 的 finish 和 close 事件觸發的時候清除調用棧。

最後再使用定時器去刪除一些遊走在 http 請求以外的調用棧便可。

還沒完

上述邏輯上線以後，仍然有上下文丟失的狀況發生，真是急禿了頭。從日誌裏發現，上下文丟失絕大多數發生在服務端異步請求超時以後，本地也能夠模擬復現這個問題。許久以後在想明白，在客戶端請求超時或者用戶終止裏鏈接，上述優化操做在這個時候就會清除該請求的調用棧，可是這其中有一個很微妙的細節，客戶端超時以後，服務端調用其餘服務可能尚未結束，在這些調用結束以前，它所屬的請求的調用棧早已被清除，這些調用結束以後在操做上下文的話，上下文早已銷聲匿跡了，無處可尋。

因此上文提到的優化並不可靠，目前只能依賴定時器去清除調用棧，且要根據業務須要合理設置有效時間。

必須優化

還有沒有其餘的優化辦法呢？固然有！既然 destory 鉤子方法不可靠，那就從其餘可靠的地方下手，NodeJS 的請求裏面有兩個事件，分別是finish和close，兩者必然會觸發一個。固然在這兩個事件直接觸發以後清除調用棧是能夠的，不過仍然有一種情形須要妥善考慮，測試過程當中發現 close 事件通常發生在客戶端終止請求，這種情形通常發生在服務端超時(亦或者是服務端處理時間太久)，用戶失去耐心，關閉頁面或者刷新頁面致使的。這種情形下，close 事件觸發以後清除調用棧，內部的異步請求可能稍後纔有返回，這是再去獲取上下文就已經遲了。雖然這個優化點要比 destory 鉤子方法可靠一點，但也不是絕對可靠的，可是在大多數業務場景下，在 finish 事件以後清除調用棧是可靠的！

既然都不是絕對可靠的，那就將這些優化操做做爲可選項，默認關閉。在內部使用中，只開啓了 finish 事件以後清除調用棧，效果挺好。

具體邏輯和以前相似，全部擁有 rootId 的調用棧都會被記到 rootId 下，一旦 finish/close 事件觸發，若是須要清除調用棧的就將該 rootId 對應的調用棧一併清理掉便可。