Trazando peticiones y añadiendo logs en nuestra API asp.net

  • net-core
  • net
  • api
  • asp-net
  • audit
  • serilog
  • trace

En un post anterior explique cómo añadir trazas en nuestros registros de base de datos con Entity Framework. Estás trazas nos pueden ayudar en ciertas ocasiones, pero son insuficientes en un proyecto real en el que tengamos que tener unas trazas y logs más sofisticados.

En mis proyectos, suelo añadir, además de las citadas anteriormente, trazas de las peticiones y logs escritos en ciertos casos en los que me interesa incluir información interesante.

Este proceso de trazado es crucial para la depuración, el monitoreo del rendimiento y la seguridad.

  • Depuración: Cuando ocurre un error, las trazas nos ayudan a identificar rápidamente la causa.

  • Monitoreo de Rendimiento: El trazado nos permite observar el comportamiento de nuestra API en tiempo real y optimizarla.

  • Seguridad: Mantener un registro de todas las actividades ayuda en la detección de actividades sospechosas.

Esta implementación podría haberla hecho con una sola biblioteca, pero me gusta usar Audit.Net para el trazado de peticiones y Serilog para logs customizados.

Trazando peticiones con Audit.Net

Para este ejemplo he almacenado las trazas en una tabla de Azure, pero existen diversas extensiones para Audit.Net que nos permiten almacenar las trazas en distintos destinos, como pueden ser SQL Server, MySQL, Azure Storage Tables, Azure Storage Blobs, Elastic Search...

Una vez que hemos decidido nuestra opción de persistencia, estamos en condiciones de iniciar nuestro desarrollo.

El primer paso, es añadir los nugets que necesitamos.

  • Audit.WebApi.Core: Se trata de una extensión adaptada para proyectos de API. Se centra en la auditoría de interacciones registrando solicitudes/respuestas capturando detalles como cabeceras, cuerpo, información de ruta…

  • Audit.NET.AzureStorageTables: Facilita el almacenamiento de registros de auditoría en Azure Table Storage, que es un almacén de datos NoSQL, optimizado para almacenar grandes cantidades de datos estructurados no relacionales.

El siguiente paso, es configurar la información que deseamos almacenar de cada petición y respuestas. Esta configuración en el arranque de nuestra aplicación, en el Program.cs, aunque por limpieza he creado una clase nueva en la que realizo toda la configuración. En esta clase he creado dos métodos importantes, uno para definir que acciones se van a trazar y otro en el que configuro cómo se guardarán las trazas en la Azure Table.

public static void AuditSetupFilter(this MvcOptions mvcOptions)
{
    mvcOptions.AddAuditFilter(a => a
        .LogAllActions()
        .WithEventType("{controller} {action} {verb}")
        .IncludeModelState()
        .IncludeRequestBody()
        .IncludeResponseBody());
}
```csharp
Respecto al filtro anterior, la explicación de cada método es la siguiente:

- _LogAllActions_: Configura el filtro de auditoría para registrar todas las acciones. No obstante, hay acciones que se ignorará, pero en vez de configurarlo desde aquí lo he hecho añadiendo el decorador _AuditIgnore_ en los controladores o métodos que no queremos que dejen traza.

- _WithEventType("{controller} {action} {verb}")_: Configuración para usar un formato específico para el tipo de evento en los registros. El formato es una cadena de texto donde {controller}, {action} y {verb} serán reemplazados por el nombre del controlador, el nombre del método de acción y el verbo HTTP de la solicitud, respectivamente.

- _IncludeModelState_: Indica que se incluirá el estado del modelo en los registros. Ese estado representa los datos en una solicitud HTTP y su estado de validación.

- _IncludeRequestBody_: Indica que se tiene que añadir el cuerpo de la solicitud HTTP.

- _IncludeResponseBody_: Indica que se trazará el cuerpo de la respuesta HTTP.

El siguiente paso es configurar el volcado de nuestras trazas a un _Azure Table_.

\* Nótese que no es objetivo de este post explicamos como configurar dicho _Azure Table_

```csharp
public static void UseAudit(this WebApplication app, IConfiguration configuration)
{
    app.Use(async (context, next) =>
    {
        context.Request.EnableBuffering();
        await next();
    });

    app.UseAuditMiddleware(x => x
        .IncludeHeaders()
        .IncludeResponseHeaders()
        .IncludeRequestBody()
        .IncludeResponseBody()
    );

    app.AuditSetupAzureTableStorageOutput(configuration);
}

