Buenas prácticas de logging con Serilog en .NET

Las prácticas que más importan con Serilog son pequeñas y estructurales: configurarlo desde appsettings.json en lugar de en código, registrar plantillas de mensaje en lugar de cadenas interpoladas, inyectar ILogger<T> en lugar de recurrir a la clase estática Log y enriquecer los logs una sola vez al arrancar en lugar de en cada punto de llamada.

Cada una de ellas es una decisión que condiciona lo útiles que serán los logs más adelante. Si nos equivocamos, seguiremos teniendo logs. Solo que serán logs en los que es más difícil buscar.

¿Qué es Serilog?

Serilog es una biblioteca de logging estructurado para .NET. Mientras que un logger tradicional escribe una cadena con formato, Serilog escribe una plantilla de mensaje junto con los valores que la completan, y conserva esos valores como propiedades con nombre en el evento de log.

En esa distinción está toda la biblioteca. Una línea de log que llega como "Order 4417 shipped to Berlin" solo se puede buscar con grep. La misma línea registrada como "Order {OrderId} shipped to {City}", con dos propiedades adjuntas, se puede filtrar, agrupar y contar por cualquiera de ellas.

Los sinks deciden adónde van los eventos: consola, archivo, Seq, Elasticsearch y muchos otros. Cada uno es un paquete independiente que añadimos solo si lo queremos.

Los enriquecedores añaden propiedades a todos los eventos de forma automática, así que el nombre de la máquina o el ID del hilo (thread) aparecen en todos ellos sin tocar un solo punto de llamada.

Serilog se conecta a la interfaz ILogger<T> que ya usa el resto de .NET, así que adoptarlo no implica reescribir los puntos de llamada.

El propio README de Serilog lo presenta como la razón de ser de la biblioteca: “Donde más brilla la compatibilidad de Serilog con el logging estructurado es al instrumentar aplicaciones y sistemas complejos, distribuidos y asíncronos”.

Evita la clase estática de logger

Serilog incluye la clase estática Log, que podemos usar en toda la aplicación para registrar eventos e información. Podemos usarla para acceder a su propiedad Logger y escribir cualquier tipo de log que queramos. Pero, al hacerlo, rompemos el principio de inversión de dependencias.

Podemos integrar fácilmente Serilog con la interfaz de logging integrada de Microsoft, que es una de las prácticas más útiles que podemos seguir. Con este enfoque, no solo respetamos el principio de inversión de dependencias, sino que también hacemos que probar la aplicación sea mucho más fácil.

Ese último punto no es teórico. Una interfaz inyectada es lo que hace que sea sencillo hacer pruebas unitarias de código que registra logs sin un logger real detrás.

Sin embargo, uno de los casos de uso de la clase estática Log está en la clase Program, una vez que añadimos el paquete Serilog.AspNetCore (dotnet add package Serilog.AspNetCore), que trae consigo Serilog con sus sinks de consola y de archivo:

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 la propiedad Logger de la clase estática Log para configurarla de modo que escriba los logs en un archivo. Después, envolvemos la configuración de la aplicación en un bloque try–catch; así registraremos cualquier error que ocurra durante el arranque de la aplicación. El bloque finally simplemente se encarga de cerrar el logger y vaciar los logs pendientes.

La llamada a MinimumLevel va antes de los sinks solo por legibilidad, para que la configuración se lea en orden: primero los niveles y luego los destinos. Ambos se aplican dentro de CreateLogger(), así que el orden de las llamadas encadenadas no cambia lo que hace el logger.

También podemos usar la clase estática Log en cualquier otro lugar donde no sea posible la inyección de dependencias.

Configura Serilog desde appsettings.json

Antes que nada, hay que configurar Serilog según nuestras necesidades. Tenemos dos opciones: la API fluida o el sistema de configuración. Aunque la API fluida es muy intuitiva y fácil de leer, tiene un gran inconveniente: cada vez que cambiamos algo en la configuración, tenemos que publicar una nueva compilación de la aplicación.

Por eso es mejor usar el sistema de configuración para configurar Serilog en nuestras aplicaciones:

Install-Package Serilog.Settings.Configuration

Ese es el comando para la Package Manager Console. Fuera de Visual Studio, la CLI de .NET hace lo mismo:

dotnet add package Serilog.Settings.Configuration

