Debugging e logging

Il problema che stiamo risolvendo

Quello che fanno tutti quando qualcosa va storto:

def discount(price, rate):
    print("price:", price)
    print("rate:", rate)
    result = price * (1 - rate)
    print("result:", result)
    return result


print(discount(100.0, 0.1))

price: 100.0
rate: 0.1
result: 90.0
90.0

Funziona. Il problema è quello che succede dopo.

Cancelli le righe e la prossima volta vanno riscritte. Le lasci e restano nel codice, e un giorno stampano sul terminale di qualcun altro. E un programma che gira su un server non ha affatto un terminale — dove finisce print lì, nessuno lo sa.

Questo capitolo tratta due cose: come un programma tiene la contabilità del proprio lavoro, e come entrare dentro di lui mentre è rotto.

Alla fine di questo capitolo sarai in grado di

• Leggere un traceback nell'ordine giusto, e trovare il punto reale
• Scrivere messaggi con logging, e scegliere tra i livelli
• Spiegare perché logging.getLogger(__name__) si scrive così
• Conservare l'intero traceback di un errore catturato con log.exception
• Spiegare perché i messaggi si scrivono con %s e non con una f-string
• Fermarsi dentro un programma in esecuzione con breakpoint()

Cosa ti serve prima: Testing con pytest.

Un traceback si legge dal basso

def parse(text):
    return int(text)


def total(rows):
    return sum(parse(row) for row in rows)


print(total(["1", "2", "x"]))

Traceback (most recent call last):
  File "main.py", line 9, in <module>
    print(total(["1", "2", "x"]))
          ^^^^^^^^^^^^^^^^^^^^^^
  File "main.py", line 6, in total
    return sum(parse(row) for row in rows)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "main.py", line 6, in <genexpr>
    return sum(parse(row) for row in rows)
               ^^^^^^^^^^
  File "main.py", line 2, in parse
    return int(text)
           ^^^^^^^^^
ValueError: invalid literal for int() with base 10: 'x'

Moltissime persone lo vedono, si spaventano, e cominciano a leggere dall'alto. L'ordine è quello opposto.

L'ultima riga è la più importante — cosa è successo, e con quale valore. 'x' non è un numero.

Il blocco appena sopra viene al secondo posto — dove è successo: dentro parse, riga 2.

La parte superiore è il percorso che ha portato fin lì, da leggere dall'alto in basso: <module> ha chiamato total, total ha chiamato il generatore, che ha chiamato parse. Questa parte serve quando la domanda è "quale chiamata ha mandato il valore sbagliato".

E i segni ^^^^ mostrano quale parte della riga si è rotta — utilissimi soprattutto su una riga lunga.

Trova il frame più in basso che sia codice tuo. Anche quando metà del traceback è fatta di file di librerie, il problema sta quasi sempre nell'ultima riga che ti appartiene.

logging al posto di print

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s %(name)s - %(message)s")

log = logging.getLogger("shop")

log.debug("this is not shown")
log.info("starting")
log.warning("price is unusually high: %s", 9999)
log.error("could not read the file")

INFO shop - starting
WARNING shop - price is unusually high: 9999
ERROR shop - could not read the file

Il messaggio debug non compare, perché il livello è impostato a INFO. Questa è la differenza essenziale con print: i messaggi restano nel codice, e decidi tu quali si vedono.

I livelli sono cinque, e il loro ordine è quello della loro definizione:

import logging

logging.basicConfig(level=logging.WARNING, format="%(levelname)s - %(message)s")

log = logging.getLogger("shop")

log.debug("debug")
log.info("info")
log.warning("warning")
log.error("error")
log.critical("critical")

WARNING - warning
ERROR - error
CRITICAL - critical

Ecco quando usare ciascuno, in una riga:

• debug — dettagli interni, utili solo mentre si cerca un problema
• info — eventi normali: avviato, quante righe lette, terminato
• warning — qualcosa è insolito, e il lavoro continua
• error — un'operazione è fallita, non il programma
• critical — il programma non può continuare

logging scrive su stderr e print scrive su stdout. In un terminale compaiono entrambi, quindi la differenza passa inosservata — ma python main.py > out.txt manda nel file solo l'output di print e lascia il log sullo schermo. Per questo gli output qui sotto mostrano i due flussi separatamente — prima le righe stampate, poi il log; sul tuo terminale si alternano.

__name__ — il nome del modulo è il nome del logger

import logging

log = logging.getLogger(__name__)


def line_total(price, quantity):
    log.debug("line_total(%s, %s)", price, quantity)
    return round(price * quantity * 1.15, 2)

