Serilog 最佳实践

翻译自：https://benfoster.io/blog/serilog-best-practices/

概述

Serilog是 Microsoft .NET 的结构化日志记录库，并已成为[Checkout.com .NET 的首选日志记录库。.它支持各种日志记录目的地（称为接收器）包从标准控制台和基于文件的接收器到日志服务，如 Datadog。

本指南最初是我们工程手册中的一篇文章，在收到内部积极反馈后，我决定在我的博客上发布它。

内容

1. 标准日志属性
2. 日志记录基础知识
   1. 记录一切
   2. 选择合适的日志记录级别
   3. 定时操作源
   4. 上下文
   5. HTTP 日志记录
   6. 日志的职责
3. 日志内容的采集
   1. Serilog标准采集方法
   2. 通过全局属性采集日志
4. 关联日志
5. 消息模板
   1. 消息模板推荐
6. 日志和诊断上下文
   1. 日志上下文
   2. 诊断上下文
7. 配置
8. 生产日志
   1. 当日志变得不仅仅是日志
9. 其他工具和实用程序
   1. 在本地使用 Seq
   2. 按日志类型记录日志
   3. 按属性块记录日志
   4. 按请求记录日志

标准日志属性

标准化日志事件属性使您能够充分利用日志搜索和分析工具。在适用的情况下使用以下属性：

上面的很多属性都来自于 Serilog 自己的扩展，例如Serilog Timings（用于计时操作）和Serilog 请求日志记录。

日志记录基础知识

记录一切

通常，记录所有可以深入了解您的应用程序和用户行为的内容，例如：

• 代码中的主要分支点
• 遇到错误或意外值时
• 任何 IO 或资源密集型操作
• 重大领域事件
• 请求失败和重试
• 耗时的批处理操作的开始和结束

选择合适的日志记录级别

对您的日志记录要慷慨，但对您的日志记录级别要严格。在几乎所有情况下，您的日志级别都应该是Debug. 使用Information的日志事件，将在生产中需要确定运行状态或应用程序的正确性，Warning或Error突发事件，如异常。

请注意，该Error级别应保留用于您打算对其采取行动的事件。如果某些事情成为正常的应用程序行为（例如，请求输入验证失败），您应该降级日志级别以减少日志“噪音”。

定时操作

将应用程序中的每个资源密集型操作（例如 IO）与指标代码一起记录下来。这在本地运行应用程序以查看应用程序瓶颈或响应时间消耗的情况时非常有用。该Serilog时序库提供了一个方便的方式来做到这一点：

using (_logger.TimeDebug("Sending notification to Slack channel {Channel} with {WebhookUrl}", _slackOptions.Channel, _slackOptions.WebhookUrl))
using (_metrics.TimeIO("http", "slack", "send_message"))
{

}

源上下文

该SourceContext属性用于跟踪日志事件的来源，通常是使用记录器的 C# 类。ILogger使用依赖注入将 Serilog 注入到类中是很常见的。为确保SourceContext正确设置，请使用ForContext扩展名：

public TheThing(ILogger logger)
{
    _logger = logger?.ForContext<TheThing>() ?? throw new ArgumentNullException(nameof(_logger));
}

HTTP 日志记录

使用Serilog 请求日志记录中间件来记录 HTTP 请求。这会自动包含上面列出的许多 HTTP 属性并生成以下日志消息：

HTTP POST /payments responded 201 in 1348.6188 ms

将以下内容添加到您的应用程序启动中以添加中间件：

public void Configure(IApplicationBuilder app)
{
    app.UseHealthAndMetricsMiddleware();
    app.UseSerilogRequestLogging();
    app.UseAuthentication();
    app.UseMvc();
}

请注意，在health 和 metrics 中间件之后添加了 Serilog中间件。这是为了避免每次 AWS 负载均衡器命中您的健康检查端点时生成日志。

记录 HTTP 资源

Serilog 中间件默认记录请求路径。如果您确实需要查看对应用程序中特定端点的所有请求，如果路径包含标识符等动态参数，您可能会遇到挑战。

为了解决这个问题，记录资源名称，在我们的应用程序中，按照惯例，它是Name赋予相应路由的属性。这是这样检索的：

public static string GetMetricsCurrentResourceName(this HttpContext httpContext)
{
    if (httpContext == null)
        throw new ArgumentNullException(nameof(httpContext));

    Endpoint endpoint = httpContext.Features.Get<IEndpointFeature>()?.Endpoint;

#if NETCOREAPP3_1
    return endpoint?.Metadata.GetMetadata<EndpointNameMetadata>()?.EndpointName;
#else
    return endpoint?.Metadata.GetMetadata<IRouteValuesAddressMetadata>()?.RouteName;
#endif
}

日志的职责

过度全面的日志记录不仅会对您的应用程序产生性能影响，而且还会使诊断问题变得更加困难，并增加暴露敏感信息的风险。

Serilog 支持结构化对象输出，允许将复杂对象作为日志中的参数传递。这应该谨慎使用，如果您的主要目标是对相关属性进行分组，您最好初始化一个新的匿名对象，这样您就可以明确哪些信息被推送到日志中。

倾向于使用 Serilog 的诊断上下文功能（下面讨论）将日志折叠为单个日志条目。

收集日志

将附加信息推送到您的日志中有助于提供有关特定事件的附加上下文。

标准 Serilog 收集器

您可以使用收集器来丰富应用程序生成的所有日志事件。我们建议使用以下 Serilog 浓缩器：

• 日志上下文收集器 – 内置于 Serilog，此丰富器可确保添加到日志上下文的任何属性都被推送到日志事件中
• 环境收集器– 使用机器或当前用户名采集日志

可以使用Enrich.WithSerilog的fluent APILoggerConfiguration或通过您的appsettings.json文件（推荐）指定增强器：

{
  "Serilog": {
    "Using": [
      "Serilog.Sinks.Console"
    ],
    "MinimumLevel": {
      "Default": "Information"
    },
    "WriteTo": [
      {
        "Name": "Console"
      }
    ],
    "Enrich": [
      "FromLogContext",
      "WithMachineName"
    ],
    "Properties": {
      "ApplicationName": "Gateway API"
    }
  }
}

全局属性采集

您还可以全局指定属性。上面的片段appsettings.json演示了我们通常如何设置ApplicationName属性。在某些情况下，我们需要在启动时计算属性，这可以使用 Fluent API 来完成：

loggerConfiguration.ReadFrom.Configuration(hostContext.Configuration)
    .EnrichWithEventType()
    .Enrich.WithProperty("Version", ReflectionUtils.GetAssemblyVersion<Program>());

关联日志

为了关联属于同一请求的日志，甚至跨多个应用程序，请CorrelationId向日志添加一个属性。

在 HTTP 应用程序中，我们通常从HttpContext.TraceIdentifier属性映射它。这是使用Cko-Correlation-Id标头在内部 API 之间传递的。我们使用以下扩展来获取 _current_correlation ID：

public static string GetCorrelationId(this HttpContext httpContext)
{
    httpContext.Request.Headers.TryGetValue("Cko-Correlation-Id", out StringValues correlationId);
    return correlationId.FirstOrDefault() ?? httpContext.TraceIdentifier;
}

请注意，如果应用程序面向公众，则不应依赖提供的相关 ID 标头。

为了确保将关联 ID 推送到每个日志事件中，我们使用以下使用 Serilog 的中间件LogContext（本文稍后将详细讨论）：

public class RequestLogContextMiddleware
{
    private readonly RequestDelegate _next;

    public RequestLogContextMiddleware(RequestDelegate next)
    {
        _next = next;
    }

    public Task Invoke(HttpContext context)
    {
        using (LogContext.PushProperty("CorrelationId", context.GetCorrelationId()))
        {
            return _next.Invoke(context);
        }
    }
}

消息模板

日志消息应提供事件的简短描述。我们通常看到开发人员创建过于冗长的消息作为在事件中包含额外数据的手段，例如：

_logger.Information("Storing payment state in Couchbase for Payment ID {PaymentId} and current state {State}", paymentId, state);

相反，您可以使用ForContext（或本文底部的属性包丰富器）仍然包含数据但具有更简洁的消息：

_logger
    .ForContext("PaymentId", paymentId)
    .ForContext("State", state)
    .Information("Storing payment state in Couchbase");

消息模板推荐

Fluent风格指南

好的 Serilog 事件使用属性名称作为消息中的内容来提高可读性并使事件更紧凑，例如：

_logger.Information("Processed {@Position} in {Elapsed:000} ms.", position, elapsedMs);

句子与片段

日志事件消息是片段，而不是句子；为了与使用 Serilog 的其他库保持一致，请尽可能避免尾随句点/句号。

模板与消息

Serilog 事件具有关联的消息模板，而不是消息。在内部，Serilog 解析和缓存每个模板（最多固定大小限制）。将日志方法的字符串参数视为消息，如下例所示，会降低性能并消耗缓存内存。例如，避免：

Log.Information("The time is " + DateTime.Now);

而是使用消息属性：

Log.Information("The time is {Now}", DateTime.Now);

除了在日志消息中使用字符串连接/插值的性能开销之外，它还意味着无法计算一致的事件类型（请参阅事件类型丰富器），从而无法找到特定类型的所有日志。

日志和诊断上下文

Serilog 支持两种可用于增强日志的上下文感知功能。

日志上下文

LogContext可用于动态地添加和移除来自周围“执行上下文”性能; 例如，在事务期间写入的所有消息都可能带有该事务的 id，等等。

在RequestLogContextMiddleware上面的介绍演示了如何推动CorrelationId请求到LogContext在请求的开始。这可确保该请求中的所有日志都包含该属性。

更多信息可以在Serilog wiki上找到。

诊断上下文

日志记录的一个挑战是上下文并不总是预先知道。例如，在处理 HTTP 请求的过程中，随着我们通过 HTTP 管道（例如了解用户的身份）获得额外的上下文。虽然LogContext我们所有人都会在附加信息可用时创建新上下文，但此信息仅在 _subsequent_log 条目中可用。这通常会导致日志数量增加，只是为了捕获有关整个请求或操作的所有信息。

诊断上下文提供了一个执行上下文（类似于LogContext），其优点是可以在其整个生命周期中进行丰富。请求日志中间件然后使用它来丰富最终的“日志完成事件”。这允许我们将许多不同的日志操作折叠为一个日志条目，其中包含来自请求管道中许多点的信息，例如：

在这里您可以看到，不仅有中间件发出的 HTTP 属性，还有应用程序数据，例如AcquirerId、MerchantName和ResponseCode。这些数据点来自请求中的不同点，但通过IDiagnosticContext接口推送到诊断上下文中：

public class HomeController : Controller
{
    readonly IDiagnosticContext _diagnosticContext;

    public HomeController(IDiagnosticContext diagnosticContext)
    {
        _diagnosticContext = diagnosticContext ?? throw new ArgumentNullException(nameof(diagnosticContext));
    }

    public IActionResult Index()
    {
        // The request completion event will carry this property
        _diagnosticContext.Set("CatalogLoadTime", 1423);

        return View();
    }

在非 HTTP 应用程序中使用诊断上下文

诊断上下文不限于在 ASP.NET Core 中使用。它也可以以与请求日志中间件非常相似的方式在非 HTTP 应用程序中使用。例如，我们使用它在 SQS 使用者中生成完成日志事件。

配置

Serilog 可以使用 Fluent API 或通过 Microsoft 配置系统进行配置。我们建议使用配置系统，因为可以在不发布应用程序新版本的情况下更改日志配置。

为此，添加Serilog.Settings.Configuration包并按如下方式配置 Serilog：

public static IHostBuilder CreateHostBuilder(string[] args) =>
    Host.CreateDefaultBuilder(args)
        .UseSerilog((hostContext, loggerConfiguration) =>
        {
            loggerConfiguration.ReadFrom.Configuration(hostContext.Configuration);
        })
        .ConfigureAppConfiguration((hostingContext, config) =>
        {
            config
                .AddEnvironmentVariables(prefix: "FLOW_")
                .AddAwsSecrets();
        })
        .ConfigureWebHostDefaults(webBuilder =>
        {
            webBuilder.UseStartup<Startup>();  
        });

您现在可以通过任何支持的配置提供程序配置 Serilog。通常我们appsettings.json用于全局设置并通过生产中的环境变量配置实际接收器（因为我们不想在本地运行时使用我们的远程日志服务）：

{
  "Serilog": {
    "Using": [
      "Serilog.Sinks.Console",
      "Serilog.Sinks.Datadog.Logs"
    ],
    "MinimumLevel": {
      "Default": "Information"
    },
    "WriteTo": [
      {
        "Name": "Console"
      }
    ],
    "Enrich": [
      "FromLogContext",
      "WithMachineName"
    ],
    "Properties": {
      "ApplicationName": "Flow API"
    }
  }
}

生产环境下使用日志

在生产中部署应用程序时，请确保相应地配置日志记录：

• 控制台日志记录应限于Error. 在 .NET 中，写入控制台是一个阻塞调用，会对性能产生重大影响。
• 应为Information及以上配置全局日志记录。

据了解，在新项目发布期间，您可能需要更多信息来建立对解决方案的信心或诊断任何预期的初期问题。与其Information为此升级您的日志条目，不如考虑Debug在有限的时间内启用级别。

从开发人员那里听到的一个常见问题是他们如何在运行时动态切换日志级别。虽然这是可能的，但也可以使用蓝/绿部署来实现。使用降低的日志级别配置和部署非活动环境，然后通过加权目标组切换部分或全部流量。

当日志变得不仅仅是日志

日志可以提供对应用程序的大量洞察，并且在许多情况下足以处理日常支持请求或故障排除。然而，在某些情况下，日志不是工作的正确工具，有许多警告信号：

• 您发现自己向非技术用户开放应用程序日志
• 日志用于生成应用程序指标
• 更多信息被“塞进”日志以满足常见的支持请求或报告要求

在这些情况下，您可能需要为您的产品考虑专用工具。许多团队开发了类似“Inspector”的应用程序，将关键系统和业务数据聚合在一起，以处理可以提供给非技术利益相关者的 BAU 请求。此外，您可能会发现需要将应用程序中的数据推送到报告和分析工具中。

日志的有效性取决于您记录的内容和未记录的内容。

其他工具和实用程序

在本地使用 Seq

Seq是由 Serilog 的作者创建的免费（供本地使用）日志记录工具。它提供高级搜索和过滤功能以及对结构化日志数据的完全访问。虽然我们的日志记录要求现在超出了 Seq 所能提供的范围，但它仍然是本地测试的一个很好的选择。

我们通常在 docker 中启动 Seq 作为单独的 docker-compose 文件 ( docker-compose-logging.hml) 的一部分：

version: "3.5"

services:

seq:
    image: datalust/seq:latest
    container_name: seq
    ports:
    - '5341:80'
    environment:
    - ACCEPT_EULA=Y
    networks:
    - gateway-network

networks:
gateway-network:
    name: gateway-network

并配置我们的appsettings.Development.json文件以使用 Seq 接收器：

{
  "Serilog": {
    "Using": [
      "Serilog.Sinks.Console",
      "Serilog.Sinks.Seq"
    ],
    "MinimumLevel": {
      "Default": "Debug",
      "Override": {
        "Microsoft": "Warning"
      }
    },
    "WriteTo": [
      {
        "Name": "Console"
      },
      {
        "Name": "Seq",
        "Args": {
          "serverUrl": "http://localhost:5341",
          "apiKey": "none"
        }
      }
    ]
  }
}

事件类型收集器

通常我们需要唯一标识相同类型的日志。一些接收器（例如Seq）通过散列消息模板来自动执行此操作。为了在其他接收器中复制相同的行为，我们创建了以下使用Murmerhash 算法的收集器：

internal class EventTypeEnricher : ILogEventEnricher
{
    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        if (logEvent is null)
            throw new ArgumentNullException(nameof(logEvent));

        if (propertyFactory is null)
            throw new ArgumentNullException(nameof(propertyFactory));

        Murmur32 murmur = MurmurHash.Create32();
        byte[] bytes = Encoding.UTF8.GetBytes(logEvent.MessageTemplate.Text);
        byte[] hash = murmur.ComputeHash(bytes);
        string hexadecimalHash = BitConverter.ToString(hash).Replace("-", "");
        LogEventProperty eventId = propertyFactory.CreateProperty("EventType", hexadecimalHash);
        logEvent.AddPropertyIfAbsent(eventId);
    }
}

属性包收集器

如果您想向日志事件添加多个属性，请使用PropertyBagEnricher：

public class PropertyBagEnricher : ILogEventEnricher
{
    private readonly Dictionary<string, Tuple<object, bool>> _properties;

    /// <summary>
    /// Creates a new <see cref="PropertyBagEnricher" /> instance.
    /// </summary>
    public PropertyBagEnricher()
    {
        _properties = new Dictionary<string, Tuple<object, bool>>(StringComparer.OrdinalIgnoreCase);
    }

    /// <summary>
    /// Enriches the <paramref name="logEvent" /> using the values from the property bag.
    /// </summary>
    /// <param name="logEvent">The log event to enrich.</param>
    /// <param name="propertyFactory">The factory used to create the property.</param>
    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        foreach (KeyValuePair<string, Tuple<object, bool>> prop in _properties)
        {
            logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(prop.Key, prop.Value.Item1, prop.Value.Item2));
        }
    }

    /// <summary>
    /// Add a property that will be added to all log events enriched by this enricher.
    /// </summary>
    /// <param name="key">The property key.</param>
    /// <param name="value">The property value.</param>
    /// <param name="destructureObject">
    /// Whether to destructure the value. See https://github.com/serilog/serilog/wiki/Structured-Data
    /// </param>
    /// <returns>The enricher instance, for chaining Add operations together.</returns>
    public PropertyBagEnricher Add(string key, object value, bool destructureObject = false)
    {
        if (string.IsNullOrEmpty(key)) throw new ArgumentNullException(nameof(key));

        if (!_properties.ContainsKey(key)) _properties.Add(key, Tuple.Create(value, destructureObject));

        return this;
    }
}

用法：

_logger
    .ForContext(
      new PropertyBagEnricher()
        .Add("ResponseCode", response?.ResponseCode)
        .Add("EnrollmentStatus", response?.Enrolled)
    )
    .Warning("Malfunction when processing 3DS enrollment verification");

收集请求日志

Serilog 请求日志记录中间件允许提供一个函数，该函数可用于将来自 HTTP 请求的附加信息添加到完成日志事件。我们使用它来记录ClientIP,UserAgent和Resource属性：

public static class LogEnricher
{
    /// <summary>
    /// Enriches the HTTP request log with additional data via the Diagnostic Context
    /// </summary>
    /// <param name="diagnosticContext">The Serilog diagnostic context</param>
    /// <param name="httpContext">The current HTTP Context</param>
    public static void EnrichFromRequest(IDiagnosticContext diagnosticContext, HttpContext httpContext)
    {
        diagnosticContext.Set("ClientIP", httpContext.Connection.RemoteIpAddress.ToString());
        diagnosticContext.Set("UserAgent", httpContext.Request.Headers["User-Agent"].FirstOrDefault());
        diagnosticContext.Set("Resource", httpContext.GetMetricsCurrentResourceName());
    }
}

用法

app.UseSerilogRequestLogging(opts
  => opts.EnrichDiagnosticContext = LogEnricher.EnrichFromRequest);

© 2021 Ben Foster https://benfoster.io/