Il logging in ASP.NET Core: scrivere log che si possono cercare

Nell’articolo sulle metriche i log erano il primo dei tre segnali: un evento alla volta, con tutti i dettagli. In quello sulle trace tornavano alla fine: ILogger registra il trace id, e da una trace si arriva ai log della stessa richiesta. E nell’articolo sulla gestione delle eccezioni il middleware scriveva un errore nel log. Mancavano le basi: come si scrive un log, con quale livello, e dove finisce.

È il segnale che si scrive più spesso, e spesso alla svelta: una stringa interpolata, un LogError in ogni catch, tutto a Information. Funziona finché i log si leggono a occhio, sul terminale. Quando diventano milioni di righe in uno strumento, servono log che si possono cercare.

Gli esempi usano il modulo di firma digitale del solito documentale inventato, DocumentaleInventato.

Come funziona: chi scrive e chi raccoglie

Lo schema è quello delle metriche e delle trace. Il codice scrive con ILogger, l’API di Microsoft.Extensions.Logging; i provider decidono dove vanno i log. WebApplication.CreateBuilder ne registra quattro: la console, il debugger, EventSource (per strumenti come dotnet-trace) e, solo su Windows, il registro eventi.

Ogni log porta con sé:

1. Un log, con il template

Il caso d’uso che registra una richiesta di firma:

public sealed class RichiediFirma(IFirme firme, ILogger<RichiediFirma> logger)
{
    public async Task<Guid> ExecuteAsync(Guid documentoId, CancellationToken ct)
    {
        var firmaId = await firme.CreaAsync(documentoId, ct);

        logger.LogInformation(
            "Firma {FirmaId} richiesta per il documento {DocumentoId}",
            firmaId, documentoId);

        return firmaId;
    }
}

ILogger<RichiediFirma> arriva dalla dependency injection, già registrato. Sulla console:

info: DocumentaleInventato.Firma.RichiediFirma[0]
      Firma 7f3a2c10… richiesta per il documento 3f2a9d4e…

Prima il livello, poi la categoria e, tra parentesi quadre, l’event id.

I messaggi sono in italiano per restare leggibili come il resto degli esempi. Nei progetti, come il codice, di solito si scrivono in inglese.

Template, non interpolazione

In produzione i log non si leggono riga per riga: finiscono in uno strumento che li raccoglie, e lì si interrogano. Arriva una segnalazione: la firma del documento 3f2a9d4e… è rimasta a metà. Le domande sono “quali log riguardano quel documento?” e, subito dopo, per capire se il problema è più ampio, “quante firme sono state richieste oggi?”.

Per rispondere bene, l’id del documento non può stare solo dentro una frase: deve essere un campo del log, come una colonna in una tabella, su cui filtrare e contare. È questo lo scopo del template.

Il testo che passi a LogInformation sembra una stringa da formattare, ma {FirmaId} e {DocumentoId} non sono interpolazione: sono i segnaposto di un template. Il logger riceve il template così com’è e, separati, i due valori, ognuno con il nome del suo segnaposto. Sono quei valori a diventare i campi. Il testo completo il logger lo compone solo quando deve mostrarlo.

Sulla console normale la differenza non si vede: il testo è identico. Si vede con la console in formato JSON, che scrive tutto quello che il logger ha ricevuto:

"Message": "Firma 7f3a2c10… richiesta per il documento 3f2a9d4e…",
"State": {
  "FirmaId": "7f3a2c10-5b8e-4d21-9a6f-0c4e8b1d2a77",
  "DocumentoId": "3f2a9d4e-1c7b-4e05-8f36-2b9a6d0c5e18",
  "{OriginalFormat}": "Firma {FirmaId} richiesta per il documento {DocumentoId}"
}

Message è il testo composto. In State ci sono i valori, uno per segnaposto, e in {OriginalFormat} il template di partenza.

Ora lo stesso log scritto con l’interpolazione:

logger.LogInformation(
    $"Firma {firmaId} richiesta per il documento {documentoId}");