private static void AuditSetupAzureTableStorageOutput(this WebApplication app, IConfiguration configuration)
{
    var connectionString = configuration.GetValue<string>("Audit:ConnectionString");
    var tableName = configuration.GetValue<string>("Audit:TableName");

    Configuration.Setup()
        .UseAzureTableStorage(_ => _
            .ConnectionString(connectionString)
            .TableName(tableName)
            .EntityBuilder(e => e
                .PartitionKey(ev => $"{tableName}{ev.GetWebApiAuditAction().UserName}{ev.StartDate:yyyyMM}")
                .RowKey(_ => Guid.NewGuid().ToString())
                .Columns(c => c.FromObject(ev => new
                {
                    Date = ev.StartDate,
                    Controller = ev.GetWebApiAuditAction().ControllerName,
                    Action = ev.GetWebApiAuditAction().ActionName,
                    Method = ev.GetWebApiAuditAction().HttpMethod,
                    Result = ev.GetWebApiAuditAction().ResponseStatusCode,
                    AuditEventJson = ev.ToJson(),
                    ev.Duration,
                    ev.GetWebApiAuditAction()?.UserName,
                }))));
}

A continuación procedo a explicar algunos detalles importantes del código anterior.

  • context.Request.EnableBuffering(): Este método permite que el cuerpo de la solicitud HTTP se lea varias veces. Normalmente, el cuerpo de una solicitud HTTP sólo puede ser leído una vez, ya que se transmite como un flujo de datos. Sin embargo, para la auditoría, es necesario leer el cuerpo de la solicitud varias veces (una vez para procesar la solicitud y otra vez para registrarla). Por lo tanto, se habilita el almacenamiento en búfer para permitir esto.

  • AuditSetupAzureTableStorageOutput: Aquí es donde se configura Audit.Net para usar Azure Table Storage como proveedor de almacenamiento. Para ello se incluye la cadena de conexión a nuestro Azure Table y el nombre de la tabla.
    Además, definimos la calve de partición de la tabla, agrupando por acción, nombre de usuario, año y mes.
    Por otro lado, utilizamos un guid para definir el identificador y definimos las columnas para guardar fecha, nombre del controlador, acción, método, resultado, duración, nombre de usuario y el json con toda la información que le dijimos a Audit.Net que guardase.

Como hemos visto, cierta información se extrae del IConfiguration, por lo que es necesario completar nuestro appsettings.json para incluirla.

"Audit": {
  "ConnectionString": "YOUR_AZURE_TABLE_CONNECTION_STRING",
  "TableName": "YOUR_AZURE_TABLE_NAME"
}
```csharp
Por último, faltaría llamar a los métodos creados desde nuestro _Program.cs_

```csharp
var builder = WebApplication.CreateBuilder(args);
...
builder.Services.AddControllers(x => x.AuditSetupFilter(builder.Configuration));
...
var app = builder.Build();
...
app.MapControllers();
app.UseAudit(builder.Configuration);
app.UseExceptionHandler();
...
app.Run();

Es importante anotar que si tenemos algún middleware que modifica la respuesta de una llamada, como puede ser un rate limiter o un global exception handler, debemos tener en cuenta el orden en el que posicionamos el UseAudit para que se trace la respuesta antes o después de ser procesada por estos middlewares.

Con todo lo anterior, estamos en condiciones de lanzar peticiones y observar las trazas que quedan en nuestro Azure Table.

En mi caso, he utilizado Microsoft Azure Storage Explorer para el visionado de estas tablas.

Notese, que tal y como se comentó anteriormente, si no queremos que alguna acción sea trazada bastaría con añadir el atributo AuditIgnore.

