深入研究日志丰富

在本文中，我们将回顾如何将日志关注点和代码与基础设施和业务代码分离和解耦。在上一篇文章中，我们回顾了如何使用 DiagnosticSource 和 DiagnosticListener 来实现基础设施操作。

现在，我们将回顾如何使用附加上下文来丰富记录的数据。

从本质上讲，丰富记录数据的概念围绕着注册应与日志消息一起使用的附加上下文或数据。该上下文可以是任何东西 - 从简单的字符串到复杂的对象，并且它是在基础设施或业务代码中的某个时刻生成或已知的，而不是在写入日志消息时生成或已知的。

因此，我们不能简单地向日志消息添加另一个属性，因为此代码不会产生任何日志输出，或者我们希望上下文附加到多个日志消息，这些日志消息可能会或可能不会在执行链中产生。

此上下文甚至可能是有条件的 - 例如仅将特定数据添加到错误日志消息，而所有其他消息不需要它。

我们将使用 Serilog 及其丰富功能，因为 Serilog 使其非常灵活和强大。其他解决方案也具有不同成熟度级别的类似功能，我们将比较 Serilog 的丰富性与 Microsoft.Extensions.Logging 提供的开箱即用功能。

Serilog 现有日志丰富器概述

Serilog 包含许多有用的丰富器，对于某些场景来说非常方便。您可以访问此页面 - https://github.com/serilog/serilog/wiki/Enrichment - 查看丰富器的完整列表及其描述。

例如，LogContext 和 GlobalLogContext 丰富器允许推送额外的数据，以便在匹配范围内写入日志消息时将其与日志消息一起记录。

LogContext丰富器与Microsoft.Extensions.Logging中的日志记录范围的概念非常相似。本质上，它们都推送一些自定义数据并提供一个 IDisposable 对象，应该处理该对象以从日志上下文中删除数据。

也就是说，只要 IDisposable 对象在范围内，数据就会附加到在该范围内写入的所有日志消息。当它被处置时，将不再附加数据。

Serilog 和 Microsoft 文档提供了以下示例：

 // For Serilog log.Information("No contextual properties"); using (LogContext.PushProperty("A", 1)) { log.Information("Carries property A = 1"); using (LogContext.PushProperty("A", 2)) using (LogContext.PushProperty("B", 1)) { log.Information("Carries A = 2 and B = 1"); } log.Information("Carries property A = 1, again"); } // For Microsoft.Extensions.Logging scopes using (logger.BeginScope(new List<KeyValuePair<string, object>> { new KeyValuePair<string, object>("TransactionId", transactionId), })) { _logger.LogInformation(MyLogEvents.GetItem, "Getting item {Id}", id); todoItem = await _context.TodoItems.FindAsync(id); if (todoItem == null) { _logger.LogWarning(MyLogEvents.GetItemNotFound, "Get({Id}) NOT FOUND", id); return NotFound(); } }

虽然对于某些场景很有用，但它们非常有限。这种类型的日志丰富的最佳用法是在中间件或装饰器类型的实现中，其中范围被明确定义，并且数据在范围创建时是已知的，并且我们确定数据在范围之外没有任何价值。范围。

例如，我们可以使用它将关联 ID 附加到单个 HTTP 请求处理范围内的所有日志消息。

GlobalLogContext丰富器类似于LogContext，但它是全局的-它将数据推送到应用程序内写入的所有日志消息。然而，这种类型的丰富的实际用例非常有限。

Serilog 的自定义日志丰富器示例

事实上，为 Serilog 实现自定义日志丰富器非常简单 - 只需实现ILogEventEnricher接口，并使用记录器配置注册丰富器即可。该接口只有一种方法可以实现 - Enrich - 它接受日志事件并使用您想要的数据来丰富它。

让我们回顾一下自定义日志丰富器的示例实现。

 public sealed class CustomLogEnricher : ILogEventEnricher { private readonly IHttpContextAccessor contextAccessor; public CustomLogEnricher(IHttpContextAccessor contextAccessor) { this.contextAccessor = contextAccessor; } public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) { var source = contextAccessor.HttpContext?.RequestServices.GetService<ICustomLogEnricherSource>(); if (source is null) { return; } var loggedProperties = source.GetCustomProperties(logEvent.Level); foreach (var item in loggedProperties) { var property = item.ProduceProperty(propertyFactory); logEvent.AddOrUpdateProperty(property); } } }

