Esempio di diagnostica in produzione.

Introduzione

È da qualche tempo che ho queste note che rimbalzano da un portatile all'altro e ho pensato che sarebbe carino formattarle in un articoletto per gli interessati. In questo breve articolo daremo un occhio alla mia cassetta degli attrezzi che uso ogni volta che devo capire cosa si è rotto (spesso e volentieri in un ambiente di produzione) durante l'esecuzione di un programma Python scritto dal mio team o da un altro.

Un DevOps ha sempre il terrore di essere svegliato alle 3 del mattino nel weekend per dare dei calci ad un qualche sistema che singhiozza o che non ne vuole proprio sapere di ripartire automaticamente e anche se siamo generalmente costretti a dormire con un occhio aperto, si può fare tanto per alleviare l'ansia da reperibilità. Spesso quest'ansia sparisce con il tempo, con l'esperienza che si accumula e con la conoscenza del sistema supportato che si approfondisce.

In ogni caso, ci sono degli attrezzi del mestiere che funzionano in ogni situazione.

Scrivere del buon codice

E qui non voglio certo fare finta che il codice che scrivo sia ottimo o buono. La verità è che più il tempo passa, più il codice che scriviamo evolve, fino a che non riconosciamo più quello che abbiamo scritto un anno prima. Il che è ottimo! Significa che stiamo imparando da tutti gli errori precedenti.

In generale, ci sono alcune regole di base che tutti i programmatori dovrebbero seguire. Questa non è una lista completa, ma sono fondamenta su cui costruire il resto. È impossibile scrivere codice che non si rompe mai, ma possiamo aiutarci quando qualcosa di imprevisto succede se siamo stati attenti durante la stesura del programma.

Documentare il codice

Mi capita spesso di lavorare con dei cowboy che vomitano codice in poche ore che più o meno funziona senza documentarlo, fino a quando questo programma si spacca in modo imprevisto ed è panico generale. Commenti e documentazione (interna al codice ed esterna) è essenziale per capire come un programma è strutturato e aiuta a trovare problemi logici prima ancora che il programma sia fatto partire.

Esempio di una buona docstring. Si notino le annotazioni del tipo dei parametri e del valore di ritorno e la descrizione degli stessi. Non è necessario leggere il codice per capire il comportamento della funzione.

def _complex_flight_path_list_index(departure_airport: str, arrival_airport: str) -> int:
    """
    Search COMPLEX_FLIGHT_PATHS list for the requested flight path. Return the index of the list in which the
    record has been found, or return -1 if no record exists for the specified path.

    :param departure_airport: departing airport IATA code (ie. 'SEA', 'PDX')
    :param arrival_airport: arrival airport IATA code (ie. 'SEA', 'PDX')

    :return: index of complex path dictionary in COMPLEX_FLIGHT_PATHS list or -1 if path is not found
    """
    for index, complex_flight_path in enumerate(constants.COMPLEX_FLIGHT_PATHS):
        if {departure_airport, arrival_airport} == set(complex_flight_path["flight_path"]):
            logger.debug(f'{departure_airport} -> {arrival_airport} is a complex flight path')
            return index
    return -1

Esempio di un buon commento. Certe idee complesse devono essere ben dettagliate nel programma, anche se riguardano una sola banale riga di codice. Non bisogna mai dare per scontato che chi legge il codice sia famigliare con il comportamento del programma e che capisca al volo quello che per noi potrebbe essere ovvio.

while True:
    # If serial.readline() is returning an empty string, the controller hasn't written on the serial line within
    # ARDUINO_SERIAL_TIMEOUT seconds from the read operation start. This can happen when either no command was
    # sent via Arduino._write_serial() before attempting to read, or when the operation has failed to complete
    # (ie. controller crash or unexpected return code.) A counter is kept to ensure we eventually exit from the
    # read method and don't get stuck in an infinite loop.
    if read_timeouts_count >= constants.MAX_EMPTY_STRING_COUNT:
        raise ArduinoError(f'Serial read operation timed out after {read_timeouts_count} attempts.')