Ahora que tenemos el paquete, añadamos la configuración 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"
  }
}

Primero, en el archivo appsettings.json, añadimos una nueva sección llamada Serilog. Dentro de ella, empezamos creando la subsección Using, en la que indicamos el sink que queremos usar.

A continuación, establecemos el nivel mínimo predeterminado. En una guía aparte explicamos todos los niveles de log de Serilog y cómo establecer un mínimo. Luego pasamos a la subsección WriteTo, donde configuramos los distintos sinks, lo que puede incluir incluso cosas como la plantilla de salida.

En esa plantilla, {Level:u3} es la forma convencional. El número es un ancho máximo, no un ancho de campo, así que un valor mayor como u11 no añade relleno: simplemente imprime cada nivel completo, lo que nos da INFORMATION y WARNING, mientras que u3 da los valores alineados INF y WRN.

Después, tenemos que aplicar la configuración:

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

En la clase Program, usamos el método de extensión AddSerilog() para indicar que la aplicación debe usar el archivo appsettings.json para configurar Serilog. Con esto, ya no hace falta volver a publicar la aplicación cuando cambia la configuración del logging.

AddSerilog() es lo que documenta hoy Serilog.AspNetCore. El antiguo builder.Host.UseSerilog() sigue funcionando, pero no es un simple cambio de nombre: UseSerilog() le pasa a la lambda un HostBuilderContext, mientras que AddSerilog() le pasa un IServiceProvider, así que la configuración viene de builder.Configuration en lugar de context.Configuration.

Olvídate de los sinks de consola y de archivo de Serilog en producción

Mientras desarrollamos una aplicación, es genial ver los eventos de log a medida que ocurren. Registrar en la consola es una buena forma de conseguirlo. Sin embargo, registrarlo todo en la consola puede hacer muy difícil localizar eventos, ya que se satura enseguida de información. Además, queremos evitarlo en el entorno de producción, porque puede causar problemas de rendimiento.

En desarrollo, el sink de archivo de Serilog es más útil que el de consola porque la salida sobrevive a la ejecución. Podemos filtrar y ordenar los logs, lo que facilita encontrar un evento concreto. Sin embargo, al igual que ocurre con el logging en la consola, esto se vuelve muy engorroso de gestionar en producción.

Para producción, podemos usar Seq, Elasticsearch o cualquier otro sink de Serilog más adecuado para entornos de producción. Así ganamos escalabilidad y fiabilidad en comparación con los logs en archivo o en consola.

Otra opción es enviar los logs como datos de OpenTelemetry, lo que permite mandarlos a cualquier backend compatible con el protocolo OTLP en lugar de al sink de un único proveedor.

Cabe mencionar que, según nuestra situación, puede haber casos en los que los logs en archivo y en consola tengan su utilidad en producción. Por ejemplo, nuestro proveedor de logs podría tener problemas para recibirlos, y entonces tener logs en archivo o en consola podría resultar útil.

Hay dos prácticas de producción que quedan fuera de la elección del sink. La primera es dónde se produce la escritura. Un sink que bloquea al llamador, sobre todo el sink de archivo, se puede envolver en WriteTo.Async() para que la escritura se ejecute en un hilo de trabajo en segundo plano y no en el hilo que registró el evento.

No es una solución universal. El README de Serilog.Sinks.Async indica que los sinks de red recomendados arriba, entre ellos Seq y Elasticsearch, ya envían por lotes por su cuenta y no ganan nada con el envoltorio, que es lo mismo que este artículo explica más adelante sobre los sinks que trabajan por lotes.

La segunda práctica tiene que ver con lo que va en las propiedades. Una propiedad se almacena y se indexa en lugar de quedar enterrada en una línea de texto, así que los datos personales en una plantilla de mensaje son mucho más fáciles de extraer después que el mismo valor dentro de una cadena con formato. Mantenlos fuera de la plantilla.

Usa siempre logging estructurado

Siempre que sea posible, deberíamos evitar las cadenas simples al registrar logs. En nuestro endpoint /weatherforecast, con un parámetro ILogger<Program> logger añadido a su expresión lambda, registrar el primer pronóstico antes de devolverlo podría quedar así:

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

Esto generará un mensaje de log simple que puede no ser muy útil. Además, el primer parámetro del método LogInformation() de ILogger<T> se llama message, pero es una plantilla de mensaje, no un mensaje.

