Boas práticas de logging com Serilog no .NET

As práticas que mais importam com o Serilog são pequenas e estruturais: configurá-lo a partir do appsettings.json em vez de no código, registrar modelos de mensagem em vez de strings interpoladas, injetar ILogger<T> em vez de recorrer à classe estática Log e enriquecer os logs uma única vez, na inicialização, em vez de em cada ponto de chamada.

Cada uma delas é uma decisão que influencia o quanto os logs serão úteis depois. Se errarmos, continuamos tendo logs. Só que são logs mais difíceis de pesquisar.

O que é o Serilog?

O Serilog é uma biblioteca de logging estruturado para .NET. Enquanto um logger tradicional grava uma string formatada, o Serilog grava um modelo de mensagem mais os valores que o preenchem, e mantém esses valores como propriedades nomeadas no evento de log.

Essa distinção resume a biblioteca inteira. Uma linha de log que chega como "Order 4417 shipped to Berlin" só pode ser pesquisada com grep. A mesma linha registrada como "Order {OrderId} shipped to {City}", com duas propriedades anexadas, pode ser filtrada, agrupada e contada por qualquer uma delas.

Os sinks decidem para onde vão os eventos: console, arquivo, Seq, Elasticsearch e muitos outros. Cada um é um pacote separado, que escolhemos adicionar.

Os enriquecedores adicionam propriedades a todos os eventos automaticamente, de modo que o nome da máquina ou o ID da thread aparece em todos eles sem mexer em um único ponto de chamada.

O Serilog se conecta à interface ILogger<T> que o restante do .NET já usa, então adotá-lo não significa reescrever os pontos de chamada.

O README do próprio Serilog apresenta isso como o propósito da biblioteca: “O suporte do Serilog ao logging estruturado se destaca na instrumentação de aplicações e sistemas complexos, distribuídos e assíncronos.”

Evite a classe de logger estática

O Serilog vem com a classe estática Log, que podemos usar em toda a aplicação para registrar eventos e informações. Podemos usá-la para acessar a propriedade Logger e gravar qualquer tipo de log que quisermos. Mas, ao fazer isso, quebramos o princípio da inversão de dependência.

Podemos integrar facilmente o Serilog à interface de logging nativa da Microsoft, e essa é uma das práticas mais úteis a seguir. Com essa abordagem, não só respeitamos o princípio da inversão de dependência como também tornamos muito mais fácil testar a aplicação.

Esse último ponto não é teórico. É uma interface injetada que torna simples escrever testes unitários para código que registra logs sem um logger real por trás.

No entanto, um dos casos de uso da classe estática Log é na classe Program, depois que adicionamos o pacote Serilog.AspNetCore (dotnet add package Serilog.AspNetCore), que traz o Serilog junto com os sinks de console e de arquivo:

using Serilog;

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Information()
    .WriteTo.File(
        "logs/log.txt",
        retainedFileCountLimit: 7,
        rollingInterval: RollingInterval.Day)
    .CreateLogger();

try
{
    var builder = WebApplication.CreateBuilder(args);

    // code omitted for brevity

    app.Run();
}
catch (Exception ex)
{
    Log.Error(ex, "The exception was thrown during application startup");
}
finally
{
    Log.CloseAndFlush();
}

Usamos a propriedade Logger da classe estática Log para configurar o logger de modo que ele grave os logs em um arquivo. Em seguida, envolvemos a configuração da aplicação em um bloco try–catch; assim, registramos todos os erros que acontecerem durante a inicialização da aplicação. O bloco finally apenas se encarrega de fechar o logger e gravar os logs restantes.

A chamada MinimumLevel fica acima dos sinks apenas por legibilidade, para que a configuração se leia assim: primeiro os níveis, depois os destinos. Os dois são consumidos dentro de CreateLogger(), então a ordem da cadeia não muda o que o logger faz.

Também podemos usar a classe estática Log em qualquer outro lugar em que a injeção de dependência não seja possível.

