Docker logging: cosa fa il mio container? [parte 1]

Con l'uso sempre più massivo dei container uno degli aspetti più critici da valutare è il logging delle applicazioni che decidiamo di far girare.

Chi usa un sistema Linux da qualche tempo, sa che la maggior parte delle applicazioni in esecuzione vanno a scrivere il log da qualche parte, sia esso il buon vecchio file di log, o sistemi più moderni che inseriscono i log in un database (qualcuno ha detto systemd?); questi metodi hanno in comune il fatto che, alla fin fine ed in qualsiasi formato sia, il log risiede sul sistema che sta eseguendo l'applicazione.

Era compito nostro occuparci di evitare che la crescita del file di log non saturasse il filesystem, pena la perdita di log importanti o, peggio ancora, il blocco dell'applicazione (o di altre applicazioni) causa la mancanza di spazio. E, negli anni, ci siamo abituati ad usare gli strumenti diventati standard de-facto per controllare la crescita di questi file: dal ben conosciuto logrotate, fino a script schedulati in crontab che spostano i log su storage esterni, abbiamo imparato a tenere sotto controllo la situazione, assicurandoci di non perdere neanche una riga di quel prezioso testo che, chissà, potrebbe prima o poi essere fondamentale alla risoluzione di un problema (o all'identificazione di qualche specifico comportamento dell'applicazione).

Pensiamo bene però a quello che è un container: si tratta di un ambiente separato dal sistema che lo esegue, ed in cui è in esecuzione solo l'applicazione interessata. Questo ambiente nasce quando l'applicazione si avvia, e muore quando l'applicazione si ferma, e tutto il contorno con esso; eventuali socket, file di configurazione dell'applicazione e, si, anche i file di log! Con la fine dell'esecuzione di un container, ci perdiamo tutto.

E se pensiamo che spesso i container sono gestiti da sistemi di orchestration (ad esempio Docker Swarm o Kubernetes), questi vengono creati e distrutti autonomamente e -pressoché- costantemente dal sistema, per mantenere lo stato di quanto richiesto da noi.

Ed i nostri preziosi log? Che fine fanno?

Fortunatamente Docker è provvisto una serie di funzionalità che ci permettono di far esistere i log anche oltre il container che l'ha generato, fornendoci diversi modi per salvare i nostri dati in altro modo.

In questo articolo (e nei successivi) andremo a vedere le più comuni soluzioni di log che fornisce Docker, e cercheremo di dare una panoramica delle funzionalità, così da permettervi di scegliere il più adeguato alle vostre esigenze.

 

Dove scrivo il log?

Ecco, questa sicuramente è una delle prime domande che chi sviluppa o chi configura un'applicazione ci farà nel momento in cui sta per essere eseguita in un container. La risposta più semplice è anche la migliore, ovvero quella che permette di utilizzare il sistema di logging nativo di Docker in maniera più ottimale: standard output e standard error!

Esatto, perchè nativamente Docker gestisce questi due stream e permette di fare una serie di cose (che vedremo in seguito) con i nostri log.

Certo, ci sono casi in cui il log non può essere scritto su questi flussi, o si vuole separare i file di log in più file specifici; in questo caso le soluzioni sono fondamentalmente due.

La prima, quella più "old school" (ma che sicuramente può aiutare soprattutto in un primo periodo di transazione ai container), è quella di accordarsi su una directory in cui salvare i log (ad esempio, /logs/) e lanciare il container andando a mappare il contenuto di quella directory con una sull'host in cui il container viene eseguito:

/Users/matteo # mkdir logs
/Users/matteo # docker run -d --rm -v /Users/matteo/logs:/logs alpine \
> /bin/sh -c 'ping 8.8.8.8 &> /logs/myapp.log'
15fd6f5a743a07358c158b570b22702545f32878777ddd2bcc7861d4ee22f774

Ho quindi creato una directory logs sull'host, dopodichè ho lanciato un container con le seguenti opzioni:

• -d: daemon, l'esecuzione del container avviene in background
• --rm: remove, al termine dell'esecuzione del container, questo verrà rimosso (invece di essere messo in stop, comportamento di default di Docker).
• -v /Users/matteo/logs:/logs: questa opzione fa un map della directory locale /Users/matteo/logs in una nuova directory /logs all'interno del container
• alpine: questa è l'immagine che usiamo per il container (uso alpine perché é piccola e leggera, e per testing va più che bene
• /bin/sh -c 'ping 8.8.8.8 &> /logs/myapp.log': all'interno del sistema alpine, eseguo una shell con un ping ai dns di Google, redirigendo tutto (stdout/stdin) nel file /logs/myapp.log

Docker ci ha risposto con l'id del container, possiamo verificare che è in esecuzione:

/Users/matteo # docker ps
CONTAINER ID        IMAGE               COMMAND                  CREATED             STATUS              PORTS               NAMES
15fd6f5a743a        alpine              "/bin/sh -c 'ping ..."   7 minutes ago       Up 7 minutes                            heuristic_easley

In questo caso, dunque, nulla viene inviato sullo standard output e sullo standard error, e possiamo vedere che Docker non è in grado di gestire il logging. Se utilizziamo il suo comando logs per metterci in tail sui log del container, non vedremo nulla:

/Users/matteo # docker logs -f 15fd6f5a743a
^C
/Users/matteo #

Di contro vedremo presente il file myapp.log all'interno della directory sul nostro sistema host; su questo possiamo metterci in tail:

/Users/matteo # ls logs/
myapp.log
/Users/matteo # tail -f logs/myapp.log 
64 bytes from 8.8.8.8: seq=603 ttl=37 time=0.446 ms
64 bytes from 8.8.8.8: seq=604 ttl=37 time=0.503 ms
64 bytes from 8.8.8.8: seq=605 ttl=37 time=0.518 ms
64 bytes from 8.8.8.8: seq=606 ttl=37 time=0.491 ms
64 bytes from 8.8.8.8: seq=607 ttl=37 time=0.307 ms

Ora, diciamo a docker di fermare il container e, data l'opzione --rm, questo verrà totalmente distrutto:

/Users/matteo # docker stop 15fd6f5a743a
15fd6f5a743a
/Users/matteo # docker ps -a
CONTAINER ID        IMAGE               COMMAND             CREATED             STATUS              PORTS               NAMES

Essendo che, alla fine dei conti, il file myapp.log risiedeva su una directory dell'host, questo ci ha permesso di mantenere il file, che è ancora disponibile:

/Users/matteo # tail -1 logs/myapp.log 
64 bytes from 8.8.8.8: seq=667 ttl=37 time=0.762 ms

Possiamo quindi lavorare su questi file tranquillamente con i soliti tool con cui siamo comodi.

Il problema, però, può sorgere soprattutto in ambienti in cui ci affidiamo a soluzioni esterne per la gestione della vita dei nostri container (vedi Swarm o Kubernetes ad esempio): in questo caso, abbiamo diversi fattori problematici:

• Non sappiamo dove il container verrà eseguito: anche se questa affermazione è vera in parte (possiamo applicare delle regole per determinare la posizione di esecuzione di un container, ma fa perdere un po' senso al tutto), questo vuol dire che dobbiamo predisporci creando le varie directory mappate su tutti i sistemi.
• Sovrapposizione di container: se a questi sistemi diciamo che vogliamo in esecuzione 3 container ed abbiamo 3 nodi, tendenzialmente avremo un container per nodo. Ma nel caso uno di questi 3 nodi muoia? Di solito viene eseguito un'altro container su uno dei due nodi rimanenti. Ma su quel nodo, che comportamento avremo? Entrambi i container potranno mapparsi la stessa directory su filesystem? I file si andranno a sovrascrivere a vicenda? Un casino insomma
• Ci riportiamo nel mondo container il lavoro che avevamo prima: gestione dello spazio su filesystem, rotazione, spostamento, etc.

 

La via di Docker

Come anticipavamo, per poter sfruttare il massimo delle potenzialità di Docker per il logging, la soluzione principe è quella di far loggare l'applicazione direttamente su standard output e standard error.
Volessimo rilanciare il nostro container di test potremmo farlo semplicemente con:

/Users/matteo # docker run -d --rm alpine ping 8.8.8.8
8c40734b976f407339750d58bda54678517750bb85f5d174f3fa7470a2b3a57b

A questo punto, possiamo metterci in tail direttamente con i comandi Docker:

/Users/matteo # docker logs -f 8c40734b976f
PING 8.8.8.8 (8.8.8.8): 56 data bytes
64 bytes from 8.8.8.8: seq=0 ttl=37 time=0.426 ms
...

Di fatto, questo è il metodo standard ed in effetti nel caso dovessimo distruggere il container questi log andrebbero persi. Ma cosa fa in realtà Docker?

Come dicevamo, Docker ha diversi sitemi nativi per trattare i log su standard output e standard error, questi sistemi vengono chiamati Logging Drivers.

Per vedere il nostro sistema di default, possiamo utilizzare il seguente comando:

/Users/matteo # docker info | grep -i log
Logging Driver: json-file

Vediamo che dunque il driver di default è chiamato json-file. Questo driver dice al container di intercettare tutto il contenuto dei due stream e scriverli in un file di tipo json.

Per vedere in quale file lo specifico container sta scrivendo, dobbiamo ispezionare i dettagli del container in questione:

/Users/matteo # docker inspect 8c40734b976f | grep LogPath
        "LogPath": "/var/lib/docker/containers/8c40734b976f407339750d58bda54678517750bb85f5d174f3fa7470a2b3a57b/8c40734b976f407339750d58bda54678517750bb85f5d174f3fa7470a2b3a57b-json.log"

Il contenuto del file altro non è che i messaggi degli stream inseriti in una struttura di tipo json:

/Users/matteo # head -2 /var/lib/docker/containers/8c40734b976f407339750d58bda54678517750bb85f5d174f3fa7470a2b3a57b/8c40734b976f407339750d58bda54678517750bb85f5d174f3fa7470a2b3a57b-json.log
{"log":"PING 8.8.8.8 (8.8.8.8): 56 data bytes\n","stream":"stdout","time":"2017-02-14T12:50:31.313520563Z"}
{"log":"64 bytes from 8.8.8.8: seq=0 ttl=37 time=0.426 ms\n","stream":"stdout","time":"2017-02-14T12:50:31.313861696Z"}

Il comando "docker logs" non fa altro che riportare il contenuto di questo file, estraendo i messaggi sensibili dalla struttura del json.

Che vantaggi abbiamo, dunque, rispetto all'altro metodo? Di fatto non molti, questo driver di logging è solo quello di default ed, in genere, non è quello che viene utilizzato realmente in ambienti di produzione, demandando ad altri sistemi.

Può però venire molto comodo nel momento in cui sappiamo di aver bisogno -al massimo- di accedere ai log più recenti del container, e non ci interessa avere un grosso storico, o avere un logging sempre consistente.

Se state già per mettere mano a logrotate per andare a toccare questo json (già, può saturare il filesystem, come qualsiasi file di log) fermatevi, perché una delle comodità di utilizzare i driver di logging integrati in Docker è che questi hanno a disposizione diverse opzioni interessanti. Due di queste, relative al driver json-file, sono sicuramente:

• max-size: permette di definire la dimensione massima del file json (ad esempio, 10m per 10MB)
• max-file: identifica il numero di file json da mantenere di storico, funziona solo quando max-size è configurato

Usando una combinazione di questi due possiamo ottenere una semplice rotazione dei log ed assicurarci che il nostro amato filesystem abbia sempre spazio per respirare; rilanciamo dunque il nostro container con queste opzioni:

/Users/matteo # docker run -d --rm --log-opt max-size=10m --log-opt max-file=3 alpine ping 8.8.8.8
1739167de6b6843d6e58b60b8b136672c1be0cbb298c9f21b990244ba5a2845c

In questo modo abbiamo detto a Docker che il file di log dovrà essere grande al massimo 10MB, e che dovrà mantenere al massimo 3 file di log. Una volta che il file principale raggiungerà questa dimensione verrà ruotato, ed un nuovo file sarà creato. Quando avremo già 3 file ed il più recente arriverà alla dimensione specificata, il più vecchio sarà eliminato e la rotazione andrà avanti; avremo quindi al massimo picchi di 30MB di occupazione per i log di questo container.

Le comodità rispetto all'utilizzo delle mappature in locale delle directory sono molteplici:

• Rotazione ad-hoc: possiamo impostare logiche di rotazione differenti per ogni container, anche se questi eseguono la stessa applicazione; magari abbiamo bisogno di più log per un ambiente di QA e molti meno nell'ambiente di sviluppo;
• Gestione della sovrapposizione: viene generato uno (o più) file per ogni container, anche se questi sono identici ed eseguiti sullo stesso host; non dobbiamo più preoccuparci di trovare una naming convention che debba prevedere questa casistica
• Possibilità di retention: certo, non è integrata, ma se proprio abbiamo bisogno di fare retention dei log (e per qualsivoglia motivo non possiamo utilizzare altri driver), possiamo analizzare la quantità di logging giornaliero e ritagliare i limiti di dimensione in modo che il file venga ruotato più o meno giornalmente; dopodichè una procedura a crontab può prendere il vecchio json e spostarlo dove più ci aggrada

C'è da notare, nel caso andassimo ad impostare le regole di rotazione di questo driver che i vari comandi Docker per accedere ai log inizierebbero a lavorare solo sul log più recente; eventuali log ruotati saranno esclusi dagli output, e dovremo accedervi utilizzando direttamente il file .json (fortunatamente esiste jq).

 

journald

Un altro driver che fornisce Docker per gestire i log dei vostri container, ammesso che la distribuzione che usate utilizzi systemd come sistema di init, è journald.

Questo sistema utilizza il metodo integrato di systemd per la gestione dei log, interrogabili tramite il comando journalctl.

Una delle comodità nell'usare questo driver rispetto a quello di default di Docker sta nel fatto che, insieme al log, vengono salvati una serie di metadati che possono essere utili per andare ad interrogare e filtrare i log sul sistema. Questi sono:

• CONTAINER_ID: l'id del container che scrive i log, troncato a 12 caratteri (esattamente come lo troviamo nell'output di docker ps
• CONTAINER_ID_FULL: questo è l'id completo del container, in tutti i suoi 64 caratteri
• CONTAINER_NAME: il nome del container nel momento dell'avvio. Nel caso lo abbiate rinominato con il comando 'docker rename', questa modifica non si riflette nei metadati di journald
• CONTAINER_TAG: i tag che sono stati applicati al container
• CONTAINER_PARTIAL_MESSAGE: nel caso le righe di log siano molto lunghe, questa è una versione ottimizzata che permette di avere migliori performance in fase di interrogazione

Ma vediamo subito come funziona; innanzi tutto dobbiamo ricordarci di informare Docker, al momento del lancio del container, di voler usare journald come driver per il logging:

/Users/matteo # docker run -d --rm --log-driver=journald alpine ping 8.8.8.8
984982fcc0f81a6abfa9df60e472d71b2208243da2f6936a9c4c687fef967469

Vedremo adesso, andando ad ispezionare il container, che quel driver è stato selezionato e, di fatto, non è più presente alcuna voce come LogPath:

/Users/matteo # docker ps
CONTAINER ID        IMAGE               COMMAND             CREATED             STATUS              PORTS               NAMES
984982fcc0f8        alpine              "ping 8.8.8.8"      2 minutes ago       Up 2 minutes                            admiring_hypatia
/Users/matteo # docker inspect 984982fcc0f8
...
            "LogConfig": {
                "Type": "journald",
                "Config": {}
            },
...
/Users/matteo # docker inspect 984982fcc0f8 | grep LogPath
        "LogPath": "",

possiamo dunque semplicemente andare ad interrogare con i comandi journalctl per vedere il log del nostro container:

/Users/matteo # journalctl | tail -3
feb 15 16:05:45 ubuntu64 dockerd[8631]: 64 bytes from 8.8.8.8: seq=293 ttl=61 time=27.634 ms
feb 15 16:05:46 ubuntu64 dockerd[8631]: 64 bytes from 8.8.8.8: seq=294 ttl=61 time=43.280 ms
feb 15 16:05:47 ubuntu64 dockerd[8631]: 64 bytes from 8.8.8.8: seq=295 ttl=61 time=27.108 ms

Se avete già avuto modo di utilizzare journalctl, sapete che lanciandolo così senza opzioni visualizza tutti i log gestiti da systemd, in ordine cronologico. Certo, potremmo fare un bel grep di dockerd, ma ci troveremmo con tutti i log di tutti i container.

Qui ci vengono in aiuto i metadati! Partendo dall'ID fornito dal comando ps di Docker, possiamo dire a journalctl di estrarci i log per solo quel container:

/Users/matteo # docker ps
CONTAINER ID        IMAGE               COMMAND             CREATED             STATUS              PORTS               NAMES
984982fcc0f8        alpine              "ping 8.8.8.8"      7 minutes ago       Up 7 minutes                            admiring_hypatia
/Users/matteo # journalctl CONTAINER_ID=984982fcc0f8
-- Logs begin at mer 2017-02-15 12:42:28 CET, end at mer 2017-02-15 16:08:10 CET. --
feb 15 16:00:52 ubuntu64 dockerd[8631]: PING 8.8.8.8 (8.8.8.8): 56 data bytes
feb 15 16:00:52 ubuntu64 dockerd[8631]: 64 bytes from 8.8.8.8: seq=0 ttl=61 time=38.015 ms
...

Questo garantisce una maggiore persistenza dei file di log rispetto al file json, soprattutto lavorando su questi metadati; se proviamo quindi a fermare il nostro container (il che lo distruggerà, data l'opzione --rm), possiamo vedere che i log generati da esso sono ancora presenti sul nostro sistema:

/Users/matteo # docker stop 984982fcc0f8
984982fcc0f8
/Users/matteo # docker ps -a
CONTAINER ID        IMAGE               COMMAND             CREATED             STATUS              PORTS               NAMES
/Users/matteo # journalctl CONTAINER_ID=984982fcc0f8
-- Logs begin at mer 2017-02-15 12:42:28 CET, end at mer 2017-02-15 16:16:06 CET. --
feb 15 16:00:52 ubuntu64 dockerd[8631]: PING 8.8.8.8 (8.8.8.8): 56 data bytes
feb 15 16:00:52 ubuntu64 dockerd[8631]: 64 bytes from 8.8.8.8: seq=0 ttl=61 time=38.015 ms
...

Dobbiamo quindi tenerci uno storico di tutti gli ID che abbiamo utilizzato per tutti i nostri container? Follia pura, per come la vedo io!

Come ben sappiamo l'ID del container è una stringa da 64 caratteri alfanumerici che viene generata randomicamente alla creazione di ogni singolo container, ma esiste un altro metadato che può essere utilizzato per filtrare i log da journalctl e che può essere impostato manualmente in fase di lancio del container, ovvero il CONTAINER_NAME.

Già, perchè se al momento non gli abbiamo dato peso, lasciando che Docker generasse per noi dei nomi (alquanto fantasiosi, come 'admiring_hypatia' o 'heuristic_easley'), questo è un parametro che possiamo impostare ad ogni avvio del container (deve però essere univoco).

Definiamo quindi un nome più parlante (tipo 'google_ping'), lanciamo il container assegnandogli il nome ed assicuriamoci di fermarlo appena possibile. Mantenendo il nostro ping, gli faccio fare solo due iterazioni di ping, dopodichè il comando termina, il container finisce di esistere e viene distrutto:

/Users/matteo # docker run -d --rm --log-driver=journald --name google_ping alpine ping -c 2 8.8.8.8
54190f155f6e527f06d6c621697af674de0ffa30af028c16bda804cc4235012a
/Users/matteo # docker ps -a
CONTAINER ID        IMAGE               COMMAND             CREATED             STATUS              PORTS               NAMES

Come possiamo vedere, nonostante il nostro container non esista più, possiamo interrogare journald filtrano per il nome da noi definito, ed ottenere i log del nostro container:

/Users/matteo # journalctl CONTAINER_NAME=google_ping
-- Logs begin at mer 2017-02-15 12:42:28 CET, end at mer 2017-02-15 16:32:46 CET. --
feb 15 16:32:42 ubuntu64 dockerd[8631]: PING 8.8.8.8 (8.8.8.8): 56 data bytes
feb 15 16:32:42 ubuntu64 dockerd[8631]: 64 bytes from 8.8.8.8: seq=0 ttl=61 time=28.275 ms
feb 15 16:32:43 ubuntu64 dockerd[8631]: 64 bytes from 8.8.8.8: seq=1 ttl=61 time=26.086 ms
feb 15 16:32:43 ubuntu64 dockerd[8631]: 
feb 15 16:32:43 ubuntu64 dockerd[8631]: --- 8.8.8.8 ping statistics ---
feb 15 16:32:43 ubuntu64 dockerd[8631]: 2 packets transmitted, 2 packets received, 0% packet loss
feb 15 16:32:43 ubuntu64 dockerd[8631]: round-trip min/avg/max = 26.086/27.180/28.275 ms

Fin qui, nulla di strano. La cosa interessante è che se in questo momento lanciassimo un altro container con lo stesso nome ed andassimo a vedere i log filtrando per quel metadato:

/Users/matteo # docker run -d --rm --log-driver=journald --name google_ping alpine ping 8.8.8.8
1f98b44b2694dc31a54dd2c4164d922e27c7d6aed3548e48ef290b607fb85a74
/Users/matteo # journalctl CONTAINER_NAME=google_ping
-- Logs begin at mer 2017-02-15 12:42:28 CET, end at mer 2017-02-15 16:32:46 CET. --
feb 15 16:32:42 ubuntu64 dockerd[8631]: PING 8.8.8.8 (8.8.8.8): 56 data bytes
feb 15 16:32:42 ubuntu64 dockerd[8631]: 64 bytes from 8.8.8.8: seq=0 ttl=61 time=28.275 ms
feb 15 16:32:43 ubuntu64 dockerd[8631]: 64 bytes from 8.8.8.8: seq=1 ttl=61 time=26.086 ms
feb 15 16:32:43 ubuntu64 dockerd[8631]: 
feb 15 16:32:43 ubuntu64 dockerd[8631]: --- 8.8.8.8 ping statistics ---
feb 15 16:32:43 ubuntu64 dockerd[8631]: 2 packets transmitted, 2 packets received, 0% packet loss
feb 15 16:32:43 ubuntu64 dockerd[8631]: round-trip min/avg/max = 26.086/27.180/28.275 ms
feb 15 16:37:07 ubuntu64 dockerd[8631]: PING 8.8.8.8 (8.8.8.8): 56 data bytes
feb 15 16:37:07 ubuntu64 dockerd[8631]: 64 bytes from 8.8.8.8: seq=0 ttl=61 time=30.767 ms
feb 15 16:37:08 ubuntu64 dockerd[8631]: 64 bytes from 8.8.8.8: seq=1 ttl=61 time=30.783 ms
feb 15 16:37:09 ubuntu64 dockerd[8631]: 64 bytes from 8.8.8.8: seq=2 ttl=61 time=26.032 ms

Ecco, ora abbiamo, grazie allo stesso filtro, tutti i log scritti da tutti i container con quello specifico nome, indipendentemente che i vari container siano ancora attivi, siano stati distrutti, o siano stati ricreati. Molto comodo, soprattutto se non abbiamo un sistema di orchestration che ci gestisce i container e, magari, vogliamo far girare un determinato servizio in un container; con i classici sistemi di definizione di start/stop dei servizi potremmo fare in modo di creare e distruggere diversi container sempre con lo stesso nome, garantendoci consistenza dei log anche attraverso il reboot.

 

In conclusione

In questa prima parte abbiamo visto come Docker lavora di default e diversi modi sia di organizzare che di gestire i log dei nostri container sulla macchina locale. Nei prossimi articoli vedremo metodi più elastici, che ci permetteranno di automatizzare il logging su sistemi remoti di diverso tipo, garantendoci anche diversi parallelismi per il mantenimento dei log a più livelli.

Tanta carne al fuoco, dunque. Stay tuned!

Leggi il contenuto originale su Mia mamma usa Linux!