正如我们所看到的，此丰富器依赖于ICustomLogEnricherSource来获取自定义属性来丰富日志事件。通常，日志丰富器是长期存在的实例，甚至遵循单例模式 - 它们在应用程序启动时注册一次，并在整个应用程序生命周期内有效。

因此，我们需要将丰富器与自定义属性的源解耦，源可以是具有有限生命周期的作用域实例。

 public sealed class CustomLogEnricherSource : ICustomLogEnricherSource { private readonly Dictionary<string, CustomLogEventProperty> properties = new(); public ICustomLogEnricherSource With<T>(string property, T? value, LogEventLevel logLevel) where T : class { if (value is null) { return this; } properties[property] = new CustomLogEventProperty(property, value, logLevel); return this; } public void Remove(string property) { properties.Remove(property); } public IEnumerable<CustomLogEventProperty> GetCustomProperties(LogEventLevel logLevel) { foreach (var item in properties.Values) { if (item.Level <= logLevel) { yield return item; } } } } // And CustomLogEventProperty is a simple struct (you can make it a class, too): public struct CustomLogEventProperty { private LogEventProperty? propertyValue; public CustomLogEventProperty(string property, object value, LogEventLevel level) { Name = property; Value = value; Level = level; } public string Name { get; } public object Value { get; } public LogEventLevel Level { get; } public LogEventProperty ProduceProperty(ILogEventPropertyFactory propertyFactory) { propertyValue ??= propertyFactory.CreateProperty(Name, Value, destructureObjects: true); return propertyValue; } }

这个实现有一些简单的细节：

• 丰富器与日志消息的自定义属性的源分离，以考虑这些组件的不同生命周期和不同的职责。如果需要，可以通过使用ICustomLogEnricherSource实例列表来创建丰富器，因为不同的应用程序组件可能会生成不同的自定义属性。

• 源 ( ICustomLogEnricherSource ) 可以注入到任何需要使用自定义属性丰富日志消息的组件中。理想情况下，它应该是一个作用域实例，因为它不提供使自定义属性过期的便捷方法。

• 丰富器和源根据日志消息的日志级别实现简单的过滤逻辑。但是，逻辑可能要复杂得多，并且依赖于其他LogEvent属性，甚至依赖于应用程序状态。

• CustomLogEventProperty缓存生成的LogEventProperty实例，以避免为同一自定义属性多次创建它，因为它可能会附加到多个日志消息。

另一个重要的细节是这行代码中的destructureObjects参数：

 propertyFactory.CreateProperty(Name, Value, destructureObjects: true);

当我们附加复杂对象（类、记录、结构、集合等）并且此参数未设置为true时，Serilog 将在对象上调用ToString并将结果附加到日志消息中。虽然记录有一个ToString实现，它将输出所有公共属性，并且我们可以为我们的类和结构重写ToString ，但情况并非总是如此。

此外，这样的输出对于结构化日志记录来说效果不佳，因为它将是一个简单的字符串，我们将无法根据附加对象的属性搜索和过滤日志消息。所以，我们这里把这个参数设置为true 。简单类型（值类型和字符串）可以很好地处理此参数的任一值。

此实现的另一个好处是，一旦在源中注册了自定义属性，它就会保留在所有日志消息中，直到它被删除或源被释放为止（请记住，它应该是一个作用域实例）。某些实现可能需要更好地控制自定义属性的生命周期，这可以通过不同的方式实现。

例如，通过提供特定的CustomLogEventProperty实现或通过提供回调来检查是否应删除自定义属性。

此过期逻辑可在GetCustomProperties方法中使用来预先检查自定义属性，并在其过期时将其从源中删除。

这如何帮助将日志记录问题与业务和基础设施代码分离

好吧，理想情况下，我们不希望将日志记录问题与业务和基础设施代码混合在一起。这可以通过各种装饰器、中间件和其他模式来实现，这些模式允许使用特定于日志记录的代码“包装”业务和基础设施代码。

然而，这并不总是可能的，有时，将ICustomLogEnricherSource这样的中间抽象注入业务和基础设施代码中并让它注册用于日志记录的自定义数据可能会更方便。

这样，业务和基础设施代码不需要了解有关实际日志记录的任何信息，同时仍将其与一些日志记录感知代码片段混合在一起。

