日志追踪
# 背景
在日常开发中,我们常常会遇到一些难以预见的业务逻辑错误。为了解决这类问题,通常会借助一些技术手段来获取上下文信息,其中最常用的方法就是记录日志(log)。通过详尽的日志输出,我们可以清晰地掌握业务流程、数据变更等关键信息。
然而,随着业务场景的复杂化,我们逐渐受到项目运行环境、业务并发量以及代码实现复杂度等因素的限制。此时,如何从海量日志中精准地定位问题并获取相关的上下文信息,成为一项挑战。
基于上述的问题,我们不难想到,能否为每个请求分配一个唯一标识,从而确保在日志检索的时候,可以通过唯一标识进行定位?
# 示例
# 1. 通过全局变量标识唯一值 ❌
很容易我们想到一个方案,就是维护一个全局变量,当请求进来以后,我们初始化对应的变量,后续打印日志的时候,获取变量即可。
请看下方的全局变量
的示例:
const axios = require('axios');
const koa = require('koa');
const app = new koa();
let traceId;
app.use(async ctx => {
traceId = Math.random().toString(36).substring(2, 6);
console.log('request start', traceId);
// 模拟一些异步调用
await someAsyncCall();
console.log('request ending', traceId);
ctx.body = 'Hello World' + traceId;
});
app.listen(3000);
async function someAsyncCall() {
console.log('someAsyncCall start', traceId);
return new Promise(resolve => setTimeout(() => {
resolve();
console.log('someAsyncCall end', traceId);
}, 2000));
}
// 模拟客户端请求
(async () => {
const arr = [];
for (let i = 0; i < 2; i++) {
arr.push(axios.get('http://localhost:3000'));
}
await Promise.allSettled(arr);
})();
// request start iqd9
// someAsyncCall start iqd9
// request start y71d
// someAsyncCall start y71d
// someAsyncCall end y71d
// request ending y71d
// someAsyncCall end y71d
// request ending y71d
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
从上述示例不难看出,由于两个请求几乎同时发出,traceId
的值会被第二个请求覆盖,从而影响到第一个请求中后续的日志打印。
产生该问题的原因是 Nodejs 的全局变量被多个请求共享,不同于Java、C++ 等语言,会为每个请求分配线程,而线程天然拥有属于该请求的上下文环境(如线程局部变量)。
既然提到局部变量,那我们能不能尝试将 traceId
作为一个局部变量使用呢?
# 2. 通过参数传递方式实现唯一值标识 ❌
const axios = require('axios');
const koa = require('koa');
const app = new koa();
app.use(async ctx => {
const traceId = Math.random().toString(36).substring(2, 6);
ctx.traceId = traceId;
console.log('request start', ctx.traceId);
// 模拟一些异步调用
await someAsyncCall(ctx);
console.log('request ending', ctx.traceId);
ctx.body = 'Hello World' + ctx.traceId;
});
app.listen(3000);
async function someAsyncCall(ctx) {
console.log('someAsyncCall start', ctx.traceId);
return new Promise(resolve => setTimeout(() => {
resolve();
console.log('someAsyncCall end', ctx.traceId);
}, 2000));
}
// 模拟客户端请求
(async () => {
const arr = [];
for (let i = 0; i < 2; i++) {
arr.push(axios.get('http://localhost:3000'));
}
await Promise.allSettled(arr);
})();
// request start ee6s
// someAsyncCall start ee6s
// request start h96m
// someAsyncCall start h96m
// someAsyncCall end ee6s
// request ending ee6s
// someAsyncCall end h96m
// request ending h96m
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
当通过 参数传递 的方法也可以解决唯一标识的问题,但是其仍然存在一些问题:
代码复杂度,每层函数都需要显式的传递
traceId
尽管,该参数与当前业务无关。边界情况难以触及,当调用一些中间件、三方服务时,函数签名固定,不支持传入。脱离同步栈(比如
setTimeout
、事件监听、第三方异步库回调)的时候,也无法传入。
# 3. Nodejs - AsyncLocalStorage ✅
AsyncLocalStorage
是 Nodejs 提供的一种异步上下文跟踪解决方案。它类似于其他语言中的线程本地存储。我们可以通过它重构上面的例子。
const axios = require('axios');
const koa = require('koa');
const { AsyncLocalStorage } = require('async_hooks');
const asyncLocalStorage = new AsyncLocalStorage();
const app = new koa();
// 定义 log 函数
const log = (...args) => {
const traceId = asyncLocalStorage.getStore();
console.log(...args, traceId);
};
app.use(async (ctx, next) => {
const traceId = Math.random().toString(36).substring(2, 6);
asyncLocalStorage.run(traceId, async () => {
await next();
});
});
app.use(async ctx => {
log('request start');
// 模拟异步定时器回调
await someAsyncCall();
log('request ending');
ctx.body = 'Hello World';
});
app.listen(3000);
async function someAsyncCall() {
log('someAsyncCall start');
return new Promise(resolve => setTimeout(() => {
resolve();
log('someAsyncCall end');
}, 2000));
}
// 模拟客户端请求
(async () => {
const arr = [];
for (let i = 0; i < 3; i++) {
arr.push(axios.get('http://localhost:3000'));
}
await Promise.allSettled(arr);
})();
// request start i43l
// someAsyncCall start i43l
// request start e2qy
// someAsyncCall start e2qy
// someAsyncCall end i43l
// request ending i43l
// someAsyncCall end e2qy
// request ending e2qy
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
# AsyncLocalStorage 实现原理
# AsyncLocalStorage 类
const storageList = [];
const storageHook = createHook({
// 注册一个异步事件初始化的 hook
init(asyncId, type, triggerAsyncId, resource) {
// 当前的执行环境
const currentResource = executionAsyncResource();
for (let i = 0; i < storageList.length; ++i) { // 将当前执行环境的 store 传递给新初始化的异步事件
storageList[i]._propagate(resource, currentResource, type);
}
},
});
function createHook(fns) {
return new AsyncHook(fns);
}
class AsyncLocalStorage {
constructor() {
this.kResourceStore = Symbol('kResourceStore');
this.enabled = false;
}
// 启动逻辑
_enable() {
if (!this.enabled) {
this.enabled = true;
ArrayPrototypePush(storageList, this);
storageHook.enable(); // 通过 async_hooks 注册 hook 事件
}
}
// AsyncLocalStorage 核心逻辑
run(store, callback, ...args) {
// 判断传入的 store 是否和当前运行环境的 store 一致,避免重复执行
if (ObjectIs(store, this.getStore())) {
return ReflectApply(callback, null, args);
}
// 启动当前示例
this._enable();
// 获取当前正在执行的异步资源
const resource = executionAsyncResource();
const oldStore = resource[this.kResourceStore]; // 获取旧的资源的 store
resource[this.kResourceStore] = store; // 赋值新 store
try {
// 携带新 store 执行回调函数
return ReflectApply(callback, null, args);
} finally {
resource[this.kResourceStore] = oldStore; // 无论失败与否都将旧 store 赋值回去
}
}
}
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
# run()
AsyncLocalStorage
的核心方法为 run(store, callback)
。
- 其接收
store
和callback
参数,store
是上下文需要共享的变量,callback
则为后续需要执行的业务代码。对应使用方式:
import { AsyncLocalStorage } from "async_hooks";
const asyncLocalStorage = new AsyncLocalStorage();
// store
let traceId = 1;
// some async function
let asyncFunction = async () => {
console.log(asyncLocalStorage.getStore()); // 1
};
// run
asyncLocalStorage.run(traceId++, asyncFunction);
2
3
4
5
6
7
8
9
10
11
12
13
14
run()
校验了store
是否与当前环境的store
一致。避免重复更新store
。若是首次启动,会通过
createHook()
构造一个asyncHooks
对象,并且初始化init()
事件,用于监听后续异步任务的初始化操作。记录当前环境的
store
并将新的store
绑定到对应的异步事件上,后续执行无论成功与否都需要重新赋回旧变量。类似下面示例的感觉:
import { AsyncLocalStorage } from "async_hooks";
const asyncLocalStorage = new AsyncLocalStorage();
// store
let traceId = 1;
// some async function
let asyncFunction = async () => {
console.log(asyncLocalStorage.getStore());
if (traceId <= 3) asyncLocalStorage.run(traceId++, asyncFunction);
console.log(asyncLocalStorage.getStore());
};
// run
asyncLocalStorage.run(traceId++, asyncFunction);
// 1
// 2
// 3
// 3
// 2
// 1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
由核心实现可以看出,AsyncLocalStorage
主要功能是创建了一个独立的上文环境,并且维护 store
和当前执行环境的关系。而对异步事件的跟踪,主要是依赖于 async_hooks
实现的。
# async_hooks 类
async_hooks
的核心实现基于底层 API 这里不深入探讨,仅对其功能做了解。
async_hooks
异步钩子,顾名思义其提供了一套监听异步资源动作的方法。具体实现如下:
class AsyncHook {
constructor({ init, before, after, destroy, promiseResolve }) {
// 校验参数是否为 func
if (init !== undefined && typeof init !== 'function')
throw new ERR_ASYNC_CALLBACK('hook.init');
if (before !== undefined && typeof before !== 'function')
throw new ERR_ASYNC_CALLBACK('hook.before');
if (after !== undefined && typeof after !== 'function')
throw new ERR_ASYNC_CALLBACK('hook.after');
if (destroy !== undefined && typeof destroy !== 'function')
throw new ERR_ASYNC_CALLBACK('hook.destroy');
if (promiseResolve !== undefined && typeof promiseResolve !== 'function')
throw new ERR_ASYNC_CALLBACK('hook.promiseResolve');
// 初始化赋值
this[init_symbol] = init;
this[before_symbol] = before;
this[after_symbol] = after;
this[destroy_symbol] = destroy;
this[promise_resolve_symbol] = promiseResolve;
}
enable() {
// 获取当前的 hooks 数组和对应的计数器(如多少个 hook 含有 init/before 等)
const { 0: hooks_array, 1: hook_fields } = getHookArrays();
// 如果 hooks 已经启用, 就不重复添加
if (ArrayPrototypeIncludes(hooks_array, this))
return this;
const prev_kTotals = hook_fields[kTotals];
// 计算当前的 hooks 总数。 通过将 func 转 bool 值进行数值累加。
hook_fields[kTotals] = hook_fields[kInit] += +!!this[init_symbol];
hook_fields[kTotals] += hook_fields[kBefore] += +!!this[before_symbol];
hook_fields[kTotals] += hook_fields[kAfter] += +!!this[after_symbol];
hook_fields[kTotals] += hook_fields[kDestroy] += +!!this[destroy_symbol];
hook_fields[kTotals] +=
hook_fields[kPromiseResolve] += +!!this[promise_resolve_symbol];
// 把这个 hook 加入 hooks 数组
ArrayPrototypePush(hooks_array, this);
// 如果是初次调用, 则启动 hooks
if (prev_kTotals === 0 && hook_fields[kTotals] > 0) {
enableHooks();
}
// 根据是否含有 promiseResolve 来更新 Promise hook 状态
updatePromiseHookMode();
return this;
}
disable() {
const { 0: hooks_array, 1: hook_fields } = getHookArrays();
// 找到当前 hook 在数组中的索引
const index = ArrayPrototypeIndexOf(hooks_array, this);
if (index === -1)
return this; // 不存在则直接返回
// 计算当前 hooks 总数
const prev_kTotals = hook_fields[kTotals];
hook_fields[kTotals] = hook_fields[kInit] -= +!!this[init_symbol];
hook_fields[kTotals] += hook_fields[kBefore] -= +!!this[before_symbol];
hook_fields[kTotals] += hook_fields[kAfter] -= +!!this[after_symbol];
hook_fields[kTotals] += hook_fields[kDestroy] -= +!!this[destroy_symbol];
hook_fields[kTotals] +=
hook_fields[kPromiseResolve] -= +!!this[promise_resolve_symbol];
// 移除当前 hook
ArrayPrototypeSplice(hooks_array, index, 1);
// 如果 hook 被移除完毕, 则关闭全局 async_hooks
if (prev_kTotals > 0 && hook_fields[kTotals] === 0) {
disableHooks();
}
return this;
}
}
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
async_hooks
类提供了 enable()
和 disble()
两个方法,这俩方法的主要功能在于是否监听异步资源的 hook 事件。例如下面的示例:
import async_hooks from "async_hooks";
import fs from "fs";
// 创建异步钩子回调函数
const hook = async_hooks.createHook({
init(asyncId, type, triggerAsyncId, resource) {
fs.writeSync(
1,
`init: asyncId=${asyncId}, type=${type}, triggerAsyncId=${triggerAsyncId}\n`
);
},
before(asyncId) {
fs.writeSync(1, `before: asyncId=${asyncId}\n`);
},
after(asyncId) {
fs.writeSync(1, `after: asyncId=${asyncId}\n`);
},
destroy(asyncId) {
fs.writeSync(1, `destroy: asyncId=${asyncId}\n`);
},
promiseResolve(asyncId) {
fs.writeSync(1, `promiseResolve: asyncId=${asyncId}\n`);
},
});
hook.enable();
// 自定义异步事件
Promise.resolve().then(() => {
fs.writeSync(1, "custom log promise.then()\n");
});
// 延时 100ms 后禁用钩子(卸载监听)
setTimeout(() => {
hook.disable();
fs.writeSync(1, "AsyncHook disable \n");
// 之后的异步操作将不会触发钩子回调
setTimeout(() => {
fs.writeSync(1, "new setTimeout\n");
}, 50);
}, 100);
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
这里着重介绍 async_hooks
的支持的几个事件。
// `init()` 在异步资源构造时被调用(但可能还未完成构造)
// 注意:此时传入的 resource 对象的字段可能尚未初始化完成
function init(asyncId, type, triggerAsyncId, resource) {
// asyncId: 当前新建资源的 ID
// type: 异步资源类型,例如 Timeout、PROMISE、TCPWRAP 等
// triggerAsyncId: 触发这个异步资源的父资源 ID
// resource: 底层资源对象
}
// `before()` 在异步资源的回调即将执行前被调用
// 对于 handle 类资源(如 TCPWrap),可能调用多次;对于 request 类型只会调用一次
function before(asyncId) {
// asyncId: 即将执行回调的异步资源 ID
}
// `after()` 在异步资源的回调执行完之后调用
function after(asyncId) {
// asyncId: 刚刚执行完回调的异步资源 ID
}
// `destroy()` 在异步资源生命周期结束(被销毁)时调用
function destroy(asyncId) {
// asyncId: 即将销毁的异步资源 ID
}
// `promiseResolve()` 仅对 Promise 类型资源有效
// 当 Promise 被 resolve 或 reject 时调用
function promiseResolve(asyncId) {
// asyncId: 被解决的 Promise 的异步资源 ID
}
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
# 兼容性问题❗
async_hooks
装载于 Nodejsv8.1.0
版本,至今仍为 实验性 阶段,且官网推荐优先使用AsyncLocalStorage
异步上下文追踪。AsyncLocalStorage
装载于 Nodejsv12.17.0
版本,但上线以后存在性能和稳定性问题,后续因 v8 工程师提供更深层次的 API 后于 Nodejsv16.4.0
版本稳定,所以推荐在v16.4.0
后续使用。asyncLocalStorage.enterWith(store)
截止于当前稳定版本 Nodejsv24.5.0
该 API 仍为 实验性 阶段。Bun 称近 100% 兼容 Nodejs API 但在
async_hooks
方面并没能使用 v8 相关的 API ,所以其强烈推荐不要使用它。