Usémoslo correctamente:

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

Aquí, primero pasamos la plantilla de mensaje y después los dos parámetros que requiere. Esto generará un log estructurado, en el que tanto Summary como Temperature se almacenarán como propiedades asociadas al mensaje de log. Así es mucho más fácil consultar los logs, lo que nos ahorra tiempo y esfuerzo.

La sintaxis de los marcadores de posición tiene sus propias reglas, y explicamos las plantillas de mensaje con más detalle por separado.

Usa enriquecedores de eventos de log

Un enriquecedor añade una propiedad a cada evento de log y se configura una sola vez al arrancar, en lugar de pasarse en cada punto de llamada.

Serilog incluye un núcleo pequeño y reparte la mayoría de los enriquecedores en paquetes independientes, y ahí empieza la confusión: el valor Enrich de la configuración y el paquete que lo proporciona tienen nombres distintos.

WithMachineName y WithEnvironmentName vienen ambos de Serilog.Enrichers.Environment. WithThreadId viene de Serilog.Enrichers.Thread, y WithProcessId, de Serilog.Enrichers.Process. Nombrar un enriquecedor sin instalar su paquete no hace nada y no avisa: la propiedad simplemente nunca aparece.

FromLogContext es la excepción que conviene conocer. No necesita ningún paquete adicional, y es lo que nos permite añadir una propiedad, como un ID de correlación, a todos los eventos que se generan dentro de un bloque de código.

Además, los enriquecedores son baratos en un sentido en que no lo son las propiedades en el punto de llamada. Como se configuran una vez al arrancar, no añaden código a ninguna instrucción de log y quien escriba la siguiente no puede olvidarlos.

La tabla siguiente relaciona cada enriquecedor con el paquete que lo proporciona.

Una nota sobre ese fallo silencioso: Serilog sí escribe un mensaje al respecto en Serilog.Debugging.SelfLog, que está desactivado a menos que lo activemos.

Empezamos instalando los paquetes de enriquecimiento Thread, Process y Environment de Serilog:

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

Los mismos tres paquetes con la CLI de .NET:

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

A continuación, actualizamos la configuración:

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

En el archivo appsettings.json, añadimos una nueva subsección llamada Enrich. Dentro de ella, añadimos entradas que indican que Serilog debe enriquecer los logs con ThreadId, ProcessId y MachineName, además de con EnvironmentName.

La plantilla de salida de la consola no imprime estas propiedades, así que también enviamos los logs a una instancia de Seq en nuestra máquina. Instalamos el paquete Serilog.Sinks.Seq (dotnet add package Serilog.Sinks.Seq) y añadimos un segundo sink a la subsección WriteTo, después del de la consola:

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

Ahora podemos enviar una solicitud a nuestra API y examinar la salida en Seq:

Vemos que el log incluye todas las propiedades adicionales que especificamos en la subsección Enrich del archivo appsettings.json.

Crea un enriquecedor de eventos de log personalizado para Serilog

No es ninguna sorpresa que podamos crear 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()));
    }
}

Empezamos creando la clase ThreadPriorityEnricher e implementando la interfaz ILogEventEnricher. La interfaz nos obliga a implementar el método Enrich(). Con el método AddPropertyIfAbsent() de la clase LogEvent, intentamos añadir una nueva propiedad a los logs si todavía no existe. Esta propiedad adicional añadirá la prioridad del hilo a los eventos de log. Para obtener la prioridad, usamos la clase Thread y sus propiedades. La propiedad la crea el método CreateProperty() de la interfaz ILogEventPropertyFactory.

A continuación, registramos el enriquecedor:

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

En la clase Program, usamos el método With() sobre la propiedad Enrich de la clase LoggerConfiguration. Al método le pasamos una nueva instancia de nuestra clase ThreadPriorityEnricher.

Con esto, todos los logs de la aplicación tendrán ThreadPriority como propiedad.

Una idea parecida es la que permite registrar automáticamente los nombres de clase y de método, lo que nos ahorra escribirlos a mano en cada mensaje.

Logging de solicitudes con Serilog

Las solicitudes son una parte vital de cualquier aplicación, así que un logging detallado es imprescindible:

app.UseSerilogRequestLogging();