Configure o Serilog pelo appsettings.json

Antes de tudo, precisamos configurar o Serilog de acordo com as nossas necessidades. Temos duas opções: a API fluente ou o sistema de configuração. Embora a API fluente seja muito intuitiva e fácil de ler, ela tem uma grande desvantagem: toda vez que mudamos algo na configuração, precisamos publicar uma nova compilação da aplicação.

Por isso, é melhor usar o sistema de configuração para preparar o Serilog nas nossas aplicações:

Install-Package Serilog.Settings.Configuration

Essa é a forma do Package Manager Console. Fora do Visual Studio, a CLI do .NET faz o mesmo trabalho:

dotnet add package Serilog.Settings.Configuration

Agora que temos o pacote, vamos adicionar a configuração básica:

"Serilog": {
  "Using": [
    "Serilog.Sinks.Console"
  ],
  "MinimumLevel": {
    "Default": "Information"
  },
  "WriteTo": [
    {
      "Name": "Console",
      "Args": {
        "OutputTemplate": "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj}{NewLine}"
      }
    }
  ],
  "Properties": {
    "ApplicationName": "Weather API"
  }
}

Primeiro, no arquivo appsettings.json, adicionamos uma nova seção chamada Serilog. Dentro dela, começamos criando a subseção Using, na qual indicamos o sink que queremos usar.

Em seguida, definimos o nível mínimo padrão. Em um guia à parte, explicamos o conjunto completo de níveis de log do Serilog e como definir um mínimo. Depois, passamos para a subseção WriteTo, em que configuramos os diferentes sinks, o que pode incluir até coisas como o modelo de saída.

Nesse modelo, {Level:u3} é a forma convencional. O número é uma largura máxima, e não uma largura de campo, então um valor maior, como u11, não completa nada com espaços: ele simplesmente imprime cada nível por extenso, gerando INFORMATION e WARNING, enquanto u3 gera INF e WRN, alinhados.

Depois, precisamos aplicar a configuração:

builder.Services.AddSerilog((services, config) =>
    config.ReadFrom.Configuration(builder.Configuration));

Na classe Program, usamos o método de extensão AddSerilog() para indicar que a aplicação deve usar o arquivo appsettings.json para configurar o Serilog. Com isso, não precisamos mais republicar a aplicação quando a configuração de logging muda.

AddSerilog() é o que o Serilog.AspNetCore documenta hoje. O antigo builder.Host.UseSerilog() ainda funciona, mas não é uma simples troca de nome: UseSerilog() passa à lambda um HostBuilderContext, enquanto AddSerilog() passa um IServiceProvider, então a configuração vem de builder.Configuration em vez de context.Configuration.

Esqueça os sinks de console e de arquivo do Serilog em produção

Quando desenvolvemos uma aplicação, é ótimo ver os eventos de log à medida que acontecem. Registrar os logs no console é uma ótima forma de conseguir isso. No entanto, registrar tudo no console pode tornar muito difícil encontrar eventos, porque ele rapidamente fica abarrotado de informação. Além disso, queremos evitar isso no ambiente de produção, pois pode causar problemas de desempenho.

Em desenvolvimento, o sink de arquivo do Serilog é mais útil que o de console porque a saída sobrevive à execução. Podemos filtrar e ordenar os logs, o que facilita encontrar um evento específico. No entanto, assim como no logging em console, isso se torna muito trabalhoso de gerenciar em produção.

Para produção, podemos usar o Seq, o Elasticsearch ou qualquer outro sink do Serilog mais adequado a ambientes de produção. Assim, ganhamos mais escalabilidade e confiabilidade em comparação com os logs em arquivo ou no console.

Outra opção é enviar os logs como dados do OpenTelemetry, o que os leva a qualquer back-end que fale o protocolo OTLP, e não para o sink de um único fornecedor.

