Come configurare un logger con Python

LT
Luca Terribili
Autore

Il logging è un elemento fondamentale per la gestione degli errori e delle notifiche all'interno di un'applicazione Python.

Il logging è una tecnica di debugging che consiste nell'iscrivere informazioni relative alla gestione degli errori e delle notifiche all'interno di un'applicazione. In Python, il modulo logging fornisce una serie di funzionalità per configurare e utilizzare i loggers.

Questo importantissimo componente non solo aiuta a tracciare e risolvere i bug, ma è anche essenziale per monitorare lo stato di salute di un'applicazione in produzione. Esso permette di raccogliere dati su eventi specifici, segnalare condizioni anomale, e offrire una cronologia dettagliata delle operazioni eseguite.

Un sistema di logging ben configurato consente di ottenere informazioni dettagliate e di vario livello di gravità, come errori critici, avvertimenti, informazioni e messaggi di debug. Questo è particolarmente utile in contesti di sviluppo e produzione dove la tracciabilità e l'analisi degli eventi sono cruciali per mantenere un alto livello di affidabilità e performance dell'applicazione.

Nel corso di questo articolo, vedremo come iniziare con il modulo logging, esplorando i suoi componenti principali come logger, handler, formatter e filter. Inoltre, esamineremo il modulo logging.config per configurare i loggers utilizzando file di configurazione o dizionari. Questi strumenti ci permetteranno di creare un sistema di logging flessibile e potente, adattabile a diverse esigenze applicative.

I quattro componenti e a cosa servono

Il modulo logging si basa su quattro oggetti: il logger è il punto di ingresso (logging.getLogger('nome')), l'handler decide dove finiscono i messaggi, il formatter decide come vengono scritti e il filter decide quali messaggi superano un dato handler.

Il dettaglio da fissare è che il metodo setFormatter() appartiene agli handler, non ai logger. Chiamare logger.setFormatter(...) solleva un AttributeError e interrompe il programma prima che venga scritto un solo messaggio.

Configurazione semplice con basicConfig

Se l'applicazione è piccola e serve un log su console con un formato decente, basicConfig() è la risposta più breve:

import logging

logging.basicConfig(
    level=logging.INFO,
    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
    datefmt='%Y-%m-%d %H:%M:%S',
)

logger = logging.getLogger('my_logger')
logger.info('Start processing')
logger.error('Errore durante il processing')

Attenzione però a due limiti: basicConfig() non fa nulla se il logging è già stato configurato, quindi va chiamato una volta sola all'avvio e mai dentro funzioni che possono essere importate più volte; e configura il logger radice, quindi non ha effetto su un logger che ha già handler propri, come my_logger nell'esempio successivo.

Configurazione del logger

Quando serve controllo esplicito su console e file si configurano logger, handler e formatter esplicitamente. Il seguente esempio è funzionante così com'è:

import logging
import logging.handlers

# Creiamo un logger
logger = logging.getLogger('my_logger')

# Impostiamo il livello del logger: è il filtro in ingresso (DEBUG, INFO, WARNING, ERROR, CRITICAL)
logger.setLevel(logging.INFO)

# Definiamo il formato dei messaggi: va applicato ai singoli handler, non al logger
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# Creiamo un file handler per scrivere i log nel file
file_handler = logging.FileHandler('my_logger.log')
file_handler.setLevel(logging.INFO)
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)

# Possiamo anche configurare un console handler per visualizzare i log in tempo reale
console_handler = logging.StreamHandler()
console_handler.setLevel(logging.INFO)
console_handler.setFormatter(formatter)
logger.addHandler(console_handler)

In questo esempio, creiamo un logger con il nome my\_logger e impostiamo il suo livello su INFO. Definiamo poi un formatter che include ora, nome del logger, livello e messaggio, e lo applichiamo a ciascun handler con setFormatter(). Creiamo infine due handler: un file handler che scrive nel file e un console handler che visualizza i log in tempo reale.

Vale la pena fissare il modello mentale, perché è quello che rende leggibile il resto dell'articolo: il logger è un filtro in ingresso, l'handler è un filtro in uscita. Un messaggio viene scritto solo se supera entrambi. Nel codice qui sopra il logger è su INFO e i due handler sono su INFO: un logger.debug(...) non verrebbe scritto da nessuna parte. Se abbasso il livello solo sugli handler, il logger scarterebbe comunque il messaggio prima.

Utilizzo del logger

Una volta configurato il logger, possiamo utilizzarlo per loggare le informazioni all'interno della nostra applicazione. Ad esempio:

logger.info('Start processing')
# ... processo ...
logger.error('Errore durante il processing')
# ... processo ...

In questo esempio, usiamo il logger per loggare due messaggi: uno INFO che indica l'inizio del processo e uno ERROR che indica un errore durante il processo.

Un'abitudine che conviene prendere subito è usare i parametri di formattazione invece della concatenazione: logger.warning('Retry %d su %d', tentativo, totale). Il modulo rimanda la costruzione della stringa finché il messaggio non supera il filtro di livello, quindi è anche più efficiente.

Gestione dei livelli

I livelli standard, dal più severo al più permissivo, sono CRITICAL, ERROR, WARNING, INFO e DEBUG. Ogni handler ne ha uno proprio e lo si imposta con setLevel(), così si può tenere il log verboso su file e pulito a terminale:

logger.setLevel(logging.DEBUG)

console_handler.setLevel(logging.WARNING)   # a terminale solo problemi
file_handler.setLevel(logging.DEBUG)       # su file tutto

Rotazione dei file

Un FileHandler scrive sempre sullo stesso file, che cresce senza limite. Quando il log è destinato a restare su disco conviene RotatingFileHandler, che livesce in base alla dimensione o al tempo e archivia le versioni precedenti:

import logging
import logging.handlers

logger = logging.getLogger('my_logger')
logger.setLevel(logging.INFO)

formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

file_handler = logging.handlers.RotatingFileHandler(
    'my_logger.log',
    maxBytes=1_000_000,   # ruota quando il file supera 1 MB
    backupCount=3,        # conserva my_logger.log.1, .2, .3
    encoding='utf-8'
)
file_handler.setLevel(logging.INFO)
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)

Se serve una rotazione giornaliera si usa TimedRotatingFileHandler, che accetta parametri come when='midnight' e backupCount=30.

Configurazione avanzata

Il modulo logging fornisce anche i filter, che si applicano a un singolo handler e permettono di scartare i messaggi provenienti da moduli rumorosi. Il filtro si implementa con una funzione che restituisce un booleano:

import logging


class NoSqlNoise(logging.Filter):
    def filter(self, record):
        return not record.getMessage().startswith('SELECT')


file_handler.addFilter(NoSqlNoise())

Nota bene il metodo: il formato di un messaggio si imposta con il costruttore logging.Formatter(...) e poi con handler.setFormatter(formatter). Non esiste un metodo setFormatString() nell'API standard di logging.

Configurazione con file di configurazione

In alcuni casi, potremmo voler configurare il logger attraverso un file di configurazione. Il modulo logging.config fornisce questa possibilità. Ad esempio:

import logging
from logging.config import dictConfig

# Definiamo la configurazione in un dizionario
config = {
    'version': 1,
    # Senza questo, i logger già creati da altre librerie smettono di scrivere
    'disable_existing_loggers': False,
    'formatters': {
        'default': {
            'format': '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
        }
    },
    'handlers': {
        'file_handler': {
            'class': 'logging.FileHandler',
            'filename': 'my_logger.log',
            'level': 'INFO',
            'formatter': 'default',
            'encoding': 'utf-8'
        },
        'console_handler': {
            'class': 'logging.StreamHandler',
            'level': 'WARNING',
            'formatter': 'default'
        }
    },
    'loggers': {
        'my_logger': {
            'level': 'INFO',
            'handlers': ['file_handler', 'console_handler'],
            'propagate': False
        }
    }
}

# Applichiamo la configurazione
dictConfig(config)

# Creiamo il logger
logger = logging.getLogger('my_logger')
logger.info('Start processing')

In questo esempio, definiamo la configurazione in un dizionario e applichiamo poi la configurazione a tutti i logger con una sola chiamata. L'opzione 'disable_existing_loggers': False merita attenzione: senza di essa il valore predefinito è True e i logger creati prima della chiamata, per esempio quelli delle librerie di terze parti, vengono messi a tacere. Con 'propagate': False i record di my_logger non vengono inoltre inoltrati al logger radice, evitando duplicati.

Lo stesso dizionario si può salvare in un file JSON e caricare con json.load() per non toccare il codice quando la configurazione cambia:

import json
from logging.config import dictConfig

with open('logging.json', encoding='utf-8') as fh:
    dictConfig(json.load(fh))

logger = logging.getLogger('my_logger')

Se invece si preferisce il formato INI classico, esiste anche logging.config.fileConfig(), ma per un file JSON dictConfig() con json.load() è più adatto e va comunque chiamata con disable_existing_loggers=False.

Verificare che il logger scriva davvero

Un logger configurato e mai testato è un logger che potrebbe non scrivere nulla senza che nessuno se ne accorga. Il test seguente usa una directory temporanea, applica la configurazione con dictConfig() e verifica il contenuto del file:

import logging
import os
import tempfile

from logging.config import dictConfig

LOG_FORMAT = '%(asctime)s - %(name)s - %(levelname)s - %(message)s'


def build_config(path):
    return {
        'version': 1,
        'disable_existing_loggers': False,
        'formatters': {'default': {'format': LOG_FORMAT}},
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler',
                'level': 'INFO',
                'formatter': 'default',
            },
            'file': {
                'class': 'logging.FileHandler',
                'level': 'INFO',
                'formatter': 'default',
                'filename': path,
                'encoding': 'utf-8',
            },
        },
        'loggers': {
            'my_logger': {
                'level': 'INFO',
                'handlers': ['console', 'file'],
                'propagate': False,
            },
        },
    }


def test_scrive_su_console_e_su_file():
    with tempfile.TemporaryDirectory() as tmp:
        log_path = os.path.join(tmp, 'app.log')
        dictConfig(build_config(log_path))

        logger = logging.getLogger('my_logger')
        logger.debug('dettaglio non deve comparire')
        logger.info('Start processing')
        logger.error('Errore durante il processing')

        for handler in logging.getLogger('my_logger').handlers:
            handler.flush()

        with open(log_path, encoding='utf-8') as fh:
            contenuto = fh.read()

        assert 'Start processing' in contenuto
        assert 'Errore durante il processing' in contenuto
        assert 'dettaglio non deve comparire' not in contenuto

In esecuzione le due righe compaiono su console e il test si chiude senza errori:

2024-05-25 13:09:04,317 - my_logger - INFO - Start processing
2024-05-25 13:09:04,319 - my_logger - ERROR - Errore durante il processing

Le chiamate a flush() non sono un dettaglio trascurabile: FileHandler scrive in modo bufferizzato, quindi senza flush() il file potrebbe essere ancora vuoto al momento della lettura. Chiudere il logging con logging.shutdown() al termine del test evita di lasciare file descriptor aperti.

Conclusione

Il logging è un elemento fondamentale per la gestione degli errori e delle notifiche all'interno di un'applicazione Python. Il modulo logging fornisce una serie di funzionalità per configurare e utilizzare i loggers, mentre il modulo logging.config consente di configurare il logger attraverso un dizionario o un file di configurazione. In questo articolo, abbiamo esplorato come configurare un logger con Python utilizzando i moduli standard logging e logging.config. Il punto da ricordare è che il formatter si applica agli handler e non al logger, e che logging.config si scrive con il punto. Speriamo che queste informazioni siano state utili per aiutarti a configurare il tuo logger in Python.