不管怎样，这段代码的耦合性会大大降低，并且更容易测试。我们甚至可以引入像NullLogEnricherSource这样的无操作实现，对于某些非常热的路径场景不会占用任何性能和内存。

性能考虑因素

正如微软所说，

日志记录应该非常快，以至于不值得付出异步代码的性能成本。

因此，每当我们用额外的上下文丰富日志消息时，我们都应该意识到性能影响。一般来说，Serilog 日志丰富实现速度非常快，至少与 Microsoft 日志记录范围相当，但如果我们附加更多数据，生成日志消息将花费更多时间。

我们附加的自定义属性越多，其中的对象就越复杂，生成日志消息所需的时间和内存就越多。因此，开发人员应该仔细考虑将哪些数据附加到日志消息、何时附加以及其生命周期应该是多长。

下面是一个小型基准测试结果表，显示了 Serilog 日志丰富和 Microsoft 日志记录范围的性能和内存消耗。每个基准测试方法都会生成 20 条日志消息，并通过不同的方式使用自定义属性来丰富它们。

没有附加自定义属性：

 | Method | Mean | Error | StdDev | Gen0 | Allocated | | SerilogLoggingNoEnrichment | 74.22 us | 1.194 us | 1.116 us | 1.2207 | 21.25 KB | | MicrosoftLoggingNoEnrichment | 72.58 us | 0.733 us | 0.685 us | 1.2207 | 21.25 KB |

每条日志消息都附加三个字符串：

 | Method | Mean | Error | StdDev | Gen0 | Allocated | | SerilogLoggingWithContext | 77.47 us | 0.551 us | 0.516 us | 1.7090 | 28.6 KB | | SerilogLoggingWithEnrichment | 79.89 us | 1.482 us | 2.028 us | 1.7090 | 29.75 KB | | MicrosoftLoggingWithEnrichment | 81.86 us | 1.209 us | 1.131 us | 1.8311 | 31.22 KB |

每条日志消息都附加了三个复杂的对象（记录）：

 | Method | Mean | Error | StdDev | Gen0 | Allocated | | SerilogLoggingWithObjectContext | 108.49 us | 1.193 us | 1.058 us | 5.3711 | 88.18 KB | | SerilogLoggingWithObjectEnrichment | 106.07 us | 0.489 us | 0.409 us | 5.3711 | 89.33 KB | | MicrosoftLoggingWithObjectEnrichment | 99.63 us | 1.655 us | 1.468 us | 6.1035 | 100.28 KB |The

Serilog*Context方法使用LogContext.PushProperty ， Serilog*Enrichment方法使用本文中给出的自定义丰富器和源实现，而Microsoft*方法使用日志记录范围。

我们可以看到，在大多数情况下，性能和内存消耗非常相似，并且使用复杂对象丰富比使用简单类型丰富成本更高。唯一的例外是当我们将记录附加到日志消息时使用 Microsoft 实现进行日志记录。

这是因为日志记录范围不会解构复杂对象，并且在将它们附加到日志消息时使用ToString方法进行序列化。这使得 Microsoft 的实现稍微快一些，但消耗更多的内存。

如果我们使用具有默认ToString实现的类，内存消耗会小得多，但这些自定义对象将被记录为完全限定的类型名称 - 完全无用。

无论如何，由于没有对它们进行解构，我们将无法使用 Microsoft 实现根据这些对象的属性来搜索和过滤日志消息。

因此，这是我们应该注意的 Microsoft 日志记录范围的限制 - 不会对复杂对象进行解构，而简单类型可以很好地记录并且可以搜索和过滤。

注意：本文的基准源代码和代码示例可以在GitHub 存储库中找到

结论

适当的日志丰富对于代码的开发和维护来说是一种“生活质量的提高”。它允许将附加上下文附加到日志消息创建时未知的日志消息。

该上下文可以是任何东西 - 从简单的字符串到复杂的对象，并且它在基础设施或业务代码中的某个时刻生成或已知。

它是一种将日志记录和可观察性代码与基础设施和业务代码分离的方法，并使代码更易于维护、可测试和可读。

参考

• 关于 Serilog 日志丰富 - https://github.com/serilog/serilog/wiki/Enrichment
• 关于 Microsoft 日志记录范围 - https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-8.0#log-scopes
• 本文的代码示例 - https://github.com/dmitry-slabko/log-enrichment-pub