Vale mencionar que, dependendo da situação, pode haver casos em que o logging em arquivo e no console tenha sua utilidade em produção. Por exemplo, o nosso provedor de logs pode ter problemas para receber os logs, e aí ter logs em arquivo ou no console pode ser útil.

Duas práticas de produção ficam fora da escolha do sink. A primeira é onde a gravação acontece. Um sink que bloqueia quem o chama, principalmente o sink de arquivo, pode ser envolvido em WriteTo.Async() para que a gravação aconteça em uma thread de trabalho em segundo plano, e não na thread que registrou o log.

Isso não é uma solução universal. O README do Serilog.Sinks.Async diz que os sinks de rede recomendados acima, entre eles Seq e Elasticsearch, já agrupam os eventos em lotes por conta própria e não ganham nada ao serem envolvidos, o mesmo ponto que este artigo defende mais adiante sobre os sinks que trabalham em lotes.

A segunda prática diz respeito ao que vai nas propriedades. Uma propriedade é armazenada e indexada, em vez de ficar enterrada em uma linha de texto, então dados pessoais em um modelo de mensagem são muito mais fáceis de recuperar depois do que o mesmo valor dentro de uma string formatada. Mantenha esses dados fora do modelo.

Sempre use logging estruturado

Sempre que possível, devemos evitar strings simples ao registrar logs. No nosso endpoint /weatherforecast, depois de adicionar um parâmetro ILogger<Program> logger à lambda dele, registrar a primeira previsão antes de retorná-la poderia ficar assim:

logger.LogInformation(
    $"The weather today will be {forecast[0].Summary} and {forecast[0].TemperatureC} degrees.");

Isso produz uma mensagem de log simples, que pode não ser muito útil. Além disso, o primeiro parâmetro do método LogInformation() de ILogger<T> se chama message, mas é um modelo de mensagem, não uma mensagem.

Vamos usá-lo corretamente:

logger.LogInformation(
    "The weather today will be {Summary} and {Temperature} degrees.",
    forecast[0].Summary,
    forecast[0].TemperatureC);

Aqui, primeiro passamos o modelo de mensagem e depois os dois parâmetros que ele exige. Isso produz um log estruturado, em que tanto Summary quanto Temperature são armazenados como propriedades associadas à mensagem de log. Isso torna muito mais fácil consultar os logs, o que economiza tempo e esforço.

A sintaxe dos espaços reservados tem regras próprias, e explicamos os modelos de mensagem com mais profundidade em outro artigo.

Use enriquecedores de eventos de log

Um enriquecedor anexa uma propriedade a todos os eventos de log. Ele é configurado uma vez, na inicialização, em vez de ser passado em cada ponto de chamada.

O Serilog traz um núcleo pequeno e coloca a maioria dos enriquecedores em pacotes separados, e é aí que começa a confusão: o valor Enrich na configuração e o pacote que o fornece têm nomes diferentes.

WithMachineName e WithEnvironmentName vêm ambos de Serilog.Enrichers.Environment. WithThreadId vem de Serilog.Enrichers.Thread, e WithProcessId, de Serilog.Enrichers.Process. Citar um enriquecedor sem instalar o pacote dele é uma operação nula e silenciosa: a propriedade simplesmente nunca aparece.

FromLogContext é a exceção que vale conhecer. Ele não precisa de nenhum pacote extra, e é ele que nos permite adicionar uma propriedade, como um ID de correlação, a todos os eventos gerados dentro de um bloco de código.

Os enriquecedores também são baratos de um jeito que as propriedades passadas no ponto de chamada não são. Configurados uma vez na inicialização, eles não acrescentam código a nenhuma instrução de log, e quem escrever a próxima instrução não tem como esquecê-los.

A tabela abaixo associa cada enriquecedor ao pacote que o fornece.

Uma observação sobre essa operação nula e silenciosa: o Serilog escreve, sim, uma mensagem sobre isso no Serilog.Debugging.SelfLog, que fica desativado a menos que o ativemos.

Começamos instalando os pacotes de enriquecimento Thread, Process e Environment do Serilog:

Install-Package Serilog.Enrichers.Thread
Install-Package Serilog.Enrichers.Process
Install-Package Serilog.Enrichers.Environment

Os mesmos três pacotes com a CLI do .NET:

dotnet add package Serilog.Enrichers.Thread
dotnet add package Serilog.Enrichers.Process
dotnet add package Serilog.Enrichers.Environment

Em seguida, atualizamos a configuração:

"Enrich": [
  "WithThreadId",
  "WithProcessId",
  "WithMachineName",
  "WithEnvironmentName"
]

No arquivo appsettings.json, adicionamos uma nova subseção chamada Enrich. Dentro dela, adicionamos entradas indicando que o Serilog deve enriquecer os logs com ThreadId, ProcessId, MachineName e também EnvironmentName.

O modelo de saída que usamos no console não imprime essas propriedades, então também enviamos os logs para uma instância do Seq na nossa máquina. Instalamos o pacote Serilog.Sinks.Seq (dotnet add package Serilog.Sinks.Seq) e adicionamos um segundo sink à subseção WriteTo, depois do sink de console:

{
  "Name": "Seq",
  "Args": {
    "serverUrl": "http://localhost:5341"
  }
}

Agora podemos enviar uma requisição à API e examinar a saída no Seq:

Vemos que o log inclui todas as propriedades adicionais que especificamos na subseção Enrich do arquivo appsettings.json.

Crie um enriquecedor de eventos de log personalizado para o Serilog

Não é surpresa que possamos criar enriquecedores de eventos de log personalizados:

using Serilog.Core;
using Serilog.Events;

public class ThreadPriorityEnricher : ILogEventEnricher
{
    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        logEvent.AddPropertyIfAbsent(
            propertyFactory.CreateProperty(
                "ThreadPriority",
                Thread.CurrentThread.Priority.ToString()));
    }
}

Começamos criando a classe ThreadPriorityEnricher e implementando a interface ILogEventEnricher. A interface nos obriga a implementar o método Enrich(). Com o método AddPropertyIfAbsent() da classe LogEvent, tentamos adicionar uma nova propriedade aos logs, caso ela ainda não exista. Nossa propriedade adicional vai incluir a prioridade da thread nos eventos de log. Para obter a prioridade em si, usamos a classe Thread e suas propriedades. Quem cria a propriedade é o método CreateProperty() da interface ILogEventPropertyFactory.

Em seguida, registramos o enriquecedor:

builder.Services.AddSerilog((services, config) =>
    config.ReadFrom.Configuration(builder.Configuration)
        .Enrich.With(new ThreadPriorityEnricher()));

Na classe Program, usamos o método With() na propriedade Enrich da classe LoggerConfiguration. Passamos ao método uma nova instância da nossa classe ThreadPriorityEnricher.

Com isso, todos os logs da aplicação terão ThreadPriority como propriedade.

Uma ideia parecida está por trás do registro automático dos nomes de classe e de método, o que evita escrevê-los à mão em cada mensagem.

Logging de requisições com o Serilog

As requisições são uma parte vital de qualquer aplicação, então um logging detalhado é obrigatório:

app.UseSerilogRequestLogging();

Na classe Program, chamamos o método de extensão UseSerilogRequestLogging() na instância de WebApplication. Com isso, os logs de requisição passam a ter informações sobre o método HTTP, o caminho, o código de status e quanto tempo a aplicação levou para responder.

Podemos ir além e criar um enriquecedor personalizado para os logs de requisição:

using Serilog;

public static class RequestEnricher
{
    public static void LogAdditionalInfo(
        IDiagnosticContext diagnosticContext,
        HttpContext httpContext)
    {
        diagnosticContext.Set(
            "ClientIP",
            httpContext.Connection.RemoteIpAddress?.ToString());
    }
}

Começamos criando uma nova classe RequestEnricher.