Seguire gli standard della comunità

Ad esempio PEP8 per Python. Se tutti seguiamo lo stesso stile di programmazione non mi devo preoccupare che il codice di qualcun altro si rompa per errori banali e so già più o meno come navigarlo visto che è strutturato in modo simile al mio. Ci sono programmi apposta per controllare la stesura del codice, i cosiddetti "linters" (ad esempio, flake8 per Python.)

Logging

Come i commenti e la documentazione, un buon sistema di logging è essenziale per capire cosa sta facendo il nostro programma e perché una certa decisione è stata presa piuttosto che un'altra. Un buon sistema di logging è generalmente frutto di esperienza e fine-tuning fatto nel tempo, e dipende da quali informazioni sono ritenute importanti. È buona pratica comunque avere una riga di log (a livello DEBUG) in ogni funzione che si attraversa, così da poter diagnosticare con precisione il comportamento del programma.

Il mio formato di log preferito è questo (potete copiarlo ed eseguirlo nell'interpreter di Python):

import logging

# Logging setup
log = logging.getLogger()
logging.basicConfig(
    format='%(asctime)s [%(levelname)s] %(module)s:%(lineno)d %(message)s',
    datefmt='%Y-%m-%d %H:%M:%S'
)

log.warning('Questa è una riga di WARNING')

Che produce (ad esempio):

2021-10-09 09:23:07 [ERROR] client.py:78 An error occured while initializing the Kubernetes API client: No secrets found in keystore.

Il formato della data (anno/mese/giorno ora:minuti:secondi) è essenziale per poter ordinare e confrontare diversi log. Altri formati di data - ad esempio l'americanissimo mese/giorno/anno - non possono essere facilmente ordinati con tool di sistema (il sort di Unix) visto che, ad esempio, il 31 ottobre 2021 sarebbe nel futuro rispetto a marzo 2022:

03/04/2022 < 10/31/2021

Altro elemento essenziale della linea di log d'esempio è l'esatta posizione in cui la riga è stata generata (modulo:riga) che aiuta a separare errori simili e ad immediatamente indicare la funzione colpevole.

Infine, l'errore nell'esempio è chiaro, ci dice esattamente cos’è andato storto. Molti programmatori tendono ad essere pigri con i dettagli e spesso ci si trova un log che dice "L'operazione è fallita", che causa solo frustrazione e tentativi di lanciare il portatile dalla finestra. Se loggate un'eccezione, stampate sempre il suo messaggio:

try:
    return l.pop()
except IndexError as e:
    log.error(f'Failed to load element from list: {e}')
    return None

Specializzare le funzioni

Ogni funzione di un programma deve essere specializzata in - idealmente - una sola operazione. Ad esempio, se vogliamo scaricare e convertire un'immagine da Internet, avremo bisogno di una funzione per gestire il download dell'immagine, una per convertire l'immagine nel formato che ci interessa ed una per scrivere su disco il prodotto.

Più una funzione è complessa e ricca di operazioni, più magia nera si nasconde e più è difficile isolarla. Inoltre, funzioni semplici si prestano molto meglio ad essere testate completamente. I linter di qualunque linguaggio vi segnalano funzioni troppo lunghe o troppo complesse. Ascoltate il loro monito!

Testare il codice

Nel mio vecchio team vigeva la regola che se i test non coprono almeno il 95% del codice, quel programma non vedrà mai la luce del giorno. Il che è una bella seccatura certe volte, visto che una patch scritta in 20 minuti richiede 2 ore per stendere i nuovi test e aggiornare quelli esistenti. Ma test ben scritti vi aiuteranno a scoprire errori logici e - forse più importante - a proteggervi da nuovo codice (o nuove versioni di librerie) che accidentalmente modifica il comportamento di funzioni già esistenti (questo fenomeno è chiamato regressione.)

Evitare anti-patterns

Che sono tutti quei modi di scrivere codice scoraggiati dalla comunità e dal buonsenso. Ad esempio, non utilizzare variabili globali, non riassegnare nomi riservati dal compilatore a variabili, non usare import * e così via. Una lista di anti-patterns comuni si può trovare qui.

Static typing

Il bello di Python (e altri linguaggi dynamically typed) è che uno script funzionante può essere scritto in pochi minuti senza doversi preoccupare di formalizzare il tipo di variabile che si usa e doverne allocare una nuova ogni volta che bisogna fare una conversione di tipo (es. da intero a stringa). Ma la verità è che in un programma complesso di migliaia di righe la struttura delle variabili è ben definita ed è a tutti gli effetti statica. Python supporta il typing statico di variabili, cioè ci permette di dichiarare una variabile intera, piuttosto che stringa o dizionario. Python di per sé non blocca l'esecuzione di un programma se il contenuto di una variabile non risulta essere del tipo dichiarato, ma si possono usare altri tool (ad esempio mypy) per verificare che le funzioni si passino il tipo corretto di variabile.

Lo static typing è molto utile per confermare che il programma gestisca solo il tipo di variabili che si aspetta.

from typing import List


def pretty_print_log(log_list: List[str]) -> str:
    ...

In questo caso la funzione pretty_print_log() si aspetta una lista di stringhe e restituirà una stringa sola. Questa annotazione ci permette di verificare che le funzioni chiamanti passino effettivamente una lista, e che siano pronte a gestire il risultato di tipo stringa.

Il software deve morire

Quando un programma si trova ad interagire con altre entità, che sia un database, un'API o un message broker, prima o poi qualcosa andrà storto e il nostro programma dovrà prendere una decisione su come proseguire.

Certi eventi possono essere corretti. Ad esempio, se un'API smette di rispondere possiamo chiedere al programma di riprovare la richiesta un certo numero di volte prima di gettare la spugna. Altre volte, invece, lo stato di un programma può essere sufficientemente corrotto da dover abortire l'operazione e tirare un'eccezione. Se il vostro programma è scritto bene, un evento che porta ad una corruzione inaspettata dei dati su cui lavora forzerà il programma ad uscire con un errore chiaro sul file di log.

Ci sono alcune scuole di pensiero che sostengono che un programma debba essere in grado di recuperare la normale operazione indipendentemente da cosa è andato storto. Lasciate che condivida con voi un'opinione su questa visione: sono tutte stupidaggini da startup fondate nella Silicon Valley da due diciannovenni. Se un programma si ritrova in una situazione critica, è suo dovere morire e donare la propria salma al manutentore perché una situazione del genere venga capita e gestita.

Un buon pezzo di codice che si ritrova in uno stato inaspettato deve almeno generare un core dump (la salma di cui sopra) così che il suo stato possa essere analizzato.

Analisi post mortem

Cosa fare quando un programma muore inaspettatamente.

Generare un coredump

Un file di coredump è un'immagine dello stato del programma, incluse le pagine di memoria che stava utilizzando. Questo file può essere caricato in GDB e analizzato.

Per prima cosa, verifichiamo che il sistema operativo permetta la generazione dei dump. Su Linux possiamo utilizzare ulimit -c. Il terminale vi restituirà la dimensione massima (in kib) dei file di dump generati. Se il risultato è 0 dovremo modificare il limite per consentire al sistema operativo di scrivere su disco questi file.

Su Debian (per altre distro cercate la documentazione del OS) basta creare un file in limits.d con le dimensioni del coredump. Ad esempio, sulla mia macchina ho scritto nel file /etc/security/limits.d/core.conf:

*       soft    core    unlimited
root    soft    core    unlimited

In questo modo il sistema operativo non ha limiti di dimensioni per i file di dump. In un sistema di produzione potreste voler mettere un limite a seconda dello spazio del disco.

Dopo un riavvio del sistema tutti i programmi potranno generare un coredump se necessario. Il coredump è generato se il programma è arrestato col segnale esterno SIGABRT (che si può invocare con kill -SIGABRT [PID]) o se lo stesso chiede al sistema operativo di abortire (in Python os.abort())

Analisi con GDB

In Debian, GDB e le librerie di supporto per Python si installano con apt-get.

apt-get install gdb python3-dbg

Per caricare un coredump di un programma Python basta invocare:

gdb -c [COREDUMP] --args $(which python3)

SIGABRT

Per provare che il tutto funzioni ho scritto un banale programma che ogni 3 secondi incrementa e stampa il valore di una variabile:

import time


def main():
    a = 0
    while True:
        print(a)
        time.sleep(3)
        a += 1


if __name__ == '__main__':
    main()

Lancio questo programma e lo termino con un SIGABRT:

jon@Winry:~$ ps aux | grep test.py
jon         1716  0.2  0.1  11660  6992 pts/2    S+   16:21   0:00 python test.py
jon         1719  0.0  0.0   3180   720 pts/1    S+   16:21   0:00 grep test.py

jon@Winry:~$ kill -SIGABRT 1716

jon@Winry:~$ ll core
-rw------- 1 jon jon 3.0M Oct  9 16:21 core

A questo punto, lanciando ls (il mio ll è un alias per ls -lah) possiamo vedere che nella stessa directory dove risiede lo script test.py è stato creato il file di dump core. Possiamo ora aprirlo con gdb.

jon@Winry:~$ gdb -c core --args $(which python3)
GNU gdb (Debian 10.1-1.7) 10.1.90.20210103-git

[..]

(gdb) py-list
   3
   4    def main():
   5        a = 0
   6        while True:
   7            print(a)
  >8            time.sleep(3)
   9            a += 1
  10 
  11 
  12    if __name__ == '__main__':
  13        main()

Eseguendo il comando py-list possiamo vedere esattamente la riga che Python stava eseguendo quando il programma è stato interrotto. Con py-bt possiamo anche vedere il backtrace (la sequenza di chiamate) che ci ha portato ad eseguire quella funzione.

(gdb) py-bt
Traceback (most recent call first):
  <built-in method sleep of module object at remote 0x7f5854fea400>
  File "/home/jon/test.py", line 8, in main
    time.sleep(3)
  File "/home/jon/test.py", line 13, in <module>
    main()

os.abort()

L'esempio sopra funziona bene ed è utilissimo per programmi che non rispondono, ma richiede che sia un operatore ad inviare SIGABRT al processo. Se invece volessimo che fosse il programma stesso a generare un dump? In questo esempio, il programma genera un coredump quando un'eccezione non gestita viene incontrata:

import os
import time


def something():
    a = []
    a.pop()


def main():
    try:
        something()
    except Exception as e:
        print('Whoops!! Error was: {e}')
        os.abort()


if __name__ == '__main__':
    main()

La funzione something() causerà un'eccezione, visto che a.pop() non può restituire un elemento di una lista vuota. Purtroppo, a causa di un errore di sintassi, l'errore {e} non verrà interpolato correttamente e ci ritroveremo con un output inutile:

jon@Winry:~$ python test.py
Whoops!! Error was: {e}
Aborted (core dumped)

Possiamo quindi utilizzare GDB per stampare le variabili locali e scoprire cosa contiene e:

jon@Winry:~$ gdb -c core --args $(which python3)
GNU gdb (Debian 10.1-1.7) 10.1.90.20210103-git

[..]

(gdb) py-bt
Traceback (most recent call first):
  <built-in method abort of module object at remote 0x7feee63976d0>
  File "/home/jon/test.py", line 15, in main
    os.abort()
  File "/home/jon/test.py", line 19, in <module>
    main()

(gdb) py-list
  10    def main():
  11        try:
  12            something()
  13        except Exception as e:
  14            print('Whoops!! Error was: {e}')
 >15            os.abort()
  16
  17
  18    if __name__ == '__main__':
  19        main()

(gdb) py-up
#8 Frame 0x7feee6378dd0, for file /home/jon/test.py, line 15, in main (e=IndexError('pop from empty list',))
    os.abort()

(gdb) py-locals
e = IndexError('pop from empty list',)

Ed eccoci qui, abbiamo scoperto che la variabile e contiene un'eccezione di tipo IndexError causata da un pop(). Adesso è solo una questione di capire perchè stiamo facendo pop() su una lista vuota!

Ancora una volta abbiamo iniziato con py-bt e py-list che ci dicono che il programma si è trovato in una situazione non gestita e ha chiamato os.abort(). Da qui abbiamo invocato un py-up che chiede a GDB di analizzare il livello dello stack sopra all'ultimo. Questo perchè GDB automaticamente si interessa dell'ultimo frame dello stacktrace, e cioè - in questo caso - dell'operazione abort del sistema operativo, identificato come "built-in method abort of module object", mentre a noi interessa il livello leggermente sopra, e cioè la parte del nostro programma che ha chiamato os.abort().

Una volta che il frame corretto è selezionato (file /home/jon/test.py, line 15) possiamo stampare tutte le variabili locali con py-locals.

Analisi online

Cosa fare quando un programma non risponde.

Analisi con GDB

GDB può essere utilizzato anche per analizzare programmi in esecuzione. Attenzione però: GDB sospenderà l'esecuzione del programma per darci modo di vedere esattamente il suo stato. È possibile impostare breakpoints e procedere per step attraverso le librerie di CPython (il compilatore di Python), ma questo risulta spesso troppo complesso e macchinoso per quello che ci interessa. È comunque bene sapere che questa opzione esiste.

gdb -p [PID] --args $(which python3)

Esempio:

jon@Winry:~$ ps aux | grep test.py
jon         7004  0.2  0.1  11660  7032 pts/2    S+   19:52   0:00 python test.py
jon         7007  0.0  0.0   3180   712 pts/1    S+   19:52   0:00 grep test.py

jon@Winry:~$ gdb -p 7004 --args $(which python3)
GNU gdb (Debian 10.1-1.7) 10.1.90.20210103-git

[..]

(gdb) py-bt
Traceback (most recent call first):
  <built-in method sleep of module object at remote 0x7f0f7d13c400>
  File "/home/jon/test.py", line 8, in main
    time.sleep(3)
  File "/home/jon/test.py", line 13, in <module>
    main()

(gdb) step
PyEval_RestoreThread (tstate=0x11bed50) at ../Include/internal/pycore_pystate.h:82
82      ../Include/internal/pycore_pystate.h: No such file or directory.

(gdb) continue
Continuing.
^C
Program received signal SIGINT, Interrupt.

py-spy

py-spy è un'eccellente utility scritta per analizzare programmi in Python. Generalmente utilizzata per profiling (vedi capitolo successivo), è anche molto utile per capire in che stato si trova un programma in esecuzione.

Lo script può essere usato in ambienti di produzione in quanto non influisce sul programma in esecuzione e può essere installato con pip:

pip install py-spy

Per vedere l'operazione corrente di un programma:

py-spy dump --locals --pid [PID]

jon@Winry:~$ py-spy dump --locals --pid 7004
Process 7004: python test.py
Python v3.9.2 (/usr/bin/python3.9)

Thread 7004 (idle)
    main (test.py:8)
        Locals:
            a_variable: 20
    <module> (test.py:13)

In questo modo vediamo che il programma è composto da un solo thread, al momento sospeso (idling), correntemente alla riga 8 (sta eseguendo un time.sleep(3)). L'opzione --locals ci permette di stampare tutte le variabili locali, per aiutarci ad analizzare eventuali problemi.

py-spy può anche essere utilizzato per visualizzare lo stato del programma come in un task manager, così da vedere quali sono le funzioni che occupano più tempo nel programma. Vedi esempio.

py-spy top --pid [PID]

Profiling

Se un programma che si rompe dà decisamente fastidio, non c'è niente di peggio di un programma che funziona a tratti. Magari avete questo scritto questo pezzo di codice che va a cannone per 5 secondi e poi per 3 secondi non fa niente per poi ripartire all'improvviso, e non riuscite a capire come sia possibile. Il profiling di un programma può aiutarci a capire dove spende il tempo il nostro codice.

Flame graph

Il modo più semplice per rappresentare graficamente il tempo speso dal nostro programma è attraverso un flame graph. Nell'immagine qui sotto, ho fatto profiling di un server web Flask che avevo scritto tempo fa.

Clicca per ingrandire

Aprendo il file SVG con un browser moderno possiamo ingrandire la sezione che ci interessa. Ad esempio, ingrandendo l'immagine sopra scopro che il modulo routes/route_index.py, che gestisce tutte le chiamate all'homepage del sito, spende la maggior parte del suo tempo dentro le funzioni di SQLAlchemy, a recuperare dati dal database remoto. Questo già mi fa intuire che il programma non è sufficientemente ottimizzato, e un semplice sistema di caching potrebbe aumentare molto le prestazioni.

Clicca per ingrandire

Profiling con py-spy

py-spy ci permette di analizzare un processo esistente e campionarlo per un numero arbitrario di secondi o di lanciare un nuovo processo e campionarlo fino al suo termine. Il campionamento può essere effettuato su sistemi in produzione senza comprometterne il funzionamento.

Per analizzare un processo esistente basta specificare il PID del processo ed il tempo di campionamento:

py-spy record --duration 30 -o flame.svg --pid [PID]

In questo caso, py-spy campionerà il processo PID 100 volte al secondo per 30 secondi e genererà il file flame.svg.

Per analizzare un processo dalla sua nascita alla sua morte è invece sufficiente lanciare il programma dopo gli argomenti di py-spy.

py-spy record -o flame.svg -- python test.py

Con py-spy è anche possibile generare flame graphs compatibili con speedscope. Per dettagli e documentazione fate riferimento alla homepage del progetto su GitHub: https://github.com/benfred/py-spy

Debugging con PySnooper

A volte è più semplice/comodo arrestare un programma per cambiare qualche riga di logging o aggiungere una serie di print() in una funzione per vedere esattamente il valore delle variabili durante l'esecuzione. Il metodo più rapido che ho trovato è usare PySnooper per decorare la funzione che mi interessa.

PySnooper si può installare con pip.

pip install pysnooper

Prendiamo un banale programma che stampa le lettere da 'a' a 'c':

from string import ascii_letters


def do_stuff():    
    for i in range(3):
        print(ascii_letters[i])


def main():
    do_stuff()


if __name__ == '__main__':
    main()

Eseguendo il programma otteniamo:

jon@Winry:~$ python test.py
a
b
c

Se mi interessasse osservare le variabili all'interno della funzione do_stuff(), mi basterebbe decorarla con pysnooper.snoop().

from string import ascii_letters

import pysnooper  # DEBUG ONLY - DELETE ME


@pysnooper.snoop()
def do_stuff():    
    for i in range(3):
        print(ascii_letters[i])

Lanciando di nuovo lo script, l'output sarà il seguente:

jon@Winry:~$ python test.py 
Source path:... /home/jon/test.py
22:55:34.355050 call         5 def do_stuff():
22:55:34.355206 line         6     for i in range(3):
New var:....... i = 0
22:55:34.355244 line         7         print(ascii_letters[i])
a
22:55:34.355298 line         6     for i in range(3):
Modified var:.. i = 1
22:55:34.355347 line         7         print(ascii_letters[i])
b
22:55:34.355427 line         6     for i in range(3):
Modified var:.. i = 2
22:55:34.355517 line         7         print(ascii_letters[i])
c
22:55:34.355629 line         6     for i in range(3):
22:55:34.355685 return       6     for i in range(3):
Return value:.. None
Elapsed time: 00:00:00.000740

In pochi secondi abbiamo ottenuto quello che cercavamo senza scrivere una marea di print() nella funzione.

Conclusione

Come potete immaginare, esistono molti tool diversi adatti per specifiche funzioni. Quelli che ho elencato in questo articolo sono quelli che tendo ad usare di più e che mi aiutano a dormire bene la notte. Quali altri conoscete e usate? Lasciate un commento!

-J