在OnActionExecutedAsync中添加的NLog Scope属性未在日志中渲染

问题现象 #

在ASP.NET Web API的ActionFilterAttribute中，通过ScopeContext.PushProperty在OnActionExecutedAsync方法添加的NLog范围属性未在日志中渲染显示；而在OnActionExecutingAsync方法中添加的同类属性可正常显示。

相关代码 #

ActionFilterAttribute代码

/// <summary>
/// 执行Action方法前
/// </summary>
public override Task OnActionExecutingAsync(HttpActionContext actionContext, CancellationToken cancellationToken)
{
     ScopeContext.PushProperty("Any-Executing-Property", "Value");
     return base.OnActionExecutingAsync(actionContext, cancellationToken);
}

/// <summary>
/// 执行Action方法后
/// </summary>
public override Task OnActionExecutedAsync(HttpActionExecutedContext ctx, CancellationToken cancellationToken)
{
     ScopeContext.PushProperty("Any-Executed-Property", "Value");
     return base.OnActionExecutedAsync(ctx, cancellationToken);
}

NLog.config配置

<target name="jsonFile"
        xsi:type="File"
        fileName="${logDirectory}/api.jsonl"
        archiveFileName="${logDirectory}/archives/api{#####}.jsonl"
        archiveAboveSize="1000240" 
        archiveNumbering="Sequence" 
        maxArchiveFiles="1"
        keepFileOpen="true" 
        concurrentWrites="false"
        encoding="UTF-8">
    <layout xsi:type="JsonLayout"
        includeAllProperties="true"
        MaxRecursionLimit="2" 
        suppressSpaces="true"
        includeScopeProperties="true">
        <attribute name="context" encode="false">
        <layout type="JsonLayout">
            <attribute name="Any-Executing-Property" layout="${scopeproperty:item=Any-Executing-Property}"/>    
            <attribute name="Any-Executed-Property" layout="${scopeproperty:item=Any-Executed-Property}"/>          
        </layout>
        </attribute>
    </layout>
    </target>

实际日志结果

{"context":{ "Any-Executing-Property": "Value" },"Any-Executing-Property":"Value"}

原因解释 #

ASP.NET Web API的过滤器执行流程决定了：

• OnActionExecutingAsync在Action方法执行前触发，此时添加的Scope属性会被包含在后续整个Action执行过程中输出的日志上下文里，所以能正常显示。
• OnActionExecutedAsync在Action方法执行完成后触发，这时候Action内部的日志已经全部输出完毕，新添加的Scope属性无法回溯到之前的日志中；如果不在OnActionExecutedAsync内部主动记录日志，这个属性就没有对应的日志条目可以附着，自然不会出现在现有日志里。

解决方案 #

方案1：在OnActionExecutedAsync内部记录日志 #

如果需要让Any-Executed-Property出现在日志中，可在添加属性后主动记录一条日志，此时Scope属性会生效：

private static readonly ILogger _logger = LogManager.GetCurrentClassLogger();

/// <summary>
/// 执行Action方法后
/// </summary>
public override Task OnActionExecutedAsync(HttpActionExecutedContext ctx, CancellationToken cancellationToken)
{
     using (ScopeContext.PushProperty("Any-Executed-Property", "Value"))
     {
         _logger.Info("Action执行完成");
         return base.OnActionExecutedAsync(ctx, cancellationToken);
     }
}

此时日志会包含该属性：

{"context":{ "Any-Executing-Property": "Value", "Any-Executed-Property": "Value" },"Any-Executing-Property":"Value","Any-Executed-Property":"Value","message":"Action执行完成"}

方案2：提前收集属性信息，在Action执行时注入Scope #

如果需要让Action内部的日志也包含Any-Executed-Property相关信息，可在OnActionExecutingAsync中提前准备好后续需要的属性数据，通过HttpActionContext.Properties存储，然后在Action内部或其他日志输出点将其添加到Scope中：

public override Task OnActionExecutingAsync(HttpActionContext actionContext, CancellationToken cancellationToken)
{
     ScopeContext.PushProperty("Any-Executing-Property", "Value");
     // 提前存储后续需要的属性值
     actionContext.Properties["ExecutedPropertyValue"] = "Value";
     return base.OnActionExecutingAsync(actionContext, cancellationToken);
}

// 在Action方法中
public IHttpActionResult Get()
{
    if (Request.Properties.TryGetValue("ExecutedPropertyValue", out var value))
    {
        using (ScopeContext.PushProperty("Any-Executed-Property", value.ToString()))
        {
            _logger.Info("Action执行中");
        }
    }
    return Ok();
}

方案3：使用NLog的全局诊断上下文（GDC）替代ScopeContext #

如果属性不需要严格的异步上下文隔离，可使用GlobalDiagnosticsContext.Set来设置属性，它的生命周期更长，能覆盖到OnActionExecutedAsync阶段的日志：

public override Task OnActionExecutedAsync(HttpActionExecutedContext ctx, CancellationToken cancellationToken)
{
     GlobalDiagnosticsContext.Set("Any-Executed-Property", "Value");
     try
     {
         _logger.Info("Action执行完成");
         return base.OnActionExecutedAsync(ctx, cancellationToken);
     }
     finally
     {
         // 记得清理，避免污染后续请求
         GlobalDiagnosticsContext.Remove("Any-Executed-Property");
     }
}

同时需要修改NLog配置中的布局，将${scopeproperty}替换为${gdc}：

<attribute name="Any-Executed-Property" layout="${gdc:item=Any-Executed-Property}"/>

内容的提问来源于stack exchange，提问作者Ilgiz Timrukov