Logging estructurado en producción: por qué NLog cambió el diagnóstico de incidencias

La primera vez que tuve que reconstruir una incidencia nocturna con un archivo de log lleno de frases sueltas en texto plano, entendí la diferencia entre loguear y poder diagnosticar. Tenía la prueba de que algo había pasado. No tenía forma de preguntarle nada al log: ni filtrar por dispositivo, ni por lote, ni correlacionar dos líneas que pertenecían al mismo incidente pero estaban escritas por hilos distintos, con formato distinto, sin ningún campo en común más que la marca de tiempo aproximada.

Ese fue el punto de partida para introducir logging estructurado con NLog en un proyecto real. No fue una migración de «cambiar de librería»; fue cambiar qué pregunta le puedes hacer a la aplicación después de que algo salga mal.

Loguear no es diagnosticar

Un logger.LogInformation($"Procesado dispositivo {deviceId}") con interpolación de cadena te da una frase legible por un humano en el momento en que la escribes. Lo que no te da es un dato que puedas consultar: deviceId queda enterrado dentro de un string, no como un campo independiente. Si mañana necesitas todas las líneas de un dispositivo concreto, tu única herramienta es una búsqueda de texto y cruzar los dedos con el formato.

El cambio fue tan simple de enunciar como incómodo de aplicar en todo el código existente: usar siempre parámetros con nombre en el mensaje de log, nunca interpolación de cadena, y dejar que el motor de logging decida cómo serializar cada campo.

var builder = WebApplication.CreateBuilder(args);

builder.Logging.ClearProviders();
builder.Host.UseNLog();

builder.Services.Configure<DeviceEventOptions>(
    builder.Configuration.GetSection("DeviceEvents"));

var app = builder.Build();

Con NLog conectado a través de Microsoft.Extensions.Logging, cada log escrito con {NombreDeCampo} en el mensaje deja de ser solo texto: se convierte en un evento con propiedades propias que el target de NLog —archivo, base de datos, o el sistema de recolección que toque en cada entorno— puede escribir en un formato consultable, típicamente JSON.

Qué decidí loguear

No todo merece un log, y decidir qué sí fue tan importante como decidir cómo. Los criterios que usé, en orden:

• Todo cambio de estado de negocio relevante, con el identificador del recurso afectado como campo propio, no como texto libre. Si un dispositivo pasa de activo a descartado, ese evento lleva su DeviceId como parámetro.
• Todo punto donde el sistema descarta algo silenciosamente por diseño —un evento fuera de ventana, un registro duplicado— porque si nadie lo ve en el log, nadie sabe que está pasando hasta que alguien pregunta por qué faltan datos.
• Los límites de un lote o una operación por lotes: cuántos se procesaron, cuántos se descartaron y por qué, al principio y al final de la operación, no solo al final.

Para que ese tercer punto no costara una llamada a LogInformation mal escrita cada vez, definí los mensajes de log de dominio como métodos generados con LoggerMessage, que además evitan el coste de formatear el string cuando el nivel de log está desactivado:

public static partial class DeviceEventLog
{
    [LoggerMessage(
        EventId = 1001,
        Level = LogLevel.Warning,
        Message = "Evento de dispositivo {DeviceId} descartado: {Reason}. Lote {BatchId}")]
    public static partial void EventDiscarded(
        ILogger logger, string deviceId, string reason, Guid batchId);

    [LoggerMessage(
        EventId = 1002,
        Level = LogLevel.Information,
        Message = "Lote {BatchId} procesado: {ProcessedCount} eventos, {DiscardedCount} descartados")]
    public static partial void BatchProcessed(
        ILogger logger, Guid batchId, int processedCount, int discardedCount);
}

El EventId no es cosmético tampoco. Con un identificador numérico fijo por tipo de evento, buscar «todas las veces que se ha descartado un evento de dispositivo en el último mes» deja de depender de que el texto del mensaje no haya cambiado entre versiones.

Qué decidí no loguear

Tan importante como la lista anterior es lo que se quedó fuera, por dos razones distintas.

Datos que no aportan al diagnóstico y sí aportan ruido. Loguear cada iteración de un bucle interno, o cada llamada a un método auxiliar sin significado de negocio propio, no ayuda a reconstruir una incidencia: la entierra bajo volumen. Si el log de un incidente real tiene que competir con miles de líneas irrelevantes del mismo minuto, el log ha dejado de servir para lo que se supone que sirve.

Datos sensibles o identificativos que no hacen falta para diagnosticar. Ningún dato personal de cliente final, ninguna credencial, ningún token, entraba en un campo de log, estructurado o no. Si el diagnóstico necesitaba relacionar un evento con un cliente concreto, se hacía con un identificador interno, nunca con el dato en crudo. Es una decisión que cuesta un poco de indirección extra en el código y que no es negociable.

Para relacionar eventos que pertenecen al mismo flujo sin repetir el mismo campo en cada llamada a LogInformation, usé el ámbito (scope) de ILogger para adjuntar campos comunes —el identificador del lote, el número de eventos del lote— a todas las líneas escritas dentro de ese bloque, sin tener que pasarlos explícitamente a cada llamada de log:

public sealed class DeviceEventProcessor(
    IDeviceEventRepository repository,
    ILogger<DeviceEventProcessor> logger)
{
    public async Task ProcessBatchAsync(DeviceEventBatch batch, CancellationToken cancellationToken)
    {
        using var scope = logger.BeginScope(new Dictionary<string, object>
        {
            ["BatchId"] = batch.Id,
            ["DeviceCount"] = batch.Events.Count
        });

        var processed = 0;
        var discarded = 0;

        foreach (var evt in batch.Events)
        {
            if (evt.Timestamp < DateTimeOffset.UtcNow.AddDays(-7))
            {
                DeviceEventLog.EventDiscarded(logger, evt.DeviceId, "evento fuera de ventana de retención", batch.Id);
                discarded++;
                continue;
            }

            await repository.AppendAsync(evt, cancellationToken);
            processed++;
        }

        DeviceEventLog.BatchProcessed(logger, batch.Id, processed, discarded);
    }
}

Todo lo que se escribe dentro de ese using hereda BatchId y DeviceCount como campos propios, sin que cada línea de log tenga que repetirlos. Cuando el target de NLog escribe en JSON, esos campos de scope quedan en el mismo objeto que el resto del evento, así que una consulta por BatchId te trae todo lo que pasó en ese lote, en el orden en que pasó, con el contexto completo.

Logging estructurado con NLog: cómo medí que sirvió

No tengo una cifra que enseñar de cuánto bajó el tiempo de diagnóstico, y prefiero decirlo así a inventar un porcentaje que suene bien. Lo que sí puedo decir, con evidencia directa de cómo cambió el trabajo diario: antes de esto, reconstruir una incidencia dependía casi siempre de pedirle al cliente una captura de pantalla o una descripción de lo que había visto, porque el log no daba suficiente información por sí solo. Después, la pregunta habitual pasó a ser «dame el BatchId o el DeviceId aproximado» y con eso bastaba para reconstruir la secuencia completa de eventos sin depender de la memoria de nadie.

Esa es la prueba real de que loguear y diagnosticar son cosas distintas: el día en que dejas de necesitar preguntarle al usuario qué vio, porque el sistema ya te lo cuenta con sus propios campos estructurados, es el día en que el logging ha dejado de ser un archivo de texto y ha empezado a ser una herramienta de diagnóstico. Es el mismo criterio que aplico en despliegue y DevOps en Azure, donde dejo monitorización activa en producción para detectar el problema antes de que lo note el usuario.