Vantaggi del Logging strutturato rispetto alla registrazione di base

Ci sono due fondamentali progressi con l'approccio strutturato che non possono essere emulati usando log di testo senza (a volte livelli estremi di) sforzo aggiuntivo.

Tipi di eventi

Quando scrivi due eventi con log4net come:

log.Debug("Disk quota {0} exceeded by user {1}", 100, "DTI-Matt");
log.Debug("Disk quota {0} exceeded by user {1}", 150, "nblumhardt");

Ciò produrrà un testo simile:

Disk quota 100 exceeded by user DTI-Matt
Disk quota 150 exceeded by user nblumhardt

Ma, per quanto riguarda l'elaborazione della macchina, sono solo due righe di testo differente.

Potresti voler trovare tutti gli eventi di "quota disco superata", ma il caso semplicistico di cercare eventi like 'Disk quota%' cadrà non appena si verifica un altro evento simile a:

Disk quota 100 set for user DTI-Matt

La registrazione del testo getta via le informazioni che abbiamo inizialmente sulla fonte dell'evento, e questo deve essere ricostruito durante la lettura dei registri di solito con espressioni di corrispondenza sempre più elaborate.

Al contrario, quando scrivi i seguenti due Serilog eventi:

log.Debug("Disk quota {Quota} exceeded by user {Username}", 100, "DTI-Matt");
log.Debug("Disk quota {Quota} exceeded by user {Username}", 150, "nblumhardt");

Producono output di testo simile alla versione di log4net, ma dietro le quinte, il "Disk quota {Quota} exceeded by user {Username}" modello di messaggio viene portato da entrambi gli eventi.

Con un sink appropriato, puoi in seguito scrivere query where MessageTemplate = 'Disk quota {Quota} exceeded by user {Username}' e ottenere esattamente gli eventi in cui è stata superata la quota del disco.

Non è sempre conveniente memorizzare l'intero modello di messaggio con ogni evento di registro, quindi alcuni sink hanno cancellato il modello del messaggio in un valore numerico EventType (ad esempio 0x1234abcd ), oppure, puoi aggiungere un enricher alla pipeline di registrazione per fai da te .

È più sottile rispetto alla successiva differenza di seguito, ma è potente in modo massiccio quando si gestiscono volumi di registro di grandi dimensioni.

Dati strutturati

Considerando nuovamente i due eventi sull'utilizzo dello spazio su disco, potrebbe essere abbastanza semplice utilizzare i registri di testo per eseguire una query per un particolare utente con like 'Disk quota' and like 'DTI-Matt' .

Ma la diagnostica di produzione non è sempre così semplice. Immagina di dover trovare eventi in cui la quota disco superata è inferiore a 125 MB?

Con Serilog, questo è possibile nella maggior parte dei lavandini usando una variante di:

Quota < 125

Costruire questo tipo di query da un'espressione regolare è possibile, ma diventa faticoso e di solito finisce per essere una misura di ultima istanza.

Ora aggiungi a questo un tipo di evento:

Quota < 125 and EventType = 0x1234abcd

Inizi a vedere qui come queste capacità si combinano in un modo semplice per rendere il debugging della produzione con i log come un'attività di sviluppo di prima classe.

Un ulteriore vantaggio, forse non così facile da prevenire in anticipo, ma una volta che il debugging della produzione è stato rimosso dalla terra dell'hackery regex, gli sviluppatori iniziano a valutare molto più i log e ad esercitare maggiore attenzione e considerazione quando li scrivono. Registri migliori - > applicazioni di qualità migliore - > più felicità tutt'intorno.

Quando si raccolgono i registri per l'elaborazione, sia per l'analisi in alcuni database e / o per la ricerca nei registri elaborati in un secondo momento, l'uso della registrazione strutturata semplifica / rende più efficiente l'elaborazione. Il parser può sfruttare la struttura conosciuta ( eg JSON, XML, ASN.1, qualunque) e utilizzare le macchine di stato per l'analisi, al contrario delle espressioni regolari (che possono essere computazionalmente costose (relativamente) per compilare ed eseguire). L'analisi del testo in forma libera, come quella suggerita dal tuo collega, tende a basarsi su espressioni regolari, e per fare affidamento su quel testo che non cambia . Questo può rendere l'analisi del testo in forma libera piuttosto fragile (l'analisi i.e. è strettamente accoppiata al testo esatto nel codice).

