Serilog: Manejando trazas en .Net Core

Qué es Serilog

El logging es uno de los aspectos más básicos que toda aplicación necesita. Es fundamental para solucionar cualquier problema de la aplicación cuando está en producción, incluso en fase de desarrollo puede sernos de gran utilidad a pesar de que podamos depurar el código desde nuestro IDE. Es fundamental contar con la funcionalidad de “logging” en nuestras aplicaciones. Sin embargo, históricamente guardar en los “logs” únicamente cadenas de puro texto plano ha sido el origen de varios problemas cuando queríamos tratar de explorar o consultar los datos de los mismos.

Por ejemplo, si quisieras filtrar de todo tu “log” solamente aquellos registros que cumplen con cierto identificador o condición, sería una tarea no tan trivial. Los archivos de log son uno de los activos más valiosos que tiene un desarrollador. Normalmente, cuando algo va mal en producción lo primero que se oye es “envíame los logs”. El objetivo de tener un log estructurado es aportar un formato más definido y detallado. Los frameworks de logging facilitan el envío de tus registros a diferentes lugares a través de configuraciones simples.

Serilog es un framework de Logging para .NET. Ha sido construido con el registro de datos estructurado en mente. Facilita el registro de propiedades de objetos personalizados e incluso la salida de sus registros a JSON. Serilog utiliza lo que se llama sinks para enviar sus registros a un archivo de texto, base de datos, o soluciones de gestión de registros, o cualesquiera que sean otros lugares, todo ello sin cambiar tu código.

Cómo usar Serilog

Para hacer uso de Serilog precisamos de instalarlo en nuestra app. Para ello podemos hacer una búsqueda de paquetes nuget para instalar tanto Serilog como el o los sinks que deseemos. Por ejemplo, para un log de consola instalaríamos lo siguiente:

Install-Package Serilog
Install-Package Serilog.Sinks.Console

Con esto le estaríamos proporcionando a Serilog un sink en el cual le decimos que los datos de logging los vaya escribiendo por la consola. Este tipo de sink y el de escribir en ficheros suelen ser los más comunes. Veamos un ejemplo de una aplicación de consola haciendo uso de este sink:

using Serilog;

class Program
{
    public static void Main(string[] args)
    {
        using (var log = new LoggerConfiguration()
            .WriteTo.Console()
            .CreateLogger())
        {
            log.Information("Hello, Serilog!");
            log.Warning("Goodbye, Serilog.");
        }
    }
}

Aquí podemos ver cómo hacemos uso de un LoggerConfiguration que nos proporciona acceso a los siguientes métodos:

• WriteTo.Console, dónde estamos haciendo uso del sink de consola.
• CreateLogger, el cual instancia nuestro logger para su posterior uso donde deseemos.
• Como el logger es Disposable, lo debemos usar dentro de una clausula using, para liberar recursos una vez finalizado el uso del mismo.
• log.Information, el cual escribe una línea de tipo información.
• log.Warning, el cual escribe una línea de tipo warning.

Si ejecutamos un programa con esta implementación deberíamos ver algo como lo siguiente:

Qué guarda Serilog

Comparando con otros frameworks de logging como puede ser log4net, aquí lo que tenemos que pensar es que hacemos log de eventos, no de mensajes. Serilog lo que guarda como evento es lo siguiente:

• Un timestamp o marca de tiempo que registra cuándo ocurrió el evento.
• Un nivel que describa de qué tipo se capturó el evento.
• Un mensaje que documenta lo que representa el evento.
• Propiedades con nombre que describen el evento.
• En caso que lo deseemos un objeto de con el detalle de una Excepción que se haya producido.

Estos últimos 2 puntos los veremos más adelante en otro ejemplo.

El formato en el que se ve nuestro evento de log puede ser como hemos visto anteriormente:

13:04:24 [INF] Hello, Serilog!

O puede ser que nos interese mandarlo en JSON a otro servidor:

{"@t":"2021-09-06T13:04:01.12345","@m":"Hello, Serilog!"}

Niveles de Log

Serilog es un framework ligero y rápido, pero construir y registrar eventos de log detallados todo el tiempo puede desperdiciar recursos de CPU, disco y red. Para gestionar esto, a los eventos Serilog se les asignan niveles como Debug, Info, Warning y Error. Hay un método Log.*() para cada nivel soportado.

Mediante configuración podemos cambiar el nivel de detalle de nuestro log:

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Debug() // <- minimum level
    .WriteTo.Console()
    .CreateLogger();

Log.Debug("Processing item {ItemNumber} of {ItemCount}", itemNumber, itemCount);

Para desarrollo puede ser correcto que tengamos el nivel mínimo en Debug, pero para entornos de producción podríamos tener activado el mínimo en tipo Information o superior (Warning y Error) para que sólo veamos información relevante a la hora de consultar nuestros logs.

Para guardar las Excepciones, en Serilog tenemos dentro del método Log.Error un constructor que acepta como primer parámetro la Excepción, de tal forma que el mismo la trata de forma correcta. Se recomienda hacer uso de esta forma y no incluir el mensaje de la excepción directamente.

Guardando datos estructurados

Serilog permite hacer uso de plantillas de mensajes a la hora de guardar los datos, haciendo uso de los nombres de las variables que se le pase.

var itemNumber = 1;
var itemCount = 100;
Log.Debug("Processing item {ItemNumber} of {ItemCount}", itemNumber, itemCount);

El cual produciría una salida como la siguiente en JSON:

{
    "@t": "2021-06-09T14:33:01.12345",
    "@l": "Debug",
    "@m": "Processing item 1 of 100",
    "ItemNumber": 1,
    "ItemCount": 100
}

Lo bueno de esto es que tenemos el mensaje y además tenemos las propiedades con sus valores de entrada, y aquí viene la potencia de esto. Esto nos va a permitir hacer filtrados sobre los datos haciendo consultas del tipo ItemNumber>55 por ejemplo.

Otra plantilla interesante a usar en Serilog es la que hace uso de @, veamos un ejemplo:

var user = new { Name = "Con", Id = "cnd" };
Log.Information("Logged on user {@User}", user);

Lo que hace Serilog es capturar la variable @user y meterla como Json, teniendo un fichero de salida como el siguiente:

{
    "@t": "2021-06-09T11:33:01.12345",
    "@m": "Logged on user {\"Name\": \"Con\", \"Id\": \"cnd\"}",
    "User": {"Name": "Con", "Id": "cnd"}
}

Así a la hora de consumir los datos de nuestro log podríamos hacer una consulta del tipo User.Id != ‘cnd’

Serilog y Sql Server

Veamos ahora un ejemplo de uso de Serilog con Sql Server desde una app asp.net core. Para ello en nuestra aplicación tendremos que instalar los siguientes paquetes nuget:

Serilog
Serilog.AspNetCore
Serilog.Settings.Configuration
Serilog.Sinks.MSSqlServer

En el Program.cs deberíamos tener algo como lo siguiente:

public class Program
{
    public static IConfiguration Configuration { get; } = new ConfigurationBuilder()      
        .SetBasePath(Directory.GetCurrentDirectory())
        .AddJsonFile("appsettings.json", optional: false, reloadOnChange: true)      
        .AddJsonFile($"appsettings.{Environment.GetEnvironmentVariable("ASPNETCORE_ENVIRONMENT") ?? 
                     "Production"}.json", optional: true)
                     .Build();
    public static void Main(string[] args)
    {
        Log.Logger = new LoggerConfiguration() 
            .ReadFrom.Configuration(Configuration)            
            .CreateLogger();
        try
        {
            Log.Information("Starting host...");

            BuildWebHost(args).Run();
        }
        catch (Exception ex)
        {
            Log.Fatal(ex, "Host terminated unexpectedly");
        }
        finally
        {
            Log.CloseAndFlush();
        }
    }