E in main.py:

import logging

import pricing

logging.basicConfig(level=logging.DEBUG, format="%(levelname)s %(name)s - %(message)s")

log = logging.getLogger(__name__)

log.info("starting")
print(pricing.line_total(15.0, 3))

51.75

INFO __main__ - starting
DEBUG pricing - line_total(15.0, 3)

Il __name__ del capitolo 22 torna, con la stessa identica regola: il file che viene eseguito è __main__, e un modulo importato ha il proprio nome.

Il vantaggio si vede nel log — ogni messaggio dice da dove viene. In un programma di venti moduli, è questo che fa la differenza.

C'è anche un vantaggio meno evidente: i nomi formano un albero attraverso i punti, quindi il livello di shop.pricing si può alzare da solo, mentre il resto del programma resta silenzioso.

Non chiamare basicConfig in una libreria. Ogni modulo scrive solo getLogger(__name__) e invia messaggi; dove vanno e quanti sono è una decisione di main.

Il motivo nasce da due regole insieme. Importare vuol dire eseguire il file. E basicConfig funziona solo la prima volta — una volta avviato il logging, le chiamate successive non fanno nulla, in silenzio. Supponi che pricing.py chiami basicConfig per errore:

import logging

logging.basicConfig(level=logging.WARNING, format="%(message)s")

log = logging.getLogger(__name__)


def line_total(price, quantity):
    log.debug("line_total(%s, %s)", price, quantity)
    return round(price * quantity * 1.15, 2)

Esegui di nuovo main.py qui sopra, senza cambiarlo affatto:

51.75

Tutto qui — nessuna riga di log, e nemmeno un errore. main.py ha fatto import pricing per primo, quindi il basicConfig della libreria è partito per primo e ha impostato il livello a WARNING. Poi il basicConfig(level=logging.DEBUG, ...) di main.py è stato ignorato in silenzio. La libreria ha preso il controllo del logging del programma che l'ha importata.

L'intero traceback di un errore catturato

Il capitolo 24 ha insegnato a catturare gli errori. Ma catturare non dovrebbe voler dire perdere le informazioni.

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s - %(message)s")

log = logging.getLogger("shop")


def parse(text):
    return int(text)


for value in ["1", "x"]:
    try:
        print(parse(value))
    except ValueError:
        log.exception("could not parse %r", value)

print("still running")

1
still running

ERROR - could not parse 'x'
Traceback (most recent call last):
  File "main.py", line 14, in <module>
    print(parse(value))
          ^^^^^^^^^^^^
  File "main.py", line 9, in parse
    return int(text)
           ^^^^^^^^^
ValueError: invalid literal for int() with base 10: 'x'

log.exception conserva l'intero traceback nel log — e il programma va avanti lo stesso.

Questo risolve il dilemma del capitolo 24. except ... : pass perde le informazioni; nessun except ferma il programma. log.exception dà entrambe le cose: il lavoro continua, e resta un resoconto completo di ciò che si è rotto.

Quando serve solo il messaggio, log.error:

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s - %(message)s")

log = logging.getLogger("shop")

try:
    int("x")
except ValueError as err:
    log.error("could not parse: %s", err)

print("done")

done

ERROR - could not parse: invalid literal for int() with base 10: 'x'

La regola è semplice: log.exception dentro un blocco except, log.error fuori. exception ha senso solo mentre un errore viene gestito.

%s nel messaggio, non una f-string

Il modo convenzionale di scrivere un messaggio nel logging sembra strano all'inizio:

log.debug("line_total(%s, %s)", price, quantity)

Il motivo è la pigrizia del logging: se il livello scarta il messaggio, il testo non viene mai composto. Scritto come f-string, la composizione avverrebbe prima, e il risultato verrebbe poi buttato via.

Vale la pena conoscere anche il limite:

import logging

logging.basicConfig(level=logging.WARNING, format="%(levelname)s - %(message)s")

log = logging.getLogger("shop")


def expensive():
    print("expensive() was called")
    return 42


log.debug("value is %s", expensive())
log.debug("value is %s", "cheap")
print("done")

expensive() was called
done

Il messaggio non è stato stampato, eppure expensive() è stata eseguita comunque. Ad essere pigra è la formattazione, non la valutazione degli argomenti — quelli vengono calcolati prima che log.debug venga chiamato, perché così funziona ogni chiamata in Python.

Quindi quando serve qualcosa di costoso solo per il debug, chiedi prima: if log.isEnabledFor(logging.DEBUG):.

Scrivere su un file