[AuditIgnore]
public async Task<IActionResult> DoSomethingAsync(CancellationToken cancellationToken = default)
{
    // ...
}
```csharp
## Añadiendo logs con Serilog

Con el punto anterior, hemos conseguido trazar todas las peticiones y respuestas que se producen en nuestra API, pero hay veces que queremos dejar una traza en algunos puntos de nuestro código, para ayudarnos a encontrar un posible error o para saber por qué una acción ha hecho lo que ha hecho. Para estos casos me gusta utilizar _Serilog_.

Al igual que _Audit.Net_, las trazas se pueden almacenar en muchos destinos, como _Application Insights, Azure Analytics, Amazon CloudWatch, Azure CosmosDB, PostgreSQL, SQL Server..._

Como sucede siempre que utilizamos una librería externa, el primer paso es añadir los _nuget_ que vamos a necesitar. Estos son _Serilog.AspNetCore_ y _Serilog.Sinks.AzureTableStorage_. El segundo paquete es necesario porque vamos a volcar los logs a un _Azure Table_. Si el destino fuese otro, tendríamos que usar el _nuget_ correspondiente. Por ejemplo, _Serilog.Sinks.ApplicationInsights_ si queremos almacenarlas en _Application Insights._

Como es habitual, la configuración de la librería se hace al inicio de nuestra aplicación, desde el _Program.cs_.

```csharp
Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
    .Enrich.FromLogContext()
    .WriteTo.AzureTableStorage(
        builder.Configuration["SerilogLog:ConnectionString"],
        storageTableName: builder.Configuration["SerilogLog:TableName"],
        propertyColumns: new[] { "SourceContext", "RequestId", "RequestPath", "ConnectionId" })
    .CreateLogger();

Respecto al código anterior podemos destacar los siguientes puntos:

  • MinimumLevel.Override(“Microsoft”, LogEventLevel.Warning): Establece el nivel mínimo de registro para los eventos de log de la categoría “Microsoft” en “Warning”. Esto significa que solo los eventos de log de nivel “Warning” o superior (Error, Fatal) serán registrados.

  • Enrich.FromLogContext(): Lo utilizamos para enriquecer los logs con las propiedades del contexto, lo que nos permite incluir detalles como el ID de la solicitud, el nombre del usuario, etc

  • WriteTo.AzureTableStorage: Configura el logger para escribir los eventos en Azure Table.

Tenemos que tener en cuenta que podemos tener a la vez varios destinos en los que se guarden los logs. Por ejemplo, podemos indicar que, además de en un Azure Table, las trazas se muestren en consola.

Log.Logger = new LoggerConfiguration()    .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)    .Enrich.FromLogContext()    .WriteTo.Console(outputTemplate: "{Timestamp:HH:mm:ss.fff} [{Level:u1}] {Message:lj}{NewLine}{Exception}")    .WriteTo.AzureTableStorage(        builder.Configuration["SerilogLog:ConnectionString"],         storageTableName: builder.Configuration["SerilogLog:TableName"],        propertyColumns: new[] { "SourceContext", "RequestId", "RequestPath", "ConnectionId" })    .CreateLogger();

Vemos que para realizar la configuración hay valores que se toman de IConfiguration, por lo que tenemos que incluirlos en el appsettings.

"SerilogLog": {    "ConnectionString": "",    "TableName": ""}

Una vez configurado, faltaría indicar al builder que user serilog.

builder.UseSerilog();

En este punto ya estamos en disposición de escribir logs. Para ello, basta con inyectar ILogger en la clase que deseemos usarlo y utilizar los métodos que nos ofrece en función del nivel de la traza que queramos dejar, LogCritical, LogError, LogWarning, LogInformation, LogTrace y LogDebug.

Por último, vamos a ver el contenido de la tabla de azure en la que estamos dejando las trazas.

Talk is cheap, show me the code

En este caso, os dejo un enlace a un repo en el que implemento distintas funcionalidades de asp.net, entre ellas todas las expuestas en este post. https://github.com/jorgediegocrespo/TasksWebApi