DEV Community

Cover image for [Parte 9] ASP.NET Core: Logging con Serilog
Isaac Ojeda
Isaac Ojeda

Posted on

[Parte 9] ASP.NET Core: Logging con Serilog

¿Qué es el Logging?

El Logging son bitácoras del comportamiento del sistema que se persisten en algún lado o se pueden visualizar en alguna interfaz.

No suele darse importancia al logging, pero cuando los problemas comienzan a salir en un sistema en producción, lo primero a lo que recurres son los logs. Tener logs bien estructurados y con información útil, suelen salvar el trasero de muchos.

El logging tiene muchos propósitos, pero principalmente nos ayuda a investigar las causas raíces de los problemas que suceden en el sistema, analizar bugs y revisar problemas de rendimiento y hasta para auditar un sistema.

ASP.NET Core ya cuenta con un sistema de logging el cual por default está configurado para mandar logs a consola, a event logs de windows y entre otros (esto se configura por default en el HostBuilder). Pero, para irnos más lejos de solo logs en consola, se necesita más configuración y esfuerzo.

Para esto viene Serilog, es una herramienta que nos ayuda a no reinventar la rueda.

El código siempre lo encontrarás en mi GitHub.

¿Qué es Serilog?

Serilog es una herramienta que nos permite hacer logs para diagnostico que se pueden guardar en archivos, mostrarse en consola y muchas otras opciones. Es muy fácil de configurar y tiene una API muy limpia y se puede usar en distintas versiones de .NET sin problemas.

A diferencia de otras librerías, los parámetros pasados en los logs no son "convertidos" a texto, sino que su estructura es conservada y nos permite ver de forma muy efectiva los valores de los objetos y dependiendo en donde guardamos los logs, podremos conservar sus estructuras e incluso hacer búsquedas.

No se hace log de texto, se hace log de datos.

Para sacar jugo de Serilog, debemos de usar message templates, esto implica no solo concatenar texto (de hecho, no debes de concatenar strings al hacer logs).

Nota 👀: Este vídeo explica lo que acabo de decir ☝🏽.

Un message template podría ser de esta forma:

var input = new { Latitude = 25, Longitude = 134 };
var time = 34;

log.Information("Processed {@SensorInput} in {TimeMS:000} ms.", input, time);
Enter fullscreen mode Exit fullscreen mode

Obtendremos este resultado en consola:

09:14:22 [Information] Processed { Latitude: 25, Longitude: 134 } in 034 ms. 
Enter fullscreen mode Exit fullscreen mode

El operador @ que está en SensorInput le dice a Serilog que mantenga la estructura del objeto que se pasa ahí. Si esto es omitido, serilog mandará a llamar el método ToString() para mostrar el valor de dicho objeto.

Este ejemplo cuenta con dos propiedades, SensorInput y TimeMS. Estos se guardarán en el log event y no solo como un texto que vemos en la consola.

Las propiedades capturadas, en formato JSON se podrán visualizar así:

{ "SensorInput": { "Latitude": 25, "Longitude": 134 }, "TimeMS": 34 }
Enter fullscreen mode Exit fullscreen mode

Sinks

La segunda cosa importante de utilizar Serilog, son los Sinks. Los sinks son aquellos lugares en donde podemos decirle a Serilog que guarde los logs. Pueden ser archivos en JSON, pueden ser registros en una base de datos, eventos en un Application Insights (este 👍🏽) y entre muchas cosas.

Por eso es importante usar Message Templates porque tal vez en consola no podemos ver mucha información, pero cuando se guarda la información en un lugar como Elastic Search, podemos hacer búsquedas por usuario, por tipo de operación que hizo y entre otros.

Serilog también es una alternativa al uso de Audit.NET que expliqué en otro post. La idea es aprender de las alternativas que tenemos al usar ASP.NET.

Guardar los logs en un Application Insights es super útil, ya que AI te ayuda a agrupar los logs según los requests y operaciones que se hacen en tu Web API. Hacer el tracing de esa información es super útil al estar diagnosticando tu aplicación cuando falla o tiene problemas de rendimiento.

Un ejemplo de cómo se ve un log generado con Serilog y mandado a Application Insights:

Image description

Puse en rojo mi Message template, pero a Serilog le indiqué que agregué más propiedades al Log Event. Aunque yo no los vea en consola, en los Sinks los podremos ver.

Configurando Serilog en MediatRExample

Como lo puedes ver, esta es la parte 9 de una serie de publicaciones. Todo enfocado a ASP.NET Core y temas que considero, todos deberíamos saber.

Primero, empezaremos instalando Serilog para ASP.NET Core en Web API:

dotnet add package Serilog.AspNetCore
Enter fullscreen mode Exit fullscreen mode

Por default, aquí vendrá incluido el Sink para mandar los logs a consola, pero si necesitas cualquier Sink diferente, deberás buscar en Github como configurarlo.

Agregando Serilog a Program.cs