Em seguida, criamos o método LogAdditionalInfo(). Ele recebe dois parâmetros: instâncias de IDiagnosticContext (do Serilog) e de HttpContext (do ASP.NET Core). Depois, usamos o método Set() do contexto de diagnóstico para criar a propriedade ClientIP e atribuir a ela a propriedade Connection.RemoteIpAddress do HttpContext passado ao método.

Observe que isso é diferente de implementar a interface ILogEventEnricher e precisa ser registrado de outra forma.

Em seguida, adicionamos o enriquecedor personalizado:

app.UseSerilogRequestLogging(options
  => options.EnrichDiagnosticContext = RequestEnricher.LogAdditionalInfo);

Para isso, definimos a propriedade EnrichDiagnosticContext, dentro do método UseSerilogRequestLogging(), como o método LogAdditionalInfo() que acabamos de escrever.

Por fim, podemos enviar uma requisição e verificar o log:

Vemos que o log agora tem informações sobre o método HTTP, o caminho e o código de status. Também recebemos uma propriedade chamada ClientIP com o valor ::1, o que significa que enviamos a requisição da mesma máquina em que a aplicação está rodando.

Como configurar o Serilog no ASP.NET Core?

A configuração acontece em dois lugares, e essa divisão é proposital. O host conecta o Serilog à injeção de dependência, enquanto o appsettings.json decide o que ele de fato faz.

A conexão fica na classe Program e lê a seção de configuração, então sinks, níveis mínimos e enriquecedores mudam sem recompilar.

Um logger inicial (bootstrap logger) é a peça que a maioria das configurações esquece. O Serilog só fica configurado depois que o host é construído, então qualquer coisa que falhe antes disso não é registrada em lugar nenhum. Criar primeiro um logger mínimo e substituí-lo quando a configuração for carregada fecha essa janela.

Log.CloseAndFlush() vai em um bloco finally pelo mesmo motivo. Os sinks que trabalham em lotes (Seq, Elasticsearch, muitos sinks de rede) retêm os eventos na memória por um breve período, e um processo que termina sem esvaziar esse buffer perde exatamente os eventos gravados logo antes de morrer.

Tudo o que vem depois da inicialização passa por ILogger<T>, como de costume. A classe estática Log se justifica nos pontos que a injeção de dependência não alcança, como antes de o contêiner existir e depois que ele foi descartado.

O README do Serilog.AspNetCore chama isso de inicialização em dois estágios: um logger inicial “é configurado imediatamente quando o programa inicia e é substituído pelo logger totalmente configurado assim que o host é carregado.”

Criar esse primeiro logger exige uma única chamada:

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console()
    .CreateBootstrapLogger();

CreateBootstrapLogger() substitui CreateLogger() no trecho de código que vimos antes. Todo o resto continua igual, incluindo o try–catch–finally em volta do host e o Log.CloseAndFlush() dentro do finally.

Conclusão

Em resumo, dominar as práticas de logging com o Serilog no .NET é essencial para otimizar o desempenho da aplicação e solucionar problemas. Ao configurar o Serilog a partir das configurações da aplicação, ganhamos a flexibilidade de alterar a configuração de logging sem precisar republicar a aplicação a toda hora.

Em produção, evitamos os sinks de console e de arquivo em favor de alternativas feitas para esse ambiente, e é isso que mantém o logging escalável e confiável.

Quando enriquecemos os logs com informações adicionais e adotamos práticas detalhadas de logging de requisições, reforçamos ainda mais a capacidade de diagnóstico da aplicação. Seguindo as práticas mencionadas aqui, podemos aproveitar o poder do Serilog para criar soluções de logging robustas e informativas para as nossas aplicações. Esperamos que você tenha gostado de conhecer algumas das boas práticas do Serilog. Conte para nós nos comentários quais outras você acha que merecem entrar na lista.

Testado com .NET 10.0.10, Serilog 4.4.0 e Serilog.AspNetCore 10.0.0.