Qui la stringa viene composta prima di chiamare il logger, che riceve solo il testo finito. Message è uguale a prima, ma in State non ci sono più valori, e al posto del template c’è il testo stesso:

"State": {
  "{OriginalFormat}": "Firma 7f3a2c10… richiesta per il documento 3f2a9d4e…"
}

Tornando alla segnalazione:

• “Quali log riguardano il documento 3f2a9d4e…?” Con il template filtri sul campo DocumentoId e trovi i log in cui quel valore è proprio il documento. Con l’interpolazione cerchi il testo 3f2a9d4e dentro i messaggi, e trovi anche le righe in cui quell’id compare per altri motivi.
• “Quante firme sono state richieste oggi?” Con il template conti i log con quel {OriginalFormat}, che è lo stesso per tutte le richieste. Con l’interpolazione ogni richiesta ha un testo diverso, e per contarle serve una ricerca che riconosca la frase.

Con il template ogni log è un record con dei campi; con l’interpolazione è una riga di testo.

Tre regole:

• I segnaposto si abbinano ai valori per posizione: il primo valore va nel primo segnaposto, qualunque nome abbia. Il nome decide come si chiamerà il campo.
• Lo stesso dato ha sempre lo stesso nome: DocumentoId in tutti i log, non DocId in uno e IdDocumento in un altro, o il filtro ne trova solo una parte. I nomi vanno in PascalCase.
• Il template è una costante. L’analizzatore CA2254 segnala interpolazione e concatenazione, ma di default solo come suggerimento nell’editor: in compilazione non compare.

I livelli

Il criterio per Error: deve valere la pena che qualcuno lo guardi. Un documento che non esiste, chiesto dal client, non è un errore del server: come il 404 dell’articolo sulle eccezioni, al massimo è un Information.

2. Scegliere cosa scrivere

Il livello minimo si imposta in configurazione, per categoria. È quello che c’è nell’appsettings.json di un progetto nuovo:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft.AspNetCore": "Warning"
    }
  }
}

La categoria vale come prefisso: Microsoft.AspNetCore copre Microsoft.AspNetCore.Routing.EndpointMiddleware, Microsoft.AspNetCore.Hosting.Diagnostics e tutte le altre che cominciano così. Vince la regola con il prefisso più lungo; Default vale per il resto.

Quel Warning non è un dettaglio. Con Information, ASP.NET Core scrive quattro righe sue per ogni richiesta, intorno alla nostra:

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 POST http://…/signatures?documento=3f2a9d4e… - - 0
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'HTTP: POST /signatures'
info: DocumentaleInventato.Firma.RichiediFirma[0]
      Firma 7f3a2c10… richiesta per il documento 3f2a9d4e…
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'HTTP: POST /signatures'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 POST http://…/signatures?documento=3f2a9d4e… - 200 - application/json;+charset=utf-8 11.7336ms

Cinque righe dove ne serviva una. Un log costa in proporzione al traffico, e quante richieste arrivano e quanto durano lo dice già la metrica http.server.request.duration, senza una riga per richiesta.

Per indagare su una parte sola si alza il livello di quella categoria, non di tutto:

"LogLevel": {
  "Default": "Information",
  "Microsoft.AspNetCore": "Warning",
  "DocumentaleInventato.Firma": "Debug"
}

E non serve ripartire: appsettings.json viene riletto quando cambia, e gli ILogger già creati applicano subito i nuovi livelli.

Un livello si può anche dare a un provider solo, in una sezione con il suo nome: con "Console": { "LogLevel": { "Default": "Warning" } } la console mostra solo avvisi ed errori, mentre gli altri provider seguono le regole generali.

3. Il contesto: gli scope

Un log da solo dice cosa è successo, non durante quale operazione. La firma passa da più classi, e ripetere {FirmaId} in ogni messaggio è scomodo e facile da dimenticare. Uno scope lo aggiunge a tutti i log scritti finché resta aperto:

public async Task ExecuteAsync(Guid firmaId, CancellationToken ct)
{
    using var scope = logger.BeginScope("Firma {FirmaId}", firmaId);

    logger.LogDebug("Invio al provider {Provider}", "aruba");
    await provider.FirmaAsync(firmaId, ct);
    logger.LogInformation("Firma completata");
}

Lo scope segue il flusso asincrono, come Activity.Current: vale anche per i log che scrive provider.FirmaAsync, in un’altra classe con un altro ILogger.

Di default gli scope non si vedono: la console li mostra con IncludeScopes, tra le opzioni del suo formato.

"Logging": {
  "Console": {
    "FormatterName": "simple",
    "FormatterOptions": { "IncludeScopes": true }
  }
}

Molti esempi usano ancora "Console": { "IncludeScopes": true }, un’opzione deprecata. Funziona solo con il formato di default, senza FormatterName: con il JSON viene ignorata, senza avvisi.

E qui c’è una sorpresa: gli scope sono già più di uno. Il log Firma completata, in JSON, con i soli campi che contano:

"Message": "Firma completata",
"Scopes": [
  {
    "TraceId": "0af7651916cd43dd8448eb211c80319c",
    "SpanId": "ec97b056a8eee06d",
    "ParentId": "b7ad6b7169203331"
  },
  { "ConnectionId": "0HNPE01KNR265" },
  {
    "RequestId": "0HNPE01KNR265:00000001",
    "RequestPath": "/signatures/7f3a2c10…/esegui"
  },
  { "FirmaId": "7f3a2c10-5b8e-4d21-9a6f-0c4e8b1d2a77" }
]

I primi tre li apre ASP.NET Core, per ogni richiesta. Il TraceId è quello dell’Activity corrente: questa richiesta arrivava con il traceparent dell’articolo sulle trace, 00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01, e il log ne riporta il trace id, con lo span id del chiamante in ParentId. Lo stesso trace id compare nel traceId di una risposta Problem Details.

Il trace id c’è anche senza OpenTelemetry. ASP.NET Core crea un’Activity per ogni richiesta quando c’è qualcuno che ascolta, e il logging attivo basta. Così due log della stessa richiesta hanno sempre lo stesso TraceId, anche se li hanno scritti classi diverse.

Le eccezioni, una volta sola

Un log di livello Error dice che qualcosa si è rotto, e di solito qualcuno lo conta: un allarme che scatta oltre una soglia, un grafico degli errori al minuto. Perché quei numeri dicano il vero, ogni guasto deve produrre un errore solo nel log, non due o tre. Ed è facile, senza accorgersene, scriverlo più volte.

Prima il come. L’eccezione si passa come primo argomento, non dentro il messaggio:

logger.LogError(ex, "Firma non riuscita");

Così il log ha un campo a parte con tipo, messaggio e stack trace. Con {ex.Message} nel template resterebbe solo il messaggio.

Poi il quante volte. Questo catch sembra prudente:

try
{
    await provider.FirmaAsync(firmaId, ct);
}
catch (Exception ex)
{
    logger.LogError(ex, "Firma non riuscita");
    throw;
}

Scrive l’errore e rilancia l’eccezione. Ma un’eccezione rilanciata continua a salire, e in cima alla richiesta c’è il middleware dell’articolo sulle eccezioni, che scrive nel log ogni eccezione arrivata fin lì e non gestita da un IExceptionHandler. Il risultato, per un solo 503 del provider:

fail: DocumentaleInventato.Firma.EseguiFirme[0]
      Firma non riuscita
      System.Net.Http.HttpRequestException: Il provider di firma ha risposto 503.
         at …
fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
      An unhandled exception has occurred while executing the request.
      System.Net.Http.HttpRequestException: Il provider di firma ha risposto 503.
         at …

Due errori, con lo stesso stack trace, per un guasto solo: l’allarme conta il doppio, e chi legge non sa se i problemi sono uno o due. Senza UseExceptionHandler non cambia niente: il secondo errore lo scrive Kestrel.

La regola è: l’eccezione la scrive chi la gestisce, cioè chi la ferma e decide cosa succede dopo. Chi la rilancia non l’ha gestita, e la lascia scrivere a chi sta sopra. In pratica:

Per questo EseguiFirme, nella sezione sugli scope, non ha nessun catch. L’errore del middleware ha TraceId e RequestPath, ma non FirmaId: lo scope si è chiuso quando l’eccezione è uscita dallo using. Non si perde niente, però: il TraceId è lo stesso degli altri log della richiesta, quelli che FirmaId ce l’hanno, e da lì si risale alla firma.

Infine, non tutte le eccezioni sono errori. Una richiesta annullata dal client arriva come OperationCanceledException, e scriverla come Error vorrebbe dire far scattare l’allarme per un utente che ha chiuso la pagina. Il filtro when dell’articolo sul CancellationToken serve anche a questo.

4. Quando il log costa

Un log a un livello spento non viene scritto, ma la chiamata qualcosa costa lo stesso. Gli argomenti vengono preparati prima di chiamare il metodo, e il metodo non sa ancora se li userà. La memoria allocata per chiamata, con Debug spento:

I numeri sono di .NET 10 a 64 bit, per questo messaggio. Quelli del template restano uguali finché gli argomenti sono due, di questi tipi. Quello dell’interpolazione è la stringa composta, 40 caratteri qui, e cresce con il testo: circa 2 byte per carattere.

L’interpolazione compone la stringa anche se nessuno la leggerà. Il template no, ma passa i valori in un array di object, e durata, un long, va in boxing. Pochi byte, che contano nel codice che gira spesso: un ciclo, un worker, un endpoint con molto traffico.

[LoggerMessage] sposta il lavoro in compilazione. Si scrive la firma del metodo, e un source generator scrive il corpo:

internal static partial class FirmaLog
{
    [LoggerMessage(Level = LogLevel.Information,
        Message = "Firma {FirmaId} richiesta per il documento {DocumentoId}")]
    public static partial void FirmaRichiesta(
        this ILogger logger, Guid firmaId, Guid documentoId);

    [LoggerMessage(Level = LogLevel.Debug,
        Message = "Il provider {Provider} ha risposto in {Durata} ms")]
    public static partial void RispostaProvider(
        this ILogger logger, string provider, long durata);
}

E nel caso d’uso:

logger.FirmaRichiesta(firmaId, documentoId);

Il metodo generato controlla il livello prima di tutto, riceve i valori con il loro tipo, senza array né boxing, e il template lo analizza una volta sola. Il log che esce è lo stesso, con gli stessi campi. Cambia l’event id: senza EventId nell’attributo, il generatore ne ricava uno dal nome del metodo, e ogni tipo di messaggio ha il suo numero.

È la stessa idea della classe OrderMetrics nell’articolo sulle metriche: il resto del codice chiama metodi che dicono cosa è successo, e i messaggi stanno tutti in un posto.

Un limite: gli argomenti li calcola chi chiama, prima del controllo sul livello. Se calcolarli costa, per esempio serializzare un oggetto, serve comunque logger.IsEnabled. È quello che segnala l’analizzatore CA1873, anche lui come suggerimento.

Non serve convertire tutti i log. Il template va bene quasi ovunque; i metodi generati valgono dove si scrive spesso, o dove fa comodo avere tutti i messaggi in un catalogo.

5. Dove finiscono

In un container, la piattaforma (Kubernetes, Azure Container Apps) raccoglie quello che l’app scrive sulla console. Il formato di default va su più righe per ogni log, e chi legge una riga alla volta lo spezza. Il formato JSON scrive un log per riga, con tutti i campi:

{
  "Logging": {
    "Console": { "FormatterName": "json" }
  }
}

In configurazione, e non con AddJsonConsole() in Program.cs, così in sviluppo resta il formato leggibile. Le FormatterOptions di appsettings.json valgono anche qui: il JSON ha i suoi Scopes.

Con OpenTelemetry, i log partono con lo stesso exporter OTLP di metriche e trace, come nell’articolo sulle trace:

builder.Logging.AddOpenTelemetry(l =>
{
    l.IncludeFormattedMessage = true;
    l.IncludeScopes = true;
    l.AddOtlpExporter();
});

Ogni log porta il trace id e lo span id dell’Activity corrente nei suoi campi, e i valori del template diventano attributi: FirmaId e DocumentoId si cercano come nella console JSON. Le due opzioni sono spente di default, e conviene saperlo:

• senza IncludeFormattedMessage, il corpo del log è il template, con i segnaposto, invece del testo composto;
• senza IncludeScopes, gli scope si perdono: niente FirmaId dal BeginScope, niente RequestPath.

I ServiceDefaults di Aspire le accendono entrambe. Nella dashboard di Aspire, o in qualunque strumento che riceve log e trace insieme, da un log di errore si apre la trace della richiesta, e dalla trace i suoi log.

6. I Debug, solo quando servono

Resta un dilemma. I Debug sono quelli che servono quando qualcosa va storto, ma in produzione sono troppi per tenerli sempre. È lo stesso problema del campionamento delle trace: decidere all’inizio vuol dire non sapere ancora come andrà la richiesta.

Il pacchetto Microsoft.AspNetCore.Diagnostics.Middleware, da .NET 9, permette di decidere alla fine. I log della richiesta restano in un buffer in memoria: se la richiesta va bene vengono scartati, se fallisce si scrivono.

builder.Logging.AddPerIncomingRequestBuffer(LogLevel.Debug);
builder.Services.AddExceptionHandler<SvuotaLogBuffer>();

LogLevel.Debug vuol dire: trattieni i log fino a Debug compreso, e scrivi subito gli altri. A svuotare il buffer ci pensa un handler delle eccezioni che non gestisce niente:

internal sealed class SvuotaLogBuffer(PerRequestLogBuffer buffer)
    : IExceptionHandler
{
    public ValueTask<bool> TryHandleAsync(
        HttpContext http, Exception ex, CancellationToken ct)
    {
        buffer.Flush();
        return ValueTask.FromResult(false);
    }
}

Restituisce false, quindi il middleware va avanti come prima: gli altri handler, poi il 500 generico e il suo log. Gli handler si chiamano nell’ordine di registrazione, e il primo che restituisce true ferma gli altri: questo va registrato per primo.

Con DocumentaleInventato.Firma a Debug, una firma che va bene scrive solo Firma completata. Una che fallisce scrive anche i Debug trattenuti, compreso quello del provider:

dbug: DocumentaleInventato.Firma.EseguiFirme[0]
      Invio al provider aruba
dbug: DocumentaleInventato.Firma.ProviderAruba[0]
      Chiamata HTTP al provider
fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
      An unhandled exception has occurred while executing the request.
      System.Net.Http.HttpRequestException: Il provider di firma ha risposto 503.

Due dettagli. Il buffer riceve solo i log che passano il livello minimo: senza Debug in configurazione per la categoria, non c’è niente da trattenere. E costa memoria: il buffer ha una dimensione massima, e quando è pieno i log più vecchi si perdono.

Cosa non scrivere

Un log vive più a lungo della richiesta, lo leggono più persone, e spesso finisce in un servizio esterno. Valgono le regole dei tag nelle trace:

Attenzione anche ai messaggi delle eccezioni: quello con la connection string, nell’articolo sulle eccezioni, non arrivava al client, ma nel log sì. Chi scrive il messaggio di un’eccezione scrive anche una riga di log.

In breve

1. Template con segnaposto, mai interpolazione: i valori diventano campi da cercare.
2. Livelli per categoria in configurazione; Microsoft.AspNetCore resta a Warning.
3. Scope per il contesto; il TraceId c’è già e lega i log di una richiesta.
4. Un’eccezione si scrive una volta, da chi la gestisce.
5. In produzione JSON o OpenTelemetry, con scope e messaggio composto; i Debug in un buffer, scritti solo se la richiesta fallisce.

Codice semplificato a scopo di esempio: nomi e struttura servono a dare l'idea, non sono da copiare così.