La configuración es muy sencilla, porque se integrará totalmente con ILogger<T> que ya hemos estado usando todo el tiempo. Solo en Program.cs hacemos lo siguiente:

// ... código omitido
var builder = WebApplication.CreateBuilder(args);

builder.Host.UseSerilog();

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
    .Enrich.FromLogContext()
    .WriteTo.Console()
    .CreateLogger();

// ... código omitido

try
{
    Log.Information("Iniciando Web API");

    await SeedProducts();

    Log.Information("Corriendo en:");
    Log.Information("https://localhost:7113");
    Log.Information("http://localhost:5144");

    app.Run();

}
catch (Exception ex)
{
    Log.Fatal(ex, "Host terminated unexpectedly");

    return;
}
finally
{
    Log.CloseAndFlush();
}

// ... código omitido
Enter fullscreen mode Exit fullscreen mode

Aquí la sección "Log" de appsettings.json la podemos borrar, ya que no se usará.

El Message Template que tengo en el AuditLogBehavior es:

_logger.LogInformation("{RequetsName}: {@User} with request {@Request}", typeof(TRequest).Name, _currentUserService.User.Id, request);
Enter fullscreen mode Exit fullscreen mode

Y al correr la aplicación, se verá de la siguiente manera:

Image description
Y si queremos guardar los logs en un archivo en el mismo Web Server (que sirve como para consultarlos en tiempo real si usamos Azure), hacemos lo siguiente en Program.cs:

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
    .Enrich.FromLogContext()
    .WriteTo.Console()
    .WriteTo.File("log.txt", rollingInterval: RollingInterval.Day)  // <-------
    .CreateLogger();
Enter fullscreen mode Exit fullscreen mode

Con esto, si corremos la aplicación, se crearán archivos txt con el nombre log{yyyyMMdd}.txt en la raiz del proyecto y con el siguiente contenido:

2022-04-14 10:42:31.447 -06:00 [INF] Iniciando Web API
2022-04-14 10:42:32.417 -06:00 [INF] Corriendo en:
2022-04-14 10:42:32.420 -06:00 [INF] https://localhost:7113
2022-04-14 10:42:32.422 -06:00 [INF] http://localhost:5144
2022-04-14 10:42:34.539 -06:00 [INF] CreateProductCommand: 759aa503-f916-4962-96ed-be0b416b5632 with request {"Description":"New Product","Price":9952,"$type":"CreateProductCommand"}
2022-04-14 10:42:35.738 -06:00 [INF] CreateProductCommand: 759aa503-f916-4962-96ed-be0b416b5632 with request {"Description":"New Product","Price":9952,"$type":"CreateProductCommand"}
2022-04-14 10:42:36.893 -06:00 [INF] CreateProductCommand: 759aa503-f916-4962-96ed-be0b416b5632 with request {"Description":"New Product","Price":9952,"$type":"CreateProductCommand"}
2022-04-14 10:42:37.547 -06:00 [INF] CreateProductCommand: 759aa503-f916-4962-96ed-be0b416b5632 with request {"Description":"New Product","Price":9952,"$type":"CreateProductCommand"}
2022-04-14 10:42:38.342 -06:00 [INF] CreateProductCommand: 759aa503-f916-4962-96ed-be0b416b5632 with request {"Description":"New Product","Price":9952,"$type":"CreateProductCommand"}
2022-04-14 10:42:38.839 -06:00 [INF] CreateProductCommand: 759aa503-f916-4962-96ed-be0b416b5632 with request {"Description":"New Product","Price":9952,"$type":"CreateProductCommand"}
2022-04-14 10:42:39.234 -06:00 [INF] CreateProductCommand: 759aa503-f916-4962-96ed-be0b416b5632 with request {"Description":"New Product","Price":9952,"$type":"CreateProductCommand"}

Enter fullscreen mode Exit fullscreen mode

WriteTo.File tiene más opciones de configuración. Les recuerdo, hay Sinks para todo tipo de persistencia.

Y te preguntarás al final, ¿para qué sirve todo esto? La respuesta corta es: Diagnosticar. Cuando algo pasa en tu aplicación, sabes aproximadamente cuando sucedió, lo único que puedes hacer es ir a ver los logs y revisar que hizo el usuario para que tronara la aplicación.

El sink de archivos es algo útil, pero es más útil si usamos sinks como de Elastic Search o Application Insights. Permitir búsqueda y hacer Tracing de los Requests de tu aplicación es un sí o sí que debes de tener en producción.

Nota 👀: Puedes visitar Github para ver todos los sinks disponibles.

Conclusión

El Logging y Tracing son temas que nos deben de interesar. Aunque solo hemos visto como crear Logs y mandarlos a un Sink de archivos y a Consola, de aquí puedes investigar más y revisar que cumple las necesidades de tu proyecto.

Como siempre, cualquier pregunta, no dudes en buscarme en mi twitter en @balunatic.

👋🏽

Referencias

Discussion (0)