En la clase Program, llamamos al método de extensión UseSerilogRequestLogging() sobre la instancia de WebApplication. Con esto, los logs de solicitudes incluirán información sobre el método HTTP, la ruta, el código de estado y cuánto tardó la aplicación en responder.

Podemos ir un paso más allá y crear un enriquecedor personalizado para los logs de solicitudes:

using Serilog;

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

Empezamos creando una nueva clase RequestEnricher.

A continuación, creamos el método LogAdditionalInfo(). Recibe dos parámetros: la instancia de IDiagnosticContext de Serilog y la de HttpContext de ASP.NET Core. Después, usamos el método Set() del contexto de diagnóstico para crear la propiedad ClientIP y le asignamos la propiedad Connection.RemoteIpAddress del HttpContext que se pasa al método.

Ten en cuenta que esto es distinto de implementar la interfaz ILogEventEnricher y que se registra de otra manera.

A continuación, añadimos nuestro enriquecedor personalizado:

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

Para ello, dentro del método UseSerilogRequestLogging() asignamos a la propiedad EnrichDiagnosticContext el método LogAdditionalInfo() que acabamos de escribir.

Por último, podemos enviar una solicitud y comprobar el log:

Vemos que el log ahora tiene información sobre el método HTTP, la ruta y el código de estado. También obtenemos una propiedad llamada ClientIP con el valor ::1, lo que significa que enviamos la solicitud desde la misma máquina en la que se ejecuta la aplicación.

¿Cómo configurar Serilog en ASP.NET Core?

La configuración se hace en dos lugares, y la división es deliberada. El host conecta Serilog con la inyección de dependencias, mientras que appsettings.json decide lo que hace realmente.

La conexión va en la clase Program y lee la sección de configuración, así que los sinks, los niveles mínimos y los enriquecedores cambian sin recompilar.

El logger de arranque (bootstrap logger) es la pieza que falta en la mayoría de las configuraciones. Serilog no queda configurado hasta que se construye el host, así que cualquier cosa que falle antes de ese momento no se registra en ninguna parte. Crear primero un logger mínimo y reemplazarlo cuando se cargue la configuración cierra ese hueco.

Log.CloseAndFlush() va en un bloque finally por el mismo motivo. Los sinks que trabajan por lotes (Seq, Elasticsearch, muchos sinks de red) retienen los eventos en memoria durante un breve tiempo, y un proceso que termina sin vaciar el búfer pierde justo los eventos escritos antes de morir.

Todo lo que ocurre después del arranque pasa por ILogger<T>, como de costumbre. La clase estática Log se gana su sitio allí donde la inyección de dependencias no llega, como antes de que exista el contenedor y después de que se haya liberado.

El README de Serilog.AspNetCore lo llama inicialización en dos fases: un logger de arranque inicial “se configura inmediatamente cuando se inicia el programa, y se sustituye por el logger completamente configurado una vez que el host se ha cargado”.

Crear ese primer logger requiere una sola llamada:

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

CreateBootstrapLogger() sustituye a CreateLogger() en el fragmento de código que vimos antes. Todo lo demás se queda como estaba, incluido el try–catch–finally que rodea al host y el Log.CloseAndFlush() dentro del finally.

Conclusión

En resumen, dominar las prácticas de logging con Serilog en .NET es esencial para optimizar el rendimiento de nuestra aplicación y diagnosticar problemas. Al configurar Serilog mediante la configuración de la aplicación, ganamos la flexibilidad de cambiar los ajustes de logging sin tener que volver a publicar constantemente.

En producción, evitamos los sinks de consola y de archivo en favor de alternativas diseñadas para ello, que es lo que mantiene el logging escalable y fiable.

Cuando enriquecemos los logs con información adicional y adoptamos prácticas detalladas de logging de solicitudes, mejoramos aún más las capacidades de diagnóstico de la aplicación. Si seguimos las prácticas que hemos visto aquí, podemos aprovechar la potencia de Serilog para crear soluciones de logging robustas y reveladoras para nuestras aplicaciones. Esperamos que hayas disfrutado de este repaso a algunas buenas prácticas de Serilog; cuéntanos en los comentarios cualquier otra que creas que merece estar en la lista.

Probado con .NET 10.0.10, Serilog 4.4.0 y Serilog.AspNetCore 10.0.0.