    public static IWebHost BuildWebHost(string[] args) =>
        WebHost.CreateDefaultBuilder(args)
               .UseStartup<Startup>()
               .UseConfiguration(Configuration)
               .UseSerilog()               
               .Build();
}

Y en el fichero appSettings podríamos tener una configuración como la siguiente:

{
  ...
  "Serilog": {
    "MinimumLevel": "Information",
    "WriteTo": [
      {
        "Name": "MSSqlServer",
        "Args": {
          "connectionString": "<connection string>",
          "tableName": "Logs"
        }
      }
    ]
  },
  ...
}

Una vez que tengamos todo listo, desde cualquier punto de nuestra app asp.net core podemos hacer uso de una llamada de log como la siguiente:

 Log.Information("Contact {@contact} retrieved from database", contact);

Y en Sql veríamos en la tabla Logs información como la siguiente:

Si a la hora de iniciar nuestra aplicación tenemos problemas, podemos habilitar la depuración de Serilog con Serilog.Debugging.SelfLog.Enable()

En nuestra configuración de Serilog vista anteriormente podríamos escribir algo como lo siguiente:

Serilog.Debugging.SelfLog.Enable(msg =>        
                                 {            
                                     Debug.Print(msg);            
                                     Debugger.Break();        
                                 });

De tal forma que podamos ver qué está ocurriendo para depurar posibles problemas a la hora de hacer uso de la configuración que hayamos puesto en Serilog

Enriquecer eventos de Serilog

Otra opción de configuración muy potente que nos brinda Serilog es la posibilidad de enriquecer nuestros mensajes por defecto, es muy sencillo de ver:

internal static class LoggerConfigurationExtensions {
    internal static void SetupLoggerConfiguration(string appName, BuildInfo buildInfo) {
        Log.Logger = new LoggerConfiguration()
            .ConfigureBaseLogging(appName, buildInfo)
            .CreateLogger();
    }

    internal static LoggerConfiguration ConfigureBaseLogging(
        this LoggerConfiguration loggerConfiguration,
        string appName,
        BuildInfo buildInfo
    ) {
        loggerConfiguration
            .MinimumLevel.Debug()
            .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
            .WriteTo.Async(a => a.Console(theme: AnsiConsoleTheme.Code))
            .Enrich.FromLogContext()
            .Enrich.WithMachineName()
            .Enrich.WithThreadId()
            // Build information as custom properties
            .Enrich.WithProperty(nameof(buildInfo.BuildId), buildInfo.BuildId)
            .Enrich.WithProperty(nameof(buildInfo.BuildNumber), buildInfo.BuildNumber)
            .Enrich.WithProperty(nameof(buildInfo.BranchName), buildInfo.BranchName)
            .Enrich.WithProperty(nameof(buildInfo.CommitHash), buildInfo.CommitHash)
            .Enrich.WithProperty("ApplicationName", appName);

        return loggerConfiguration;
    }

}

Con el siguiente fichero de configuración, con las llamadas a Enrich vemos que estamos añadiendo por defecto a cada una de las entradas de Serilog información que puede ser muy interesante, como los datos relacionados con la build que está produciendo dichas entradas de eventos en el log de Serilog.

Conclusión

Como podrás ver estas son sólo unas nociones básicas para que te hagas una idea de lo que se puede hacer con Serilog. Para ver todas las posibilidades que ofrece (son muchas) te recomiendo que le des un vistazo a la documentación oficial así como que le des un vistazo al sink de Seq el cual es un servidor de ingesta de datos de Log, que nos permite ir viendo en tiempo real nuestros logs, filtrar los mismos y muchas más funcionalidades que te pueden ser de gran ayuda a la hora de ver qué está ocurriendo con tu aplicación.