Considera anche il caso di ricerca / ricerca, e.g. :

SELECT text FROM logs WHERE text LIKE "Disk quota";

LIKE richiedono confronti con ogni valore di riga text ; di nuovo, questo è relativamente costoso dal punto di vista computazionale, particolarmente quando vengono utilizzati i caratteri jolly:

SELECT text FROM logs WHERE text LIKE "Disk %";

Con la registrazione strutturata, il tuo messaggio di registro relativo all'errore del disco potrebbe essere simile a questo in JSON:

{ "level": "DEBUG", "user": "username", "error_type": "disk", "text": "Disk quota ... exceeded by user ..." }

I campi di questo tipo di struttura possono essere facilmente associati a e.g. nomi di colonne di tabelle SQL, che a sua volta significa che la ricerca può essere più specifica / granulare:

SELECT user, text FROM logs WHERE error_type = "disk";

Puoi posizionare indici sulle colonne i cui valori ti aspetti di cercare / cercare frequentemente, se non utilizzi le clausole LIKE per quei valori di colonna . Più puoi abbattere il tuo messaggio di registro in categorie specifiche, più mirato puoi fare la tua ricerca. Ad esempio, oltre al campo / colonna error_type nell'esempio sopra, potresti persino rendere "error_category": "disk", "error_type": "quota" o somesuch.

Maggiore è la struttura dei tuoi messaggi di registro, più i tuoi sistemi di analisi / ricerca (come fluentd , elasticsearch , kibana ) possono sfruttare questa struttura ed eseguire i loro compiti con maggiore velocità e meno CPU / memoria.

Spero che questo aiuti!

Non troverai molti vantaggi dal registro strutturato quando la tua app crea poche centinaia di messaggi di log al giorno. Lo farai sicuramente quando avrai qualche centinaio di messaggi di log al secondo provenienti da diverse app distribuite.

Correlati, l'impostazione in cui i messaggi di registro finiscono in Stack ELK è appropriata anche per le scale dove la registrazione a SQL diventa un collo di bottiglia.

Ho visto l'installazione di "logging e ricerca di base" con SQL select .. like e regex spinti ai suoi limiti dove cade a pezzi - ci sono falsi positivi, omissioni, codice di filtro orribile con bug knwon che è difficile da mantenere e no -la vuole toccare, nuovi messaggi di log che non seguono le ipotesi del filtro, riluttanza a toccare le dichiarazioni di registrazione nel codice per non interrompere i report, ecc.

Quindi stanno emergendo diversi pacchetti software per affrontare questo problema in un modo migliore. C'è Serilog, ho sentito che il team di NLog ci sta guardando , e abbiamo scritto StructuredLogging.Json per Nlog , vedo anche che il nuovo Le astrazioni di registrazione core di ASP.Net "consentono ai provider di registrazione di implementare ... la registrazione strutturata".

Un esempio con StructuredLogging. Si accede a un logger di NLog come questo:

logger.ExtendedError("Order send failed", new { OrderId = 1234, RestaurantId = 4567 } );

Questi dati strutturati vanno a kibana. Il valore 1234 è memorizzato nel campo OrderId della voce di registro. Puoi quindi eseguire una ricerca utilizzando la sintassi della query di kibana per es. tutte le voci del registro dove @LogType:nlog AND Level:Error AND OrderId:1234 .

Message e OrderId sono ora solo campi in cui è possibile cercare corrispondenze esatte o inesatte di cui hai bisogno o aggregate per conteggi. Questo è potente e flessibile.

dai best practice per la registrazione strutturata :

The message logged should be the same every time. It should be a constant string, not a string formatted to contain data values such as ids or quantities. Then it is easy to search for.

The message logged should be distinct i.e. not the same as the message produced by an unrelated log statement. Then searching for it does not match unrelated things as well.