如何在 ASP.NET Core 中间件异常展开期间丰富 Serilog 日志条目？

Question

我想使用 Serilog 记录带有任何未处理异常的 HTTP 请求的详细信息（例如完整的请求路径、所有 HTTP 标头、任何表单字段等）。因此，我按照本教程将当前 HttpContext.Request 中的信息添加到已记录的 Serilog 日志中：https://blog.getseq.net/smart-logging-middleware-for-asp-net-core/

这是我的SerilogMiddleware 版本；

/// <summary>This class logs Request Headers of any failed request.</summary>
public class SerilogMiddleware
{
    private static readonly ILogger _log = global::Serilog.Log.ForContext<SerilogMiddleware>();

    private readonly RequestDelegate next;

    public SerilogMiddleware( RequestDelegate next )
    {
        this.next = next ?? throw new ArgumentNullException( nameof( next ) );
    }

    public async Task Invoke( HttpContext httpContext )
    {
        if( httpContext == null ) throw new ArgumentNullException( nameof( httpContext ) );

        try
        {
            await this.next( httpContext );

            // TODO: Log certian HTTP 4xx responses?

            if( httpContext.Response?.StatusCode >= 500 )
            {
                GetLogForErrorContext( httpContext ).Warning( _MessageTemplateForHttp500 );
            }
        }
        catch( Exception ex ) when( LogException( httpContext, ex ) )
        {
            // LogException returns false, so this catch block will never be entered.
        }
    }

    const String _MessageTemplateForException = "Unhandled exception in {RequestResource}";
    const String _MessageTemplateForHttp500   = "Handled HTTP 500 in {RequestResource}";

    private static Boolean LogException( HttpContext httpContext, Exception ex )
    {
        GetLogForErrorContext( httpContext ).Error( ex, _MessageTemplateForException );

        return false; // return false so the exception is not caught and continues to propagate upwards. (I understand this is cheaper than `throw;` inside catch).
    }

    private static ILogger GetLogForErrorContext( HttpContext httpContext )
    {
        HttpRequest req = httpContext.Request;

        String resource = "{0} {1}{2} {3}".FormatInvariant( req.Method, req.Path, req.QueryString.ToString(), req.Protocol );

        // re: `ForContext`: https://nblumhardt.com/2016/08/context-and-correlation-structured-logging-concepts-in-net-5/

        ILogger result = _log
            .ForContext( "RequestHeaders" , req.Headers.ToDictionary( h => h.Key, h => h.Value.ToString() /* Returns all values, comma-separated */ ), destructureObjects: true )
            .ForContext( "RequestResource", resource )
            .ForContext( "ResponseStatus", httpContext.Response?.StatusCode )
        ;

        if( req.HasFormContentType )
            result = result.ForContext( "RequestForm", req.Form.ToDictionary( v => v.Key, v => v.Value.ToString() ) );

        return result;
    }
}

不过，我的IWebHostBuilder 代码中也有 Serilog：

IWebHostBuilder webHostBuilder = WebHost
    .CreateDefaultBuilder( args )
    .ConfigureLogging( (ctx, cfg ) =>
    {
        cfg.ClearProviders();
        cfg.AddSerilog(); // it's unclear if this is required or not
    } )
    .UseStartup<Startup>()
    .UseSerilog();

webHostBuilder.Build().Run();

简而言之：

• 这是一个 ASP.NET Core 中间件类，它将 await next( context ) 包装在 try/catch 中，使用 Log.ForContext( ... ) 获取 ILogger 以向记录器添加新属性（例如请求路径、响应代码等）。
• 因为此代码实际上调用了ILogger.Error，所以会立即记录事件。
• 但是try/catch 让异常继续向上传播调用堆栈（通过使用catch( Exception ex ) when ( LogExceptionThenReturnFalse( httpContext, ex ) )。
• ...这意味着 Serilog 使用默认扩充再次记录异常和 HTTP 请求。

我希望 Serilog 只记录一次异常，并增加了丰富内容。快速修复是完全捕获我的SerilogMiddleware 中的异常以防止进一步传播，但这意味着它不会命中我的IWebHostBuilder 中配置的Serilog ILogger。如果我让异常传播并且不将其记录在我的中间件中，那么我将无法记录来自 HttpContext 的数据。

如何将信息“附加”到当前的 Serilog“上下文”，以便当异常最终被 IWebHostBuilder Serilog 记录器捕获并记录时，它包含额外的 HttpContext 数据？

