请求结束后,日志为什么还拿得到旧 RequestId
一次 HTTP 请求带着 RequestId = "req-42" 进入 MsRequestLoggingMiddleware。处理请求时排了一个任务,任务要等请求结束后才读取日志上下文。请求已经结束,这个任务还应从 RequestLogScope.Current 读到 req-42 吗?本组件选择让它读到 null,避免把已结束请求的字段带到后续日志。
下面的代码可放在一个 async Task 方法中运行。Task.Run 在请求作用域内排队;release 保证读取发生在作用域释放之后:
var release = new TaskCompletionSource<bool>(
TaskCreationOptions.RunContinuationsAsynchronously);
Task<string?> lateLog;
using (RequestLogScope.Push(new RequestLogContext { RequestId = "req-42" }))
{
lateLog = Task.Run(async () =>
{
await release.Task;
return RequestLogScope.Current?.RequestId;
});
Console.WriteLine("作用域内:" + RequestLogScope.Current?.RequestId);
}
Console.WriteLine("作用域结束:" + (RequestLogScope.Current?.RequestId ?? "<null>"));
release.SetResult(true);
Console.WriteLine("已排队任务:" + ((await lateLog) ?? "<null>"));
当前实现的输出是:
作用域内:req-42
作用域结束:<null>
已排队任务:<null>
前两行在三种实现下相同。最后一行则不同:
AsyncLocal 保存的值 |
“已排队任务”输出 |
|---|---|
直接保存 RequestLogContext |
req-42 |
保存只读的 ScopeState { Context },释放时只恢复旧值 |
req-42 |
保存可清空的 Holder,释放时把 Context 设为 null |
<null> |
调用 Task.Run 的那一刻,.NET 默认把当时的 AsyncLocal 值随 ExecutionContext 交给任务;任务实际何时开始运行不影响这一点。请求代码结束时改写自己的 AsyncLocal.Value,不会改写任务已经带走的值。只读 ScopeState 也一样:任务带走的是那个包装对象,包装对象里的 Context 从未被清空。修复前,Dispose_ShouldClearContextInChildFlowCapturedBeforeDisposal 测试实际读到了 req-42;现在它读到 null。
可清空的 Holder 给请求代码和已排队任务提供同一个间接引用。请求结束时清空这个对象里的 Context;任务随后通过 Current 查找,就看不到旧请求了。ASP.NET Core 的 HttpContextAccessor也利用这层间接引用清理已结束的 HttpContext。ExecutionContext 文档说明异步代码如何继承执行上下文。
请求中还有一个临时作用域
日志作用域可以嵌套。假设请求 ID 是 request,其中一小段操作临时使用 step;操作结束后,请求代码还要继续使用 request。这段操作也排了一个稍后才读取日志上下文的任务:
var releaseStep = new TaskCompletionSource<bool>(
TaskCreationOptions.RunContinuationsAsynchronously);
Task<string?> lateStepLog;
using (RequestLogScope.Push(new RequestLogContext { RequestId = "request" }))
{
using (RequestLogScope.Push(new RequestLogContext { RequestId = "step" }))
{
lateStepLog = Task.Run(async () =>
{
await releaseStep.Task;
return RequestLogScope.Current?.RequestId;
});
}
Console.WriteLine("临时作用域结束:" + RequestLogScope.Current?.RequestId);
releaseStep.SetResult(true);
Console.WriteLine("已排队任务:" + ((await lateStepLog) ?? "<null>"));
}
输出是:
临时作用域结束:request
已排队任务:<null>
请求代码得到 request,因为临时作用域结束后恢复了先前的作用域。任务排队时继承的是 step 作用域,而它在任务读取前已经结束。直接存值或旧的只读 ScopeState 会让第二行输出 step。
每次 Push 因此创建一个新的 Holder。进入 step 时保留 request 的 Holder;离开 step 时只清空 step 的 Holder,再恢复 request。即使两次 Push 传入同一个 RequestLogContext 对象,也要分别创建 Holder,否则结束内层作用域会让仍有效的外层作用域一起失效。HttpContextAccessor 的属性 setter 是替换操作,没有这里的嵌套恢复要求,不能把它的清理顺序直接照搬过来。
什么时候不需要 Holder
如果排出的任务本来就应该继续保留当时的值,直接使用 AsyncLocal<T> 即可。例如一个批处理任务在启动时继承不可变的批次标识,启动代码随后清空自己的值,任务仍读到原标识:
var batchId = new AsyncLocal<string?> { Value = "batch-7" };
var release = new TaskCompletionSource<bool>(
TaskCreationOptions.RunContinuationsAsynchronously);
var work = Task.Run(async () =>
{
await release.Task;
return batchId.Value;
});
batchId.Value = null;
release.SetResult(true);
Console.WriteLine("启动代码:" + (batchId.Value ?? "<null>"));
Console.WriteLine("已排队任务:" + await work);
输出是:
启动代码:<null>
已排队任务:batch-7
如果所有使用该值的任务都会在作用域结束前完成,直接存值也能满足这个生命周期约定。需要让任务长期保留某个字段时,显式把字段作为参数传给任务通常更容易看清所有权。
RequestLogScope 的值来自一次请求,Dispose 表示这次请求的日志作用域结束,因此选择可清空的 Holder。只增加一个不能清空的包装对象,对上面任何输出都没有帮助。
这项保证的边界和成本
Holder 控制的是以后通过 RequestLogScope.Current 进行的查找。如果代码在释放前执行 var saved = RequestLogScope.Current,之后直接使用 saved,Holder 无法收回那个引用。任务自行建立的新日志作用域也不会随原请求的作用域一起清空。调用方仍应按进入顺序的逆序释放嵌套作用域。
从模块根目录运行 基准程序,在 Windows x64、.NET 10.0.12、Release 下,每场景测 7 轮、每轮 20 万次,取中位数:
| 普通 Push/Dispose | 耗时 | 托管分配 |
|---|---|---|
| 直接保存上下文 | 100.8 ns/次 | 104 B/次 |
| 可清空 Holder | 117.3 ns/次 | 136 B/次 |
重复运行中分配差值稳定为 32 B/次,耗时有波动。这个基准只测作用域操作,不代表完整 HTTP 请求或日志输出的成本。该实现没有引入反射或动态代码生成。