Um mergulho mais profundo no enriquecimento de toras

Neste artigo, concluiremos a revisão de como as preocupações e o código de registro em log podem ser separados e desacoplados da infraestrutura e do código comercial. No artigo anterior , revisamos como usar DiagnosticSource e DiagnosticListener para conseguir isso em operações de infraestrutura.

Agora, revisaremos como enriquecer os dados registrados com contexto adicional.

Essencialmente, o conceito de enriquecimento de dados registrados gira em torno do registro de contexto adicional, ou dados, que devem acompanhar as mensagens de log. Esse contexto pode ser qualquer coisa, desde uma string simples até um objeto complexo, e é produzido ou conhecido em algum momento na infraestrutura ou no código de negócios, e não no momento em que as mensagens de log são gravadas.

Portanto, não podemos simplesmente adicionar outra propriedade às mensagens de log, pois esse código não produz nenhuma saída de log, ou queremos que o contexto seja anexado a várias mensagens de log que podem ou não ser produzidas na cadeia de execução.

Este contexto pode até ser condicional - como adicionar dados específicos apenas às mensagens de log de erros enquanto todas as outras mensagens não precisam deles.

Usaremos o Serilog e seu recurso de enriquecimento, pois o Serilog o tornou muito flexível e poderoso. Outras soluções também possuem recursos semelhantes em diferentes níveis de maturidade, e compararemos o enriquecimento do Serilog com o que o Microsoft.Extensions.Logging fornece imediatamente.

Uma visão geral dos enriquecedores de log existentes para Serilog

O Serilog vem com muitos enriquecedores úteis que podem ser muito úteis em alguns cenários. Você pode visitar esta página - https://github.com/serilog/serilog/wiki/Enrichment - para ver a lista completa de enriquecedores e suas descrições.

Por exemplo, existem enriquecedores LogContext e GlobalLogContext que permitem enviar dados extras para serem registrados com as mensagens de log se forem gravadas dentro de um escopo correspondente.

O enriquecedor LogContext é muito semelhante ao conceito de escopos de log em Microsoft.Extensions.Logging. Essencialmente, ambos enviam alguns dados personalizados e fornecem um objeto IDisposable que deve ser descartado para remover os dados do contexto de log.

Ou seja, enquanto o objeto IDisposable estiver no escopo, os dados serão anexados a todas as mensagens de log escritas nesse escopo. Quando for descartado, os dados não serão mais anexados.

A documentação do Serilog e da Microsoft fornece estes exemplos:

 // 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(); } }

Embora úteis para alguns cenários, eles são bastante limitados. O melhor uso para este tipo de enriquecimento de log é em implementações do tipo middleware ou decorador, onde o escopo é bem definido e os dados são conhecidos no momento da criação do escopo, e temos certeza de que os dados não têm valor fora do escopo.

Por exemplo, podemos usá-lo para anexar um ID de correlação a todas as mensagens de log em um único escopo de processamento de solicitação HTTP.

O enriquecedor GlobalLogContext é semelhante ao LogContext, mas é global - ele envia os dados para todas as mensagens de log escritas em um aplicativo. No entanto, os casos reais de utilização deste tipo de enriquecimento são muito limitados.

Amostra de Enriquecedor de Log Personalizado para Serilog

Na verdade, implementar enriquecedores de log personalizados para Serilog é muito fácil - basta implementar a interface ILogEventEnricher e registrar o enriquecedor com a configuração do logger. A interface possui apenas um método para implementar - Enrich - que aceita o evento de log e o enriquece com os dados desejados.

Vamos revisar um exemplo de implementação de um enriquecedor de log personalizado.

 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); } } }

Como podemos ver, esse enriquecedor depende de um ICustomLogEnricherSource para obter as propriedades personalizadas com as quais enriquecer o evento de log. Normalmente, os enriquecedores de log são instâncias de longa duração e até seguem o padrão Singleton - eles são registrados uma vez na inicialização do aplicativo e permanecem ativos durante todo o tempo de vida do aplicativo.

Portanto, precisamos dissociar o enriquecedor da origem das propriedades personalizadas, e a origem pode ser uma instância com escopo definido e vida útil limitada.

 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; } }

Esta implementação tem alguns detalhes simples:

• O enriquecedor é desacoplado da origem das propriedades customizadas para mensagens de log para levar em conta diferentes tempos de vida desses componentes e diferentes responsabilidades. Se necessário, o enriquecedor pode ser feito consumindo uma lista de instâncias ICustomLogEnricherSource , pois diferentes componentes do aplicativo podem produzir diferentes propriedades personalizadas.

• A origem ( ICustomLogEnricherSource ) pode ser injetada em qualquer componente que precise enriquecer mensagens de log com propriedades customizadas. Idealmente, deveria ser uma instância com escopo definido, pois não fornece uma maneira conveniente de expirar as propriedades personalizadas.

• O enriquecedor e a origem implementam uma lógica de filtragem simples com base no nível de log de uma mensagem de log. Entretanto, a lógica pode ser muito mais complexa e depender de outras propriedades LogEvent , ou mesmo do estado da aplicação.

• CustomLogEventProperty armazena em cache uma instância LogEventProperty produzida para evitar criá-la diversas vezes para a mesma propriedade customizada, pois ela pode ser anexada a diversas mensagens de log.

Outro detalhe importante está nesta linha de código, o parâmetro destructureObjects :

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

Quando anexamos objetos complexos - classes, registros, estruturas, coleções, etc. - e este parâmetro não está definido como true , o Serilog chamará ToString no objeto e anexará o resultado à mensagem de log. Embora os registros tenham uma implementação ToString que produzirá todas as propriedades públicas, e possamos substituir ToString por nossas classes e estruturas, esse nem sempre é o caso.

