Come risolvere i problemi di Timestamp UTC nei Log OpenSearch. Caso Studio completo

Introduzione

Nel vasto e complesso panorama delle infrastrutture cloud-native, la capacità di raccogliere, analizzare e visualizzare i log in modo efficace è un pilastro fondamentale per garantire un monitoraggio continuo e approfondito delle applicazioni. Questi dati non solo offrono una visione in tempo reale delle prestazioni e del comportamento dei sistemi, ma sono anche indispensabili per la creazione di dashboard intuitive e report dettagliati sull'utilizzo di applicazioni e siti web. Questo documento si propone di esaminare un problema specifico e rilevante incontrato nella gestione dei log applicativi di tipo analytics, focalizzandosi in particolare sulla problematica della timezone nella data dei log inviati dai server verso la piattaforma OpenSearch. La corretta gestione dei fusi orari è cruciale per l'integrità e l'affidabilità dei dati di monitoraggio, come dimostrato dalla casistica analizzata.

Il Contesto Operativo

L'ambiente in esame è caratterizzato da una pipeline di gestione dei log meticolosamente progettata per raccogliere e analizzare i dati di tipo analytics. Questi dati includono informazioni critiche sull'andamento delle applicazioni, la durata delle operazioni significative e il loro esito, fornendo insight essenziali per l'ottimizzazione e la risoluzione dei problemi. L'architettura implementata per supportare questa pipeline è robusta e modulare.

Il Problema

Durante l'utilizzo ordinario e il monitoraggio dell'infrastruttura, sono emersi due problemi distinti ma interconnessi relativi alla gestione dei timestamp, che hanno compromesso l'affidabilità delle dashboard di Grafana e l'accuratezza dei dati di log. Il primo problema si è manifestato con una visualizzazione errata dei dati nelle dashboard di Grafana, che mostravano le informazioni esattamente con un'ora di ritardo rispetto alla realtà. Un'analisi preliminare ha rivelato che la causa risiedeva nell'errata valorizzazione del timestamp nei log inviati dalle Virtual Machine verso OpenSearch. In particolare, anziché essere inviati in UTC (United Coordinated Time), i log venivano erroneamente valorizzati in CET (Central European Time), il fuso orario di molti paesi europei, inclusa l'Italia.

Poiché Grafana interpreta i timestamp come UTC per impostazione predefinita, questa discrepanza causava uno sfasamento temporale: i dati venivano visualizzati un'ora in avanti rispetto al tempo reale in inverno, e due ore in avanti nel periodo estivo, rendendo le dashboard fuorvianti. Il secondo problema, di natura più critica, riguardava i timestamp che venivano generati al momento dell'invio delle righe di log al nodo centralizzatore (Fluentd) anziché al momento effettivo della loro creazione.

Questa pratica, apparentemente innocua, causava problemi significativi, specialmente nel caso in cui la quantità di log diventava improvvisamente elevata e poteva andare a congestionare il nodo centrale di Fluentd. Questo perché, se Fluentd si ritrovava con eccessivi log da gestire, anche se presente in una infrastruttura scalabile, avrebbe sicuramente avuto dei rallentamenti e ciò avrebbe portato a una errata definizione del timestamp dei log. La conseguenza diretta era una "commistione" di log su Grafana: eventi accaduti in momenti diversi venivano visualizzati come se fossero avvenuti simultaneamente, annullando di fatto la capacità di correlazione temporale e rendendo i dati acquisiti inutilizzabili per l'analisi o, peggio, conducendo a interpretazioni errate e decisioni basate su informazioni imprecise.

Gli Obiettivi

Di fronte a queste criticità, sono stati definiti obiettivi prioritari per ripristinare la piena funzionalità e affidabilità del sistema di logging: ripristinare la corretta visualizzazione dei log, fornire un workaround temporaneo, garantire la corretta valorizzazione del timestamp in UTC e risolvere il problema della valorizzazione ritardata del timestamp.

1. Ripristinare la corretta visualizzazione dei log: era imperativo ristabilire la visibilità accurata dei log sulle dashboard di Grafana per un servizio mission-critical, sul quale erano in corso analisi urgenti relative a un disservizio in atto. La corretta interpretazione dei dati era essenziale per il troubleshooting.
2. Fornire un workaround temporaneo: era necessario implementare rapidamente una soluzione provvisoria per tamponare la situazione nell'immediato, consentendo il proseguimento delle attività di troubleshooting del disservizio principale senza ulteriori interruzioni.
3. Garantire la corretta valorizzazione del timestamp in UTC: l'obiettivo a lungo termine era assicurarsi che tutti i log inviati da Fluentd avessero il timestamp correttamente valorizzato in UTC, eliminando alla radice le problematiche legate ai fusi orari.
4. Risolvere il problema della valorizzazione ritardata del timestamp: era fondamentale trovare una soluzione che garantisse l'acquisizione del timestamp al momento della generazione del log, non dell'invio, per evitare distorsioni temporali.

La Soluzione

Il processo di troubleshooting e risoluzione si è articolato in due fasi distinte e sequenziali, mirate prima a una rapida mitigazione e poi a una soluzione definitiva.

Fase 1: Workaround Temporaneo

Per ripristinare velocemente la corretta visualizzazione su Grafana, abbiamo prima impostato le dashboard per interpretare i dati in UTC e poi utilizzato la funzionalità di Grafana che permette di impostare un intervallo temporale futuro (es. now+1h) per compensare il ritardo di visualizzazione.

1. Impostazione delle dashboard in UTC: inizialmente, le dashboard di Grafana erano configurate per valorizzare i log in CET, aggiungendo di fatto un'ora (o due, a seconda della stagione) al valore che arrivava dagli endpoint. Modificando questa impostazione e configurando le dashboard per interpretare i timestamp come UTC, si è riusciti a visualizzare i log con l'ora corretta. Tuttavia, questa soluzione presentava una limitazione: i dati potevano essere visualizzati solo fino a un'ora prima del tempo reale, creando un "buco" temporale.
2. Utilizzo di valori futuri nel campo "A": successivamente, è stato scoperto che Grafana permetteva di utilizzare valori futuri nel campo "A" del selettore di intervallo temporale. Impostando questo campo a now+1h , è stato possibile spostare l'intervallo di visualizzazione in avanti di un'ora, rendendo gli orari nuovamente visibili in modo corretto e compensando il ritardo di visualizzazione precedentemente riscontrato. Questo ha fornito una soluzione rapida ed efficace per il problema immediato.

Fase 2: Soluzione Definitiva

Una volta mitigata l'emergenza, l'attenzione si è spostata sulla ricerca di una soluzione definitiva per eliminare le cause alla radice dei problemi di timestamp.

1. Modifica della funzione di recupero orario in Fluent Bit: il problema principale della valorizzazione in CET è stato risolto modificando la funzione in Fluent Bit responsabile del recupero dell'orario di sistema. Specificamente, la funzione os.date("%Y-%m-%d %H:%M:%S") è stata cambiata in os.date("!%Y-%m-%d %H:%M:%S"). L'aggiunta del prefisso "!" prima del formato della data istruisce Fluent Bit a utilizzare l'orario UTC invece del fuso orario locale (CET), garantendo che tutti i log vengano timestampati correttamente alla fonte.
2. Adeguamento delle dashboard su Grafana: una volta che ogni log contenesse il medesimo campo che indicava il timestamp esatto di generazione, le dashboard di Grafana sono state impostate per adeguare autonomamente la visualizzazione dei log secondo la timezone di default presente sul browser. Questo permette agli utenti di visualizzare sempre i log nell’orario più consono con l’attività lavorativa ed è una soluzione elastica per i cambi di orario.

L'aggiunta del prefisso ! prima del formato della data istruisce Fluent Bit a utilizzare l'orario UTC invece del fuso orario locale, garantendo che tutti i log vengano timestampati correttamente alla fonte. Successivamente, le dashboard di Grafana sono state configurate per adattare autonomamente la visualizzazione dei log in base alla timezone del browser dell'utente.

 

I Risultati Conseguiti

Grazie all'applicazione meticolosa di queste soluzioni, le dashboard di Grafana sono tornate a mostrare i dati con gli orari corretti e in modo affidabile. La risoluzione dei problemi di timestamp ha ripristinato l'integrità dei dati di monitoraggio, permettendo al team di operare con maggiore efficacia e di prendere decisioni informate basate su informazioni accurate e in tempo reale.

Le Raccomandazioni Conclusive

Dall'analisi approfondita di questo caso, abbiamo tratto insegnamenti fondamentali che rafforzano l'importanza di alcune pratiche nella progettazione e gestione delle pipeline di ingestione di informazioni.