import logging
from pathlib import Path

logging.basicConfig(
    level=logging.INFO,
    format="%(levelname)s %(name)s - %(message)s",
    filename="run.log",
)

log = logging.getLogger("shop")
log.info("starting")
log.warning("something odd")

print("nothing was printed to the screen by logging")
print(Path("run.log").read_text(encoding="utf-8"), end="")

nothing was printed to the screen by logging
INFO shop - starting
WARNING shop - something odd

Con filename, i messaggi vanno su un file invece che sullo schermo — e non cambia nemmeno una riga del codice. Qui print e logging sono più distanti che mai: i moduli decidono cosa viene scritto, e main decide dove va.

In pratica si aggiunge anche l'ora nel format:

format="%(asctime)s %(levelname)-8s %(name)s - %(message)s"

che mette data e ora all'inizio di ogni riga. Gli esempi di questo capitolo lo omettono, perché l'output cambierebbe ad ogni esecuzione — e ciò che stampa un corso dovrebbe essere ciò che stampa la tua macchina.

Entrare dentro — breakpoint()

Un log dice cosa è successo. A volte serve invece lo stato in questo momento.

def discount(price, rate):
    result = price * (1 - rate)
    breakpoint()
    return result


print(discount(100.0, 0.1))

Raggiungere breakpoint() ferma il programma e ti dà un prompt. Una sessione è così — la prima riga riporta il percorso completo del tuo file:

> .../main.py(4)discount()
-> return result
(Pdb) p price
100.0
(Pdb) p rate
0.1
(Pdb) p result
90.0
(Pdb) c
90.0

Un piccolo gruppo di comandi copre quasi tutto il lavoro:

• p <nome> — stampa un valore (pp lo stampa in modo leggibile)
• n — la riga successiva, senza entrare dentro una funzione
• s — entra nella funzione
• c — continua fino alla prossima fermata
• l — mostra il codice intorno
• q — esci

Il vantaggio rispetto a print è che non devi decidere in anticipo cosa vuoi vedere. Una volta fermato, si può stampare qualsiasi nome ed eseguire qualsiasi espressione.

Un esempio completo

pricing.py:

"""Prices and tax, with logging instead of prints."""

import logging

log = logging.getLogger(__name__)

TAX_RATE = 0.15


def line_total(price, quantity):
    log.debug("line_total(price=%s, quantity=%s)", price, quantity)
    if quantity < 1:
        raise ValueError(f"quantity must be at least 1: {quantity}")
    return round(price * quantity * (1 + TAX_RATE), 2)


def read_order(rows):
    """Returns the usable lines, logging and skipping the rest."""
    lines = []
    for number, row in enumerate(rows, start=1):
        try:
            name, price, quantity = row.split(",")
            lines.append((name, line_total(float(price), int(quantity))))
        except ValueError:
            log.warning("line %d skipped: %r", number, row)
    log.info("%d of %d lines usable", len(lines), len(rows))
    return lines

main.py:

import logging
import os

import pricing

logging.basicConfig(
    level=logging.DEBUG if os.environ.get("SHOP_DEBUG") else logging.INFO,
    format="%(levelname)-8s %(name)s - %(message)s",
)

log = logging.getLogger(__name__)

ROWS = ["pen,15.0,3", "bag,eight,1", "ink,120.0,2", "clip,5.0,0"]


def main():
    log.info("reading %d rows", len(ROWS))
    for name, amount in pricing.read_order(ROWS):
        print(f"{name:<6} {amount:>9.2f}")


if __name__ == "__main__":
    main()

Eseguito semplicemente come python main.py — le righe stampate:

pen        51.75
ink       276.00

E nel log:

INFO     __main__ - reading 4 rows
WARNING  pricing - line 2 skipped: 'bag,eight,1'
WARNING  pricing - line 4 skipped: 'clip,5.0,0'
INFO     pricing - 2 of 4 lines usable

Ora esegui con SHOP_DEBUG=1, lo stesso codice:

INFO     __main__ - reading 4 rows
DEBUG    pricing - line_total(price=15.0, quantity=3)
WARNING  pricing - line 2 skipped: 'bag,eight,1'
DEBUG    pricing - line_total(price=120.0, quantity=2)
DEBUG    pricing - line_total(price=5.0, quantity=0)
WARNING  pricing - line 4 skipped: 'clip,5.0,0'
INFO     pricing - 2 of 4 lines usable

Cinque cose da notare.

Un programma, due volumi di output, senza cambiare il codice. È questo capitolo in miniatura. Fatto con print, il ciclo di aggiungere righe e poi cancellarle non finirebbe mai.