Além disso, essa saída não funciona bem para log estruturado, pois será uma string simples e não poderemos pesquisar e filtrar mensagens de log com base nas propriedades do objeto anexado. Portanto, definimos este parâmetro como true aqui. Os tipos simples (tipos de valor e strings) funcionarão perfeitamente com qualquer valor deste parâmetro.

Outro benefício dessa implementação é que, depois que uma propriedade customizada é registrada na origem, ela permanece lá para todas as mensagens de log até ser removida ou a origem ser descartada (lembre-se, deve ser uma instância com escopo definido). Algumas implementações podem precisar de um melhor controle sobre o tempo de vida das propriedades customizadas, e isso pode ser alcançado de diferentes maneiras.

Por exemplo, fornecendo implementações específicas CustomLogEventProperty ou fornecendo um retorno de chamada para verificar se a propriedade customizada deve ser removida.

Essa lógica de expiração pode ser usada no método GetCustomProperties para pré-verificar uma propriedade customizada e removê-la da origem se ela tiver expirado.

Como isso ajuda a dissociar as preocupações de registro do código comercial e de infraestrutura

Bem, idealmente não gostaríamos de misturar preocupações de registro com código comercial e de infraestrutura. Isso pode ser alcançado com vários decoradores, middlewares e outros padrões que permitem “envolver” o código de negócios e de infraestrutura com código específico de log.

No entanto, isso nem sempre é possível e, às vezes, pode ser mais conveniente injetar uma abstração intermediária como ICustomLogEnricherSource no código comercial e de infraestrutura e deixá-la registrar os dados personalizados para registro em log.

Dessa forma, o código de negócios e de infraestrutura não precisa saber nada sobre o registro em log real, embora ainda o misture com alguns trechos de código com reconhecimento de registro.

De qualquer forma, esse código será muito menos acoplado e muito mais testável. Podemos até introduzir algo como NullLogEnricherSource para uma implementação autônoma que não consumirá nenhum desempenho e memória para alguns cenários de caminho muito quente.

Considerações de desempenho

Como afirma a Microsoft,

O registro deve ser tão rápido que não compense o custo de desempenho do código assíncrono.

Portanto, sempre que enriquecermos nossas mensagens de log com contexto adicional, devemos estar cientes das implicações no desempenho. De modo geral, a implementação do enriquecimento de log do Serilog é muito rápida, pelo menos está no mesmo nível dos escopos de log da Microsoft, mas a produção de mensagens de log levará mais tempo se anexarmos mais dados a elas.

Quanto mais propriedades personalizadas anexarmos, mais objetos complexos estarão entre eles e mais tempo e memória serão necessários para produzir uma mensagem de log. Portanto, um desenvolvedor deve ser muito cuidadoso sobre quais dados anexar às mensagens de log, quando anexá-los e qual deve ser seu tempo de vida.

Abaixo está uma pequena tabela de resultados de benchmark mostrando o desempenho e o consumo de memória para o enriquecimento de log do Serilog e os escopos de log da Microsoft. Cada método de benchmark produziria 20 mensagens de log com diferentes maneiras de enriquecê-las com propriedades personalizadas.

Nenhuma propriedade personalizada anexada:

 | 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 |

Cada mensagem de log possui três strings anexadas:

 | 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 |

Cada mensagem de log possui três objetos complexos (registros) anexados:

 | 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

Os métodos Serilog*Context usam LogContext.PushProperty , os métodos Serilog*Enrichment usam o enriquecedor personalizado e a implementação de origem fornecidos no artigo, enquanto os métodos Microsoft* usam escopos de log.

Podemos ver que o desempenho e o consumo de memória são muito semelhantes na maioria dos casos, e o enriquecimento com objetos complexos é mais caro do que o enriquecimento com tipos simples. A única exceção é o log com implementação da Microsoft quando anexamos registros às mensagens de log.

Isso ocorre porque os escopos de log não desestruturam objetos complexos e usam o método ToString para serialização ao anexá-los a mensagens de log. Isso torna a implementação da Microsoft um pouco mais rápida, mas consome mais memória.

Se usarmos classes com a implementação padrão ToString , o consumo de memória seria muito menor, mas esses objetos personalizados seriam registrados como nomes de tipos totalmente qualificados - totalmente inúteis.

E em qualquer caso, não seríamos capazes de pesquisar e filtrar mensagens de log com base nas propriedades desses objetos com implementação da Microsoft devido à não desestruturação deles.

Portanto, esta é a limitação dos escopos de log da Microsoft que devemos estar cientes - nenhuma desestruturação de objetos complexos, enquanto tipos simples são registrados corretamente e podem ser pesquisáveis e filtráveis.

Observação: o código-fonte do benchmark e os exemplos de código deste artigo podem ser encontrados no repositório GitHub

Conclusão

O enriquecimento adequado do log é uma 'melhoria da qualidade de vida' para o desenvolvimento e manutenção do código. Ele permite anexar contexto adicional às mensagens de log que não são conhecidas no momento da criação da mensagem de log.

Esse contexto pode ser qualquer coisa - desde uma simples string até um objeto complexo, e é produzido ou conhecido em algum momento na infraestrutura ou no código de negócios.

É uma maneira de separar o código de registro e observabilidade do código de infraestrutura e de negócios e de tornar o código mais sustentável, testável e legível.

Referências

• No enriquecimento de log do Serilog - https://github.com/serilog/serilog/wiki/Enrichment
• Nos escopos de log da Microsoft - https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-8.0#log-scopes
• Exemplos de código para este artigo - https://github.com/dmitry-slabko/log-enrichment-pub