En el mundo del desarrollo de software estamos muy acostumbrados a depurar código mientras desarrollamos un producto o una nueva característica. Para ello, los entornos de desarrollo (IDE por sus siglas en inglés) van siempre acompañados de herramientas de depuración que nos permiten recolectar información sobre la ejecución, el valor de las variables, interrumpir el programa en puntos concretos y mover el puntero de ejecución hacia atrás y hacia adelante.
Esto es indispensable durante la fase de desarrollo y mantenimiento, pero ¿qué podemos hacer si el software está ya en producción y se produce un fallo catastrófico? En producción no tenemos un IDE con su depurador asociado para poder ver qué está pasando... Por ello es de vital importancia instrumentar el código de manera que tengamos métricas y trazas que aporten esa información que nos falta cuando algo no va bien en producción.
¿Por qué utilizar un logger?
Existen diferentes métodos y destinos para poder registrar toda esa información de manera que sea posible consultarla a posteriori: desde herramientas básicas integradas en la plataforma .NET, hasta utilidades específicas de proveedores cloud, como Azure, para instrumentar aplicaciones y obtener información en tiempo real sobre cómo se están ejecutando.
Parafraseando a Arquímedes*: dadme un IDE y desarrollaré lo necesario. Es posible añadir todas esas funciones y características que nos resultarían ideales pero hay que plantearse si merece la pena.
* Como dato histórico, la frase que se atribuye a Arquímedes es "Dadme un punto de apoyo y moveré el mundo".
Por ejemplo, podríamos crear con facilidad nosotros mismos una clase estática que guarde la información en un fichero:
public static class FileLogger
{
private const string FilePath = "log.txt";
public static void Log(string messsage)
{
using var fileStream = new FileStream(FilePath, FileMode.Append);
using var writter = new StreamWriter(fileStream);
writter.WriteLine(messsage);
}
}
//...
FileLogger.Log("Mensaje 1");
FileLogger.Log("Mensaje 2");
FileLogger.Log("Mensaje 3");
Como se puede comprobar, es una implementación muy sencilla que simplemente registra cada mensaje en un fichero llamado log.txt, junto al ejecutable. De hecho, si colocamos ese código en una aplicación de consola y tras ejecutarla abrimos el fichero nos encontrarémos algo como esto:
Hay que reconocer que aunque funcional, el ejemplo anterior es poco práctico y nada recomendable. Sí que es cierto que puede haber algún caso muy particular en el que esto sea suficiente. Pero por lo general vamos a necesitar más información (como la hora, los datos internos de una excepción...), un sistema más robusto de guardar la información y de lidiar con la concurrencia o, simplemente, que los ficheros se vayan purgando periódicamente para evitar acumular un montón de gigabytes con información antigua.
Existen varias herramientas disponibles para poder resolver la situación y que están ya preparadas con mucha funcionalidad extra que nos va a facilitar la vida. Por citar algunas podríamos hablar de NLog, Apache log4net o el que vamos a revisar en más profundidad en el artículo de hoy: Serilog.
Todos ellos trabajan de manera "similar": nos ofrecen un mecanismo para configurar un logger y después vamos a trabajar con él para registrar las trazas según lo configurado. Es por esto que aunque aquí vayamos a hablar de Serilog, utilizar cualquier otro logger no debería ser muy complicado una vez se conoce alguno.
Y ahora que ya hemos hecho las presentaciones, vamos con lo que realmente nos interesa. ¿Cómo se pone en marcha Serilog en .Net Core? Depende un poco del tipo de aplicación que estemos creando, así que empecemos con una aplicación de consola y después veremos cómo aprovechar la inyección de dependencias.
Creando un logger con Serilog
Para poder utilizar Serilog, lo primero que vamos a necesitar es añadir a nuestro proyecto el paquete Serilog. Este es el paquete básico que contiene toda la infraestructura necesaria para utilizar Serilog y sobre este paquete se van a ir añadiendo diferentes salidas como pueden ser ficheros, consola, una base de datos, etc... Estos diferentes destinos se conocen como Sinks y la lista de paquetes ya listos para utilizar diferentes Sinks es muy larga.
Puedes comprobar la lista completa de Sinks, así como sus enlaces en la wiki del proyecto.
En este caso, el ejemplo más básico sería utilizar el Sink de consola, para que todas las trazas que registremos se muestren por consola. Para esto, vamos a añadir también una referencia al paquete Serilog.Sinks.Console.
Teniendo ya en el proyecto los paquetes de Serilog y del Sink de consola, vamos a poder crear un logger con un código tan simple como este:
var logger = new LoggerConfiguration()
.WriteTo.Console()
.CreateLogger();
Una vez creado el logger, basta con mantener la instancia en memoría para registrar mensajes en consola desde cualquier punto donde tengamos acceso a ésta. Para conseguir registrar el mensaje, sólo hay que llamar a cualquiera de los métodos a nuestra disposición, a saber:
Verbose(string)Debug(string)Information(string)Warning(string)Error(string)Fatal(string)
Con ellos vamos a poder registrar trazas con diferentes niveles de importancia e información a lo largo del código de la aplicación. Posteriormente podremos filtrarlos de manera global o simplemente indicándole el nivel mínimo que nos interese, al registrar el Sink. Por ejemplo, si ejecutamos el siguiente código:
var logger = new LoggerConfiguration()
.MinimumLevel.Debug()
.WriteTo.Console(LogEventLevel.Information)
.CreateLogger();
logger.Verbose("Mensaje Verbose");
logger.Debug("Mensaje Debug");
logger.Information("Mensaje Information");
logger.Warning("Mensaje Warning");
logger.Error("Mensaje Error");
logger.Fatal("Mensaje Fatal");
Podemos comprobar que todos loe mensajes con un nivel inferior a Information se filtran directamente y no llegan a la salida del Sink:
Añadiendo diferentes Sink a nuestro logger
Ahora que tenemos estos conceptos básicos claros, vamos a replicar la misma funcionalidad que tenía nuestro logger hecho a mano del principio, añadiendo el Sink de salida a archivos. Para eso añadimos el paquete "Serilog.Sinks.File" y configuramos el Sink de la misma manera que antes:
var logger = new LoggerConfiguration()
.MinimumLevel.Debug()
.WriteTo.Console(LogEventLevel.Information)
.WriteTo.File("log.txt", LogEventLevel.Fatal) //Con esta línea configuramos la salida a fichero
.CreateLogger();
Con este pequeño cambio, ya hemos añadido una nueva salida al logger, de manera que vamos a mostrar toda la información superior a Information en la consola y, además, guardaremos todas las trazas de nivel igual o superior a Fatal (que en la práctica es solo Fatal) en el fichero log.txt.
De todos modos, respecto a nuestro logger hecho a mano no tenemos una gran ventaja. Simplemente hemos conseguido un par de filtros y una salida adicional por consola. Nada que no se pueda hacer escribiendo un poco más de código en nuestra pequeña clase.
La verdadera potencia se hace patente cuando necesitamos esa funcionalidad extra como poder rotar ficheros. Imaginemos que queremos que las trazas se agrupen por día y que además se retengan durante un máximo de 10 días. Para conseguir eso ya tendríamos que empezar a añadir bastante código extra a nuestra clase. Pero utilizando el Sink de Serilog lograrlo se reduce a algo como esto:
var logger = new LoggerConfiguration()
.MinimumLevel.Debug()
.WriteTo.Console(LogEventLevel.Information)
.WriteTo.File("log.txt", LogEventLevel.Fatal, rollingInterval: RollingInterval.Day, retainedFileCountLimit:10)
.CreateLogger();
¿Sencillo verdad? Pues aún hay (mucho) más. Utilizando diferentes Sink las posibilidades aumentan para poder cubrir la gran mayoría de los casos. Sin ir más lejos, un escenario habitual es escribir registros en una base de datos, y eso es algo tan simple como esto:
//Cadena de conexión de la base de datos
var connectionString = "Server=(localdb)\\MSSQLLocalDB;Database=Logger;Integrated Security=true";
//Configuración del Sink de MSSqlServer
var sqlLoggerOptions = new SinkOptions
{
AutoCreateSqlTable = true,
SchemaName = "Logger",
TableName = "Logs",
BatchPostingLimit = 1
};
var logger = new LoggerConfiguration()
.MinimumLevel.Debug()
.WriteTo.Console(LogEventLevel.Information)
.WriteTo.File("log.txt", LogEventLevel.Fatal,rollingInterval: RollingInterval.Day,retainedFileCountLimit:10)
.WriteTo.MSSqlServer(connectionString, sqlLoggerOptions) //Aquí se añade el Sink
.CreateLogger();
Como es de suponer, para poder utilizar el Sink de MSSqlServer hay que añadir el paquete "Serilog.Sinks.MSSqlServer"
Enriqueciendo las trazas con información adicional
En este punto ya está claro que, salvo que nuestro logger sea algo extremadamente simple, utilizar un logger especializado es siempre la mejor opción.
Otra de las opciones muy interesantes que ofrece Serilog es la posibilidad de añadir información útil a las trazas de manera automática. A este concepto se le conoce como enriquecer las trazas.
Esto se consigue gracias a la gran capacidad de extensión que ofrece Serilog. Aunque podemos crear nuestros propios enriquecedores para Serilog, ya existen algunos disponibles como paquete NuGet.
Por ejemplo, añadiendo el identificador del proceso:
var logger = new LoggerConfiguration()
.Enrich.WithProcessId() //Aquí se añade el enriquecedor
.WriteTo.Console(LogEventLevel.Information)
.WriteTo.File("log.txt", LogEventLevel.Fatal,rollingInterval: RollingInterval.Day,retainedFileCountLimit:10)
.WriteTo.MSSqlServer(connectionString, sqlLoggerOptions)
.CreateLogger();
Vamos a obtener una salida parecida a esta:
Para poder utilizar el método WithProcessId hay que añadir el paquete Serilog.Enrichers.Process
Configurando Serilog desde un fichero de configuración
Si bien es cierto que se pueden configurar todos los aspectos de Serilog mediante código, esto no deja de ser una solución muy rígida, que impide poder cambiar la configuración a menos que recompilemos el proyecto. No son pocas las veces donde necesitamos que una aplicación registre absolutamente toda la información disponible para arreglar algún error, pero nadie quiere tener ficheros de varios gigas en producción.
Para poder manejar esta situación los loggers suelen ofrecer la posibilidad de configurarse mediante un archivo, que es fácilmente editable. Serilog no es menos, y permite que configuremos todas sus opciones mediante un fichero app.config/web.config para .NET "tradicional", o un fichero appsettings.json en .NET Core.
Ya que la finalidad en este artículo no es entrar en profundidad en Serilog, sino darte una visión general sobre sus posibilidades, vamos a plantear solamente la opción de appsettings.json, ya que previsiblemente es la que mayor recorrido tiene. Serilog puede tomar su configuración desde cualquier origen de Microsoft.Extensions.Configuration siempre que añadamos el paquete Serilog.Settings.Configuration, por lo que podemos crear un archivo de configuración y pasárselo a Serilog para inicializarlo con las opciones contenidas en éste:
var configuration = new ConfigurationBuilder()
.AddJsonFile("appsettings.json")
.Build();
var logger = new LoggerConfiguration()
.ReadFrom.Configuration(configuration)
.CreateLogger();
Pero no solo llega con cambiar el código. También es necesario escribir la configuración en el fichero. Para ello creamos un objeto en el JSON y le indicamos todas las configuraciones que habíamos puesto antes en el código:
{
"Serilog": {
"Using": [ "Serilog.Sinks.Console", "Serilog.Sinks.File", "Serilog.Sinks.MSSqlServer" ],
"WriteTo": [
{
"Name": "Console",
"restrictedToMinimumLevel": "Information"
},
{
"Name": "File",
"Args": {
"path": "log.txt",
"rollingInterval": 3,
"retainedFileCountLimit": 10
},
"restrictedToMinimumLevel": "Fatal"
},
{
"Name": "MSSqlServer",
"Args": {
"connectionString": "Server=(localdb)\\MSSQLLocalDB;Database=Logger;Integrated Security=true",
"sinkOptionsSection": {
"tableName": "Logs",
"schemaName": "Logger",
"autoCreateSqlTable": true,
"batchPostingLimit": 1
}
}
}
],
"Enrich": [ "WithThreadId" ]
}
}
Si analizamos en detalle el contenido de este archivo podemos comprobar que se parece mucho a lo que teníamos por código, pero de manera declarativa. ¡Genial!
Registrando Serilog en el inyector de dependencias
Lo que hemos planteado hasta ahora está muy bien, pero para los que estamos habituados a trabajar con inyección de dependencias y la interfaz ILogger de .Net Core, esto se queda un poco corto. Eso de crear instancias de objetos por aquí y por allá va totalmente en contra del principio de inyección de dependencias. Es por eso que, Serilog está preparado también para registrarse en el contenedor de inyección de dependencias.
¿A estas alturas ya no hay dudas de cómo añadir ese soporte verdad? En efecto... Utilizando un paquete NuGet.
Esta vez vamos a necesitar incorporar Serilog.AspNetCore, y con esto podremos ir a Program.cs y añadir las únicas 9 líneas que necesitamos para que Serilog trabaje debajo del capó de ILogger:
public static IHostBuilder CreateHostBuilder(string[] args) =>
Host.CreateDefaultBuilder(args)
.ConfigureWebHostDefaults(webBuilder =>
{
webBuilder.UseStartup<Startup>();
})
//Borramos todos los registros de los loggers que vienen prerregistrados
.ConfigureLogging(logging =>
{
logging.ClearProviders();
logging.SetMinimumLevel(LogLevel.Debug);
})
//Añadimos Serilog obteniendo la configuración desde Microsoft.Extensions.Configuration
.UseSerilog((HostBuilderContext context, LoggerConfiguration loggerConfiguration) =>
{
loggerConfiguration.ReadFrom.Configuration(context.Configuration);
});
Et voilà!, ya tenemos listo nuestro Serilog trabajando por debajo de ILogger. Allá donde utilicemos ILogger realmente por debajo estaremos llamando a Serilog y con todas las configuraciones que le hayamos indicado.
Conclusión
Después de todo lo planteado, crear nuestros propios loggers debería ser algo que ni se nos pase por la cabeza. Al alcance de unos pocos clics tenemos la potencia de loggers tan completos como Serilog.
En esta entrada hemos planteado algunas de las principales opciones de Serilog, aunque no son ni mucho menos las únicas. Te recomiendo encarecidamente que, si no tienes costumbre de trabajar con herramientas como Serilog, Nlog u otros loggers, le eches un vistazo a la documentación de Serilog, ya que un mundo de posibilidades te está esperando.
Ahora que ya conoces lo interesante que puede resultar un sistema de logging como Serilog, seguramente te interesará también aprender a utilizarlo junto a Seq, un sistema de ingesta de logs que permite hacer analítica en tiempo real de los mismos.
Y tú, ¿conocías Serilog? ¿crees que puede ayudarte en el día a día de tus proyectos? Puedes dejarnos tus experiencias e impresiones en los comentarios.
Fecha de publicación: