Débogage et journalisation

Le problème que nous résolvons

Ce que tout le monde fait quand quelque chose ne va pas :

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

Ça marche. Le problème, c'est ce qui se passe ensuite.

Supprimez les lignes, et il faudra les réécrire la prochaine fois. Laissez-les, et elles restent dans le code ; un jour, elles s'afficheront dans le terminal de quelqu'un d'autre. Et un programme qui tourne sur un serveur n'a pas du tout de terminal — là où print écrit, personne ne le sait.

Ce chapitre traite de deux choses : comment un programme garde une trace de son propre travail, et comment regarder à l'intérieur quand il est cassé.

À la fin de ce chapitre vous pourrez

• Lire un traceback dans le bon ordre, et trouver le vrai endroit du problème
• Écrire des messages avec logging, et choisir entre les niveaux
• Expliquer pourquoi on écrit logging.getLogger(__name__) de cette façon
• Garder tout le traceback d'une erreur interceptée avec log.exception
• Expliquer pourquoi les messages s'écrivent avec %s plutôt qu'avec une f-string
• Arrêter un programme en cours d'exécution avec breakpoint()

Ce qu'il vous faut d'abord : Tester avec pytest.

Un traceback se lit depuis le bas

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'

Beaucoup de gens voient ceci, s'effraient, et commencent à lire par le haut. L'ordre est inverse.

La dernière ligne compte le plus — ce qui s'est passé, et sur quelle valeur. 'x' n'est pas un nombre.

Le bloc juste au-dessus est le deuxième — où c'est arrivé : dans parse, ligne 2.

La partie du haut est le chemin qui a mené là, à lire de haut en bas : <module> a appelé total, total a appelé le générateur, qui a appelé parse. Cette partie est utile quand la question est « quel appel a envoyé la mauvaise valeur ».

Et les marques ^^^^ montrent quelle partie de la ligne a cassé — très utile sur une ligne longue.

Repérez la frame la plus basse qui est votre propre code. Même si la moitié du traceback concerne des fichiers de bibliothèque, le problème se trouve presque toujours là.

logging à la place de 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

Le message debug est absent, car le niveau est réglé sur INFO. C'est la différence essentielle avec print : les messages restent dans le code, et c'est vous qui décidez lesquels sont affichés.

Il y a cinq niveaux, rangés du moins grave au plus grave :

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

Lesquels, quand, en une ligne chacun :

• debug — détail interne, utile seulement pendant la recherche d'un bug
• info — événements normaux : démarrage, nombre de lignes lues, fin
• warning — quelque chose d'inhabituel, et le travail continue
• error — un travail a échoué, pas le programme
• critical — le programme ne peut pas continuer

logging écrit sur stderr et print écrit sur stdout. Dans un terminal, les deux apparaissent, donc la différence passe inaperçue — mais python main.py > out.txt n'envoie dans le fichier que la sortie de print et laisse le journal à l'écran. C'est pourquoi les résultats ci-dessous montrent séparément les deux flux : d'abord les lignes affichées, puis le journal. Dans votre terminal, elles se mélangent.

__name__ — le nom du module sert de nom au 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)

Et dans 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)

Le __name__ du chapitre 22 revient, selon exactement la même règle : le fichier lancé est __main__, et un module importé a son propre nom.

Le bénéfice se voit dans le journal : chaque message indique d'où il vient. Dans un programme de vingt modules, c'est ce qui fait la différence.

Il y a aussi un bénéfice moins visible : grâce aux points, les noms forment un arbre. Le niveau de shop.pricing peut donc être monté tout seul, pendant que le reste du programme reste silencieux.

N'appelez pas basicConfig dans une bibliothèque. Chaque module écrit seulement getLogger(__name__) et envoie ses messages ; où ils vont et combien il y en a, c'est la décision de main.

La raison vient de deux règles combinées. Importer un module revient à l'exécuter. Et basicConfig ne fonctionne que la première fois : une fois la journalisation configurée, les appels suivants ne font rien, sans un mot. Imaginons que pricing.py appelle basicConfig lui-même, par erreur :

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)

Relancez le main.py ci-dessus, sans le modifier du tout :

51.75

C'est tout : aucune ligne de journal, et aucune erreur non plus. main.py a fait import pricing en premier, donc le basicConfig de la bibliothèque s'est exécuté en premier et a réglé le niveau sur WARNING. Puis le basicConfig(level=logging.DEBUG, ...) de main.py a été ignoré en silence. La bibliothèque a pris la main sur la journalisation du programme qui l'importait.

Le traceback complet d'une erreur interceptée

Le chapitre 24 a appris à intercepter les erreurs. Mais intercepter ne doit pas vouloir dire perdre l'information.

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 garde tout le traceback dans le journal — et le programme continue.

Cela résout le dilemme du chapitre 24. except ... : pass fait perdre l'information ; pas de except du tout arrête le programme. log.exception offre les deux : le travail continue, et un compte rendu complet de ce qui a cassé est conservé.

Quand seul le message est voulu, on utilise 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 règle est simple : log.exception dans un bloc except, log.error en dehors. exception n'a de sens que pendant qu'une erreur est traitée.

%s dans le message, pas une f-string

La façon habituelle d'écrire un message avec logging paraît étrange au début :

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

La raison est la paresse : si le niveau écarte le message, le texte n'est jamais assemblé. Écrit en f-string, l'assemblage aurait eu lieu d'abord, et le résultat aurait ensuite été jeté.

La limite mérite aussi d'être connue :

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

Le message n'a pas été affiché, et expensive() s'est quand même exécutée. Ce qui est paresseux, c'est le formatage, pas l'évaluation des arguments : ceux-ci sont calculés avant que log.debug soit appelé, car c'est ainsi que fonctionne tout appel en Python.

Donc, quand quelque chose de coûteux n'est voulu que pour le débogage, vérifiez d'abord : if log.isEnabledFor(logging.DEBUG):.

Écrire dans un fichier

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

Avec filename, les messages vont dans un fichier au lieu de l'écran — et pas une seule ligne du code ne change. C'est là que print et logging sont le plus éloignés : les modules décident de ce qui est écrit, et main décide où ça va.

En pratique, l'heure figure aussi dans le format :

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

Cela met une date et une heure au début de chaque ligne. Les exemples de ce chapitre l'omettent, parce que la sortie changerait à chaque exécution — et ce qu'un cours affiche doit correspondre à ce qu'affiche votre machine.

Entrer dans le programme — breakpoint()

Un journal dit ce qui s'est passé. Parfois, ce qu'on veut, c'est l'état à l'instant présent.

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


print(discount(100.0, 0.1))

Atteindre breakpoint() arrête le programme et affiche une invite. Une session ressemble à ceci — la première ligne contient le chemin complet de votre propre fichier :

> .../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

Quelques commandes suffisent pour l'essentiel :

• p <name> — afficher une valeur (pp l'affiche joliment)
• n — la ligne suivante, sans entrer dans une fonction
• s — entrer dans la fonction
• c — continuer jusqu'au prochain arrêt
• l — afficher le code autour
• q — quitter

L'avantage par rapport à print, c'est que vous n'avez pas à décider à l'avance ce que vous voulez voir. Une fois arrêté, n'importe quel nom peut être affiché et n'importe quelle expression exécutée.

Un exemple complet

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()

Lancé simplement avec python main.py — les lignes affichées :

pen        51.75
ink       276.00

Et dans le journal :

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

Maintenant, lancez avec SHOP_DEBUG=1, le même code :

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

Cinq points à remarquer.

Un seul programme, deux volumes de sortie, sans modifier le code. C'est tout ce chapitre en miniature. Avec print, le cycle d'ajout puis de suppression de lignes n'en finirait jamais.

bag,eight,1 et clip,5.0,0 ont été ignorées pour deux raisons différentes, et un seul except ValueError les a attrapées toutes les deux. float("eight") lève une ValueError, et line_total en lève une elle-même pour quantity=0. La conception du chapitre 24 à l'œuvre : la fonction du bas lève l'erreur, la fonction du haut l'intercepte et décide quoi faire.

Le journal de débogage montre ce que le journal ordinaire ne montre pas. Pour la ligne clip, line_total a bien été appelée — la ligne DEBUG ... quantity=0 le prouve — puis elle a levé une erreur. La ligne bag n'a pas de ligne DEBUG, parce que float("eight") a échoué avant. Les deux lignes sont « ignorées », et elles ont cassé à des endroits différents, ce que seul le niveau debug révèle.

Le niveau vient de l'environnement, pas du code. Pour un programme qui tourne sur un serveur, c'est la voie normale : on change une variable et on relance, plutôt que de modifier un fichier et de le republier.

pricing.py n'appelle basicConfig nulle part. Il se contente d'écrire getLogger(__name__) et d'envoyer des messages. Où ils vont et combien il y en a relève entièrement de main. C'est pourquoi tester pricing, ou l'utiliser dans un autre programme, ne prend le contrôle de la journalisation de personne.

Quand ça casse

Rien n'apparaît dans le journal basicConfig n'a pas été appelé, ou le niveau est trop élevé. Le niveau par défaut est WARNING, donc log.info est invisible par défaut.

J'ai appelé basicConfig et rien n'a changé Il ne prend effet qu'une fois : si la journalisation a déjà démarré quelque part, un appel ultérieur est ignoré sans bruit. Appelez-le une seule fois, au tout début, ou passez force=True.

Le niveau ou le format de main n'a aucun effet, et il n'y a pas d'erreur Une bibliothèque importée a appelé basicConfig elle-même, et cela s'est exécuté avant l'appel de main. Le basicConfig de main est donc ignoré en silence. Retirez basicConfig de la bibliothèque — une bibliothèque n'utilise que getLogger(__name__).

Le journal ne va pas dans le fichier La journalisation avait déjà démarré avant que filename soit donné. La règle du « une seule fois », encore.

J'ai utilisé log.exception et il n'y a pas de traceback Il n'a de traceback qu'à l'intérieur d'un bloc except. En dehors, utilisez log.error.

J'ai lancé python main.py > out.txt et le journal n'est pas dans le fichier logging écrit sur stderr. Utilisez 2> log.txt, ou filename.

Le traceback est long et ne contient que des fichiers de bibliothèque Lisez de bas en haut, et repérez la frame la plus basse qui est votre propre code. Le problème se trouve presque toujours là.

breakpoint() ne fait rien PYTHONBREAKPOINT=0 est défini. Supprimez-le.

À vous de jouer

Prenez le library.py que vous avez testé au chapitre 28, et remplacez chaque print par logging.

• log = logging.getLogger(__name__) en haut du module
• Un message debug dans add(), avec le titre du livre
• Un warning quand une donnée incorrecte est ignorée
• Un main.py qui appelle basicConfig et prend le niveau depuis une variable d'environnement
• Aucun basicConfig dans library.py

Puis six expériences :

• Lancez au niveau INFO, puis au niveau DEBUG. Du code a-t-il dû être modifié ?
• Ajoutez filename="run.log" à basicConfig. Que reste-t-il à l'écran ?
• Appelez aussi basicConfig dans library.py, avec un niveau différent de celui de main.py. Quel niveau est utilisé maintenant — et pourquoi ?
• Provoquez volontairement une KeyError, puis dans le bloc except, écrivez une fois log.error(err) et une fois log.exception("..."). Lequel est le plus utile, et pourquoi ?
• Écrivez log.debug("%s", expensive()) où expensive() affiche quelque chose, et gardez le niveau à WARNING. expensive() s'exécute-t-elle ?
• Placez un breakpoint() et explorez avec p, n et c.

La quatrième expérience a le dernier mot sur ce chapitre. On sait comment va un programme d'après ce qu'il laisse derrière lui — et un bloc except qui ne laisse rien derrière lui n'a fait que reporter la question.

La suite

C'est la fin du cours de Python. Après 29 chapitres, vous savez écrire un programme, gérer ce qui casse, le tester et voir ce qu'il fait — et ces trois dernières compétences sont ce qui permet à un programme de vivre au-delà de son premier jour.

La suite n'est plus d'apprendre le langage, mais de faire quelque chose avec. Le cours pandas commence exactement là : les fichiers CSV du chapitre 25, mais avec des milliers de lignes, et des questions pour lesquelles une boucle ne serait plus une bonne méthode.