bag,eight,1 e clip,5.0,0 sono stati saltati per due motivi diversi, e un solo except ValueError le ha catturate entrambe. float("eight") solleva un ValueError, e line_total ne solleva uno per conto suo con quantity=0. Il disegno del capitolo 24 in azione: la funzione più in basso solleva, quella più in alto cattura e decide cosa fare.

Il log di debug mostra ciò che il log ordinario non può mostrare. Per la riga clip, line_total è stata davvero chiamata — lo prova la riga DEBUG ... quantity=0 — e poi ha sollevato l'errore. La riga bag non ha una riga DEBUG, perché float("eight") si è rotto prima. Entrambe le righe sono "saltate", ma si sono rotte in punti diversi, cosa che solo il livello debug rivela.

Il livello arriva dall'ambiente, non dal codice. Per un programma che gira su un server è il modo normale — cambi una variabile e lo rilanci, invece di modificare un file e rilasciarlo.

pricing.py non chiama basicConfig da nessuna parte. Scrive solo getLogger(__name__) e invia messaggi. Dove vanno e quanti sono è una decisione interamente di main. Per questo testare pricing, o usarlo in un altro programma, non toglie il controllo del logging a nessuno.

Quando si rompe

Non compare nulla nel log basicConfig non è stato chiamato, oppure il livello è troppo alto. Il livello predefinito è WARNING, quindi log.info è invisibile di default.

Ho chiamato basicConfig e non è cambiato nulla Ha effetto una sola volta — se il logging è già stato avviato da qualche parte, una chiamata successiva viene ignorata in silenzio. Chiamalo una volta, all'inizio, oppure passa force=True.

Il livello o il formato di main non hanno effetto, e non c'è nessun errore Una libreria importata ha chiamato basicConfig per conto suo, e questo è avvenuto prima della chiamata di main. Così il basicConfig di main viene ignorato in silenzio. Rimuovi basicConfig dalla libreria — una libreria usa solo getLogger(__name__).

Il log non va nel file Il logging era già partito prima che fosse indicato filename. È di nuovo la regola della "sola volta".

Ho usato log.exception e non c'è nessun traceback Il traceback esiste solo dentro un blocco except. Fuori, usa log.error.

Ho eseguito python main.py > out.txt e il log non è nel file logging scrive su stderr. Usa 2> log.txt, oppure filename.

Il traceback è lungo e fatto solo di file di librerie Leggilo dal basso verso l'alto, e trova il frame più in basso che sia codice tuo. Il problema sta quasi sempre lì.

breakpoint() non fa nulla PYTHONBREAKPOINT=0 è impostato. Rimuovilo.

Tocca a te

Prendi il library.py che hai testato nel capitolo 28 e sostituisci ogni print con logging.

• log = logging.getLogger(__name__) in cima al modulo
• Un messaggio debug in add(), con il titolo del libro
• Un warning quando si scartano dati non validi
• Un main.py che chiama basicConfig e prende il livello da una variabile d'ambiente
• Nessun basicConfig in library.py

Poi sei esperimenti:

• Esegui al livello INFO, poi a DEBUG. Hai dovuto cambiare qualche riga di codice?
• Aggiungi filename="run.log" a basicConfig. Cosa resta sullo schermo?
• Chiama basicConfig anche in library.py, con un livello diverso da quello di main.py. Di chi è il livello che viene usato ora — e perché?
• Provoca di proposito un KeyError, poi nel blocco except scrivi una volta log.error(err) e una volta log.exception("..."). Quale è più utile, e perché?
• Scrivi log.debug("%s", expensive()) dove expensive() stampa qualcosa, e lascia il livello a WARNING. expensive() viene eseguita?
• Inserisci un breakpoint() ed esplora con p, n e c.

Il quarto esperimento è l'ultima parola di questo capitolo. Come sta andando un programma lo si sa da ciò che lascia dietro di sé — e un blocco except che non lascia nulla ha solo rimandato la domanda.

Cosa c'è dopo

Questa è la fine del corso di Python. Dopo 29 capitoli, sai scrivere un programma, gestire ciò che si rompe, testarlo e vedere cosa sta facendo — e gli ultimi tre sono ciò che tiene un programma in vita oltre il suo primo giorno.

Il passo successivo non è più imparare il linguaggio, ma farci qualcosa. Il corso di pandas parte esattamente da lì: i file CSV del capitolo 25, ma con migliaia di righe, e domande a cui un ciclo non è più un modo sensato di rispondere.