Answer 1

到目前为止我找到的最佳解决方案，显然是一个 hack， 从这里偷来的想法 - https://blog.datalust.co/smart-logging-middleware-for-asp-net-core/

添加一个中间件类来捕获异常并手动添加。

// Idea from https://blog.datalust.co/smart-logging-middleware-for-asp-net-core/
public class LogDetailsMiddleware
{
    private readonly RequestDelegate _next;
    private readonly IHttpContextAccessor _httpContextAccessor;
    private readonly IUserManager _userManager;

    private readonly ILogger _logger = Serilog.Log.ForContext<LogDetailsMiddleware>();

    public LogDetailsMiddleware(RequestDelegate next, IHttpContextAccessor httpContextAccessor, IUserManager userManager)
    {
        if (next == null)
        {
            throw new ArgumentNullException(nameof(next));
        }

        _next = next;
        _httpContextAccessor = httpContextAccessor;
        _userManager = userManager;
    }

    public async Task Invoke(HttpContext httpContext)
    {
        if (httpContext == null)
        {
            throw new ArgumentNullException(nameof(httpContext));
        }

        LogContext.PushProperty("Email", _userManager.CurrentUser.Email);
        LogContext.PushProperty("Url", _httpContextAccessor.HttpContext.Request.GetDisplayUrl());

        Stopwatch sw = Stopwatch.StartNew();
        try
        {
        await _next(httpContext);
            sw.Stop();
        }
        // Never caught, because `LogException()` returns false.
        catch (Exception ex) when (LogException( sw, ex)) { }
    }

    bool LogException(Stopwatch sw, Exception ex)
    {
        sw.Stop();
        
        _logger.Error(ex, "An unhandled exception has occurred while executing the request.");

        return false;
    }
}

Answer 2

我们正在使用HttpClientFactory 记录我们的请求

services.AddHttpClient("clientWithLogger")
    .AddHttpMessageHandler<HttpClientLoggingHandler>();

还有我们的HttpClientLoggingHandler

public class HttpClientLoggingHandler : DelegatingHandler
{
    private readonly ILogger<HttpClientLoggingHandler> _logger;

    public HttpClientLoggingHandler(ILogger<HttpClientLoggingHandler> logger)
    {
        _logger = logger;
    }

    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
        CancellationToken cancellationToken)
    {
        var sw = Stopwatch.StartNew();
        _logger.LogInformation("Starting request to '{requestUri}'", request.RequestUri);
        var response = await base.SendAsync(request, cancellationToken);
        sw.Stop();
        _logger.LogInformation("Finished request to '{requestUri}' in {elapsedMilliseconds}ms, response: {response}",
            request.RequestUri, sw.ElapsedMilliseconds, await response.Content.ReadAsStringAsync());
        return response;
    }
}

那么我们就可以简单的使用HttpClientFactory了

public class DeviceDetector
{
    private readonly IHttpClientFactory _httpClientFactory;
    private const string LicenceKey = "XXX";
    private const string Domain = "https://xxx/api/v1/";

    public DeviceDetector(IHttpClientFactory httpClientFactory)
    {
        _httpClientFactory = httpClientFactory;
    }

    public async Task<Device> DetectDevice(string userAgent)
    {
        var url = $"{Domain}{LicenceKey}";
        var result = await _httpClientFactory.CreateClient("clientWithLogger").GetStringAsync(url);
        return Newtonsoft.Json.JsonConvert.DeserializeObject<Device>(result);
    }
}

这样我们就可以使用普通的 ILogger，它是幕后的 Serilog，并且可以完全控制记录的内容和时间。

编辑

如果您只想记录错误，那么可以轻松添加逻辑

public class HttpClientLoggingHandler : DelegatingHandler
{
    private readonly ILogger<HttpClientLoggingHandler> _logger;

    public HttpClientLoggingHandler(ILogger<HttpClientLoggingHandler> logger)
    {
        _logger = logger;
    }

    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
        CancellationToken cancellationToken)
    {
        // Log error requests
        try
        {
            var response = await base.SendAsync(request, cancellationToken);

            if(response.IsSuccessStatusCode)
            {
                // Success status code
            }
            else if( (int)response.StatusCode >= 500 )
            {
                // error 500
            }
        }
        catch( Exception ex ) when( LogException( httpContext, ex ) )
        {
            // LogException returns false, so this catch block will never be entered.
        }
    }
}