Controlla la tua applicazione Spring Cloud con Elastic Stack (a.k.a ELK) – Parte 1

Nei post precedenti abbiamo visto come è diventato facile (e di moda) creare microservizi nel mondo Java con Spring Cloud. La flessibilità che porta questa architettura non è però esente da una maggior complessità, in primis dal punto di vista del monitoriaggio del sistema e la gestione dei log. Abbiamo parlato del Mapping Diagnostic Context, che permette di aggiungere “metadati” alle singole righe di log, ricordando però che è necessario un sistema di aggregazione centralizzato affinché le informazioni acquistino un senso e possano essere analizzate. Tra i più famosi ed usati, sicuramente c’è lo stack ElasticSearch, Logstash e Kibana (ELK per gli amici) rebrandizzato oggi come “Elastic Stack“. Vediamo gli aspetti base di ELK (ci vorrebbero libri altrimenti), ma soprattutto come configurare la nostra applicazione Java per poter usufruire delle potenzialità che offre.

C’era una volta ElasticSearch, Logstash e Kibana… e Beats!

La homepage spiega in pochi step come siamo arrivati oggi a parlare di Elastic Stack. Si tratta di uno stack perché fondamentalmente sono 4 prodotti, ognuno con un compito specifico, che collaborano l’uno con l’altro.

Tutto è nato da ElasticSearch, un motore di analisi e ricerca distribuito, basato su NoSQL e Lucene, con interfaccia REST e scambio di documenti JSON.

Ben presto è stato ritenuto un buono strumento per raccogliere i log di sistemi distribuiti: mancava solo un sistema capace di leggere i log e trasformarli in documenti JSON da dare in pasto ad ElasticSearch. E’ così che nasce Logstash. Sostanzialmente si tratta di un ETL che è capace di ricevere i log da fonti diverse (TPC, UDP, file, JMS, JDBC, Redis, Kafka…), trasformarli ed aggregarli tramite l’applicazione di filtri, ed infine inviare il risultato in uno “stash“, in una destinazione, tra le quali ovviamente c’è ElasticSearch!

Che fare però di questi dati se non possono essere estratti, richiesti o aggregati facilmente? Era necessario un tool di visualizzazione flessibile e potete: Kibana vede la luce e diventa l’interfaccia ideale per ElasticSearch, permettendo di creare grafici e dashboard in modo intuitivo a partire dai dati, sfruttando tutti gli strumenti di aggregazione e ricerca di ElasticSearch per produrre istogrammmi, grafici a torta, geolocalizzare le informazioni e così via.

Lo stack nel tempo è diventato complesso e certe volte sembra aver perso l’immediatezza iniziale. Alla fine, il primo grande uso che se ne vuol fare è sempre l’aggregatore di log: manca quindi un semplice “trasportatore” di log che li prelevi dalle nostre applicazioni e li faccia entrare nello stack. Nasce quindi un quarto elemento, o meglio una famiglia di prodotti specifici nel trasporto di log (ma non solo) chiamati Beats. Non sono altro che agenti da installare come “sidecar” delle nostre applicazioni, solitamente a livello di server, che hanno il compito di raccogliere i dati ed inviarli a Logstash o direttamente a ElasticSearch.

Per questo lo stack in realtà oggi dovrebbe chiamarsi BELK, BLEK o ELKB… per evitare problemi hanno giustamente optato per un brand più generico, cioè Elastic Stack!

Elastic Stack

Architettura

Abbiamo quindi conosciuto i 4 elementi dello stack, ma in che relazione stanno tra loro? A livello teorico (a.k.a. “fuffa ad alto livello”), il flusso di elaborazione dei dati segue questo schema:

Elastic Stack Data Flow

Le informazioni entrano da Beats e/o Logstash, vengono indicizzate da ElasticSearch, e si visualizzano con Kibana. Mentre il ruolo degli ultimi due strati dello stack è chiaro, quello dei primi due all’inizio può sembrare confusionario: i dati possono entrare in entrambi, ma volendo Beats può girarli sia a Logstash che ElasticSearch… perché? Beats è nato dopo Logstash per semplificare e alleggerire il footprint delle operazioni di trasporto dei log nello stack, nonché di raccolta delle metriche dei sistemi distribuiti. Beats infatti è una famiglia di prodotti che non è solo incentrata sui log, ma permette di raccogliere informazioni più a basso livello per monitorare lo stato di salute del nostro sistema distribuito.
Vediamo di seguito qualche esempio su come implementare questa architettura per capirne le differenze e i vantaggi.

Come implementare l’architettura Elastic Stack

Partiamo da una delle immagini Docker più scaricate e ben documentate: in un unico container abbiamo a disposizione tutto lo stack, valido almeno per un ambiente di test (anche se è già pronto per architetture più complesse).

Cominceremo quindi da una architettura base, per poi successivamente preoccuparci dello stress del sistema e dell’alta affidabilità.

Su GitHub sono disponibili 2 progetti, usati per scrivere questo post: uno con le customizzazioni apportate al container sebp/elk (elk-poc); un altro è il POC di Spring Cloud già visto in un precedente post, riadattato (in branch separati) per dialogare con ELK in diverse modalità.

Lettura diretta dal file di log

Logstash è uno strumento estremamente versatile: grazie alla miriade di plugin di input, filtering e output, è possibile realizzare diverse pipeline di processazione per distinguere le sorgenti e le elaborazioni (solitamente l’output rimane ElasticSearch, ma non è detto…)

Logstash

Il flusso più semplice che possiamo realizzare è far leggere direttamente a Logstash i nostri log, nel classico formato di testo “plain”, secondo questo schema:

ELK Base

In questa configurazione, Logstash assume il ruolo fondamentale di collettore, elaboratore e “dispatcher” di log e risiede sulla macchina dove girano le applicazioni (a differenza di ElasticSearch e Kibana).

Logstash e le pipeline

Poco meno di un anno fa è stato introdotto in Logstash il concetto di pipeline multiple: si tratta cioè di poter dichiarare nella stessa istanza di Logstash più flussi “ETL” separati. Prima infatti o si istanziava più volte Logstash con configurazioni diverse, oppure si faceva un’unica configurazione piena di “if“… Adesso è tutto molto più semplice e manutenibile.

Basta compilare il file chiamato pipelines.yml (che nel nostro container risiede in /opt/logstash/config) con i riferimenti alla configurazione da usare:

- pipeline.id: spring-cloud-poc-file-plain
  pipeline.batch.size: 1
  path.config: /etc/logstash/conf.d/{input-file-plain.conf,filter-output-plain.conf}
  queue.type: persisted
    pipeline.id
    identificativo univoco della pipeline
    pipeline.batch.size
    quanti elementi accumulare nel plugin di input prima di passarli agli “worker” del filtering e output
    path.config
    path assoluto delle configurazioni da usare per la pipeline. Supporta la sintassi glob (in questo caso la configurazione è formata da due file, così da essere condivisa con altre pipeline)
    queue.type
    tipo di coda che gestisce i batch di dati. Una coda persistente permette di salvare i messaggi ricevuti in fase di input (prima di essere elaborati) in modo da fare buffering e non perdere nessuna messaggio in caso di sovraccarico

Queste sono solo le opzioni più frequenti: l’elenco completo è disponibile come commento all’interno del file. Scendiamo ora nel cuore della pipeline, ovvero i 3 step di intput, filtering e output.

Input

Il file input-file-plain.conf configura il plugin file in modo che legga direttamente i nostri log

input {
    file {
        path => "/logs/*/*/*/*.log"
        codec => multiline {
            pattern => "^%{YEAR}-%{MONTHNUM}-%{MONTHDAY} %{TIME}.*"
            negate => "true"
            what => "previous"
        }
    }
}

E’ obbligatorio specificare il path del file (sempre in sintassi glob). Per supportare anche il multiriga (per gli stacktrace) e necessario aggiungere il codec multiline opportunamente configurato: ogni riga comincia con una data (pattern di default dei log di Spring Boot, come suggerito da questo splendido post); se non è così (negate => "true"), va raggruppata con la precedente (what => "previous").

Filter

Dal momento che stiamo leggendo del log non strutturati (puro testo), è necessario dar loro una semantica. La vera potenza di Logstash sta proprio in questa fase, grazie al plugin grok (che possiamo tradurre come “buttar giù”, “decifrare”). Il suo scopo è “tokenizzare” il log in modo da creare una struttura (json) valorizzata con i token estratti.

Il plugin non fa altro che usare massicciamente espressioni regolari, mascherate con una dose di zucchero sintattico del tipo %{SYNTAX:SEMANTIC}:

  • SYNTAX fa riferimento ad una espressione regolare
  • SEMANTIC definisce il nome della variabile (chiamata anche field o campo) che contiene il valore del pattern trovato (come se fosse il gruppo “matchato” in una espressione regolare)

