AsyncLocalStorage与日志追踪

最近在思考node.js如何做服务间与服务内部的日志追踪，一个很简单的实现就是在HTTP request header里添加一个字段x-trace-id来标识唯一性，打印日志时添加x-trace-id的值。但如何保存这个状态呢？

我看到的一些框架和应用会将traceId作为参数传递到应用的各个函数/方法里，调用logger.info(traceId, "XXX")来实现打印traceId的功能。这样的写法并不优雅，但node.js又不像其他语言框架，比如Spring MVC，可以用过ThreadLocal来保存这个状态，那如何保存这个状态呢？其实node.js已经有了这样一个API：AsyncLocalStorage。

AsyncLocalStorage属于async_hooks模块，node.js v14引入，后被反向移植到v12上。下面用一个express应用来说明它的用法。

import { AsyncLocalStorage } from "async_hooks"
import express from "express"
import { v4 as uuid4 } from "uuid"

export const app = express()
const t = new AsyncLocalStorage<string>()

app.use((req, _, next) => {
  const traceId = req.header('x-trace-id')
  t.run(traceId ?? uuid4(), next)
})

app.get('/', async function (_, res) {
  console.log('start', t.getStore())
  // 模拟耗时操作
  await new Promise((resolve) => {
    setTimeout(() => resolve(), 100)
  })
  console.log('end', t.getStore())
  res.send('Hello World!')
})

app.listen(3000)

这里我们写了一个middleware，将HTTP Request Header里的信息保存到AsyncLocalStorage实例中，需要打印日志时使用getStore方法获取。

我们期望的行为是：一个请求进来后，保存并打印它的traceId，之后进行了一些异步操作，操作结束后，我们能通过AsyncLocalStorage获取到保存的traceId。下面我们就使用ab命令验证一下。

ab -n 6 -c 2 http://localhost:3000/

从日志中我们看出确实是成功地将状态保存了下来。

start 1c9de33e-84a0-4827-ae82-eae9dd8dec60
end 1c9de33e-84a0-4827-ae82-eae9dd8dec60
start 9c1f6eab-5c95-4a5f-b2f4-2f1a026684f5
start 61a32915-5316-4066-bfb0-382c41a2a1aa
end 9c1f6eab-5c95-4a5f-b2f4-2f1a026684f5
end 61a32915-5316-4066-bfb0-382c41a2a1aa
start bb1cb174-0f42-4dc6-9eab-85ccaef9d08c
start 3ef04aba-dc0c-4c02-aebf-850dbf8c2e31
end bb1cb174-0f42-4dc6-9eab-85ccaef9d08c
end 3ef04aba-dc0c-4c02-aebf-850dbf8c2e31
start a39d34be-da8a-44f6-b3b4-3eb6eb3501ef
end a39d34be-da8a-44f6-b3b4-3eb6eb3501ef

这样的写法比起将logger作为参数在各个函数间传递的做法，可读性、可维护性更强，对业务代码的侵入也更低。

以上是服务内日志追踪的办法。

那如何做服务与服务之间的追踪呢？其实也很简单，将traceId注入到http-client的header中，或者更进一步，重写require函数，调用http/https模块时，将traceId注入。这里就不详细展开。