Ci vorrebbe un post dedicato al grok, ma per farsi un’idea basta un esempio. Il seguente log

GET /login 0.241ms

è catturato dal pattern:

%{WORD:method} %{URIPATHPARAM:request} %{NUMBER:duration}ms

che genera un json con i seguenti field

{
   "method": "GET",
   "request": "/login",
   "duration": "0.241"
}

Non è un caso che i valori trovati siano tutti dichiarati come stringhe, vedremo dopo come specificarne il tipo.

Da dove vengono fuori WORD, URIPATHPARAM e NUMBER? Grok dispone di un ricco vocabolario già pronto di espressioni regolari, ma che è molto facile estendere.

Per esempio, i pattern Grok necessari a matchare i log di Spring Boot + Sleuth, usati in questo POC, sono definiti in un file a parte, da specificare nella configurazione del plugin.

Per imparare ad usare grok è molto utile poter testare i pattern (anche quelli propri) direttamente online grazie all’applicazione Grok Debugger o ai DevTools di X-Pack (incluso dalla 6.3).

Fatta questa premessa, la dichiarazione del plugin grok all’interno del filter non dovrebbe risultare misteriosa:

filter {
  grok {
    patterns_dir => ["/etc/logstash/conf.d/patterns"]
    named_captures_only => true
    match => {
        "message" => [
            "%{SB_LAYOUT}: %{GREEDYDATA:message}"
        ]
    }
    overwrite => [ "message" ]
  }
}

Specifichiamo la cartella con i nostri pattern (patterns_dir); dichiariamo che vogliamo una entry nel json solo per i pattern che hanno un nome (named_captures_only), cioè che hanno specificato il nome del field a destra dei due punti (:SEMANTIC) del pattern; con match invece dichiariamo i possibili pattern del campo “message” ricevuto in input dal plugin file. In pratica tutto quello matchato da SB_LAYOUT è il layout (custom) del log di Spring Boot (non ci interessa dargli un nome in questo caso, perché i “sotto layout” già definiscono i nomi dei field per le singole parti): a destra c’è il messaggio vero e proprio del nostro log, catturato dal fieldmessage“.

Alla fine vogliano che la nuova variabilemessage“, cioè il nostro messaggio di log vero e proprio estratto dal layout di Spring Boot, sovrascriva (overwrite) quella ricevuta in input.

Se infatti il “message” ricevuto in input dal plugin file è:

2018-04-22 18:53:45.691  INFO [order-services,ed5a486181943259,ed5a486181943259,false] 2062 --- [nio-9191-exec-5] i.c.filters.mdc.UriMetricsLoggerFilter   : Searching customer by id 1

in uscita dal grok avremo il json del tipo:

{
  "timestamp": "2018-04-22 18:53:45.691",
  "level": "INFO",
  "service_name": "order-services",
  "trace": "ed5a486181943259",
  "span": "ed5a486181943259",
  "export": "false",
  "pid": "2062",
  "thread": "nio-9191-exec-5",
  "class": "i.c.filters.mdc.UriMetricsLoggerFilter",
  "message": "Searching customer by id 1"
}

il cui campo “message” è il testo vero e proprio che abbiamo scritto nel nostro codice.

Di per sé questo sarebbe sufficiente per avere una prima indicizzazione da parte di ElasticSearch. Ma nel momento in cui andiamo ad usare Kibana ci accorgiamo che qualcosa non quadra. Il timestamp degli eventi non torna con quello mostrato nel nostro file di log: non sapendo infatti quale variabile del nostro pattern rappresenta il tempo, Logstash ne genera uno automaticamente: è ovvio quindi che questo tempo non è quello del nostro log, ma quello di quando viene processata la riga (che può essere potenzialmente in differita).

Prima di uscire dal filter è necessario quindi indicare quale campo rappresenta la data dell’evento, grazie al plugin date:

filter {
  grok {
     ...
  }
  #Replace autogenerated @timestamp with timestamp from grok
  date {
    match => [ "timestamp" , "yyyy-MM-dd HH:mm:ss.SSS" ]
    timezone => [ "Europe/Rome" ]
  }
}

Così diciamo a logstash di generare il campo @timestamp (nome di default preso in considerazione per le “time-series”) a partire dal campo timestamp appena “grokkato”, nella timezone “Europe/Rome” (perché così è il nostro log).

Infine, come ultimo step, possiamo aggiungere il plugin mutate per specializzare, per esempio, il tipo di un campo:

filter {
  grok {
     ...
  }
  date {
    ...
  }
  mutate {
    convert => {
       "export" => "boolean"
    }
  }
}

Per l’esempio completo del file, vedere filter-output-plain.conf.

Output

Questo file contiene anche la sezione di output: usando il plugin elasticsearch, possiamo mandare i log ad ElasticSearch (sul localhost del container):

output {
    elasticsearch {
        hosts => ["localhost"]
        index => "plain-%{service_name}-%{+yyyy.MM.dd}"
    }
}

Nel plugin è possibile specificare tutte le istanze di ElasticSearch (hosts) e l’indice da creare (index). E’ interessante notare che il nome dell’indice è variabile: dipende dal campo service_name estratto da grok (che corrisponde ad un microservizio) e dal giorno corrente. Creare un indice al giorno sembra una prassi ricorrente, perché permette facilmente di eliminare dati più vecchi di una certa data.

Visualizzare i log

A questo punto non ci resta che avviare tutto lo stack, inviare dei dati e poi aprire Kibana per vedere i risultati.

Per motivi di test (e di semplicità), applicazione e ElasticStack risiedono sulla stessa macchina: ovviamente, nel mondo reale, Logstash dovrebbe stare con la nostra applicazione, ElasticSearch e Kibana su altre macchine.

Partiamo quindi dall’applicazione Spring Cloud POC (branch elk-logstash-with-grok-via-fs) e avviamo tutti i servizi (è importante che il config-server e eureka-server siano i primi). Nel file README sono specificati tutti i branch e a cosa servono.

Andiamo ora su Elastic Stack: il progetto elk-poc su GutHub è dockerizzato e ha un docker-compose.yml che semplifica l’avvio dello stack. Per far finta che Logstash sia sulla stessa macchina dell’applicazione (per poterne collezionare i log), è necessario mappare la cartella dei nostri log come volume nel container, come specificato nel README quando si parla della pipeline spring-cloud-poc-file-plain.

Kibana sarà disponibile all’indirizzo http://localhost:5601, ma sarà ancora vuoto e chiede di inserire dati:

Dopo qualche chiamata a

curl http://localhost:8080/api/v1/customers/1/orders

potremo creare un nuovo Index pattern:

Kibana define index pattern

che aggregherà tutti gli indici che cominciano con plain, creati automaticamente su ElasticSearch da Logstash. Specifichiamo poi qual è il campo che definisce la data del log:

Kibana define index pattern timestamp

ed il gioco è fatto! Dalla voce “Discover” possiamo cominciare a definire come vogliamo filtrare e rappresentare la griglia dei log:

Kibana discover

Grazie alle informazioni aggiunge da Spring Sleuth, filtrare sui valori delle colonne trace e span ci permettrà di seguire agilmente il percorso fatto da una chiamata attraverso i nostri servizi (service_name) e avere sotto controllo l’intero flusso da un’unico punto.

Conclusioni

In questa prima parte abbiamo esplorato i componenti e i concetti fondamentali di Elastic Stack. La soluzione proposta per aggregare i log è la più semplice che si può realizzare ma molto probabilmente è più adatta ad un ambiente di test che altro. Le possibilità con cui si possono inviare i dati allo stack sono molteplici e nel prossimo post cercheremo di vedere le alternative.

Andrea Como

Sono un software engineer focalizzato nella progettazione e sviluppo di applicazioni web in Java. Presso OmniaGroup ricopro il ruolo di Tech Leader sulle tecnologie legate alla piattaforma Java EE 5 (come WebSphere 7.0, EJB3, JPA 1 (EclipseLink), JSF 1.2 (Mojarra) e RichFaces 3) e Java EE 6 con JBoss AS 7, in particolare di CDI, JAX-RS, nonché di EJB 3.1, JPA2, JSF2 e RichFaces 4. Al momento mi occupo di ECM, in particolar modo sulla customizzazione di Alfresco 4 e sulla sua installazione con tecnologie da devops come Vagrant e Chef. In passato ho lavorato con la piattaforma alternativa alla enterprise per lo sviluppo web: Java SE 6, Tomcat 6, Hibernate 3 e Spring 2.5. Nei ritagli di tempo sviluppo siti web in PHP e ASP. Per maggiori informazioni consulta il mio curriculum pubblico. Follow me on Twitter - LinkedIn profile - Google+