Logging v Pythonu správně: od print() k čitelným logům

print() stačí, dokud program běží v terminálu před vámi. Jakmile běží na serveru, v cronu nebo jako služba, potřebujete vědět, kdy se co stalo, jak vážné to bylo a v které části kódu. Přesně to umí vestavěný modul logging.

Minimální správné nastavení

import logging

logger = logging.getLogger(__name__)

def zpracuj(soubor: str) -> None:
    logger.info("Zpracovávám %s", soubor)
    ...

if __name__ == "__main__":
    logging.basicConfig(
        level=logging.INFO,
        format="%(asctime)s %(levelname)-8s %(name)s: %(message)s",
    )
    zpracuj("data.csv")

Tři zásady, které z toho plynou:

V každém modulu logger = logging.getLogger(__name__). Jméno loggeru pak odpovídá modulu (mojeapp.db) a víte, odkud zpráva přišla.
Konfigurace jen na jednom místě – ve vstupním bodě aplikace. Knihovny logging nekonfigurují nikdy.
Nepoužívejte přímo logging.info(), ale vlastní logger. Funkce na úrovni modulu logují do root loggeru.

Úrovně

Úroveň	Kdy použít
`DEBUG`	detaily pro ladění, při běžném provozu vypnuté
`INFO`	běžné události: start, dokončení úlohy, připojení
`WARNING`	něco neočekávaného, ale program pokračuje
`ERROR`	operace selhala
`CRITICAL`	aplikace nemůže pokračovat

Výchozí úroveň root loggeru je WARNING, proto bez basicConfig vaše info zprávy neuvidíte.

Lazy formátování

logger.debug("Uživatel %s, data: %r", uid, data)      # správně
logger.debug(f"Uživatel {uid}, data: {data!r}")        # funguje, ale…

Při %s stylu se řetězec skládá jen tehdy, když se zpráva opravdu zaloguje. U f-stringu se složí vždy, i když je DEBUG vypnutý. U drahých repr velkých objektů je to znát. Navíc nástroje pro agregaci logů umí seskupovat zprávy podle šablony.

Logování výjimek

try:
    vysledek = 1 / 0
except ZeroDivisionError:
    logger.exception("Výpočet selhal")

logger.exception() zaloguje na úrovni ERROR včetně celého tracebacku. Volejte ho jen uvnitř except. Pro jinou úroveň použijte logger.warning("...", exc_info=True).

Častá chyba:

except Exception as e:
    logger.error(f"Chyba: {e}")   # ztratíte traceback i typ výjimky

Zápis do souboru s rotací

import logging
from logging.handlers import RotatingFileHandler

handler = RotatingFileHandler(
    "app.log", maxBytes=5_000_000, backupCount=5, encoding="utf-8"
)
handler.setFormatter(logging.Formatter(
    "%(asctime)s %(levelname)s %(name)s: %(message)s"
))

root = logging.getLogger()
root.setLevel(logging.INFO)
root.addHandler(handler)
root.addHandler(logging.StreamHandler())

Po dosažení 5 MB se soubor přejmenuje na app.log.1 a starší se posunou. Rotaci podle času nabízí TimedRotatingFileHandler(when="midnight", backupCount=14).

Pokud aplikace běží jako služba systemd, často je nejjednodušší logovat jen na stderr a nechat ukládání a rotaci na journaldu (journalctl -u sluzba).

Konfigurace přes dictConfig

Pro větší aplikace je přehlednější deklarativní konfigurace:

import logging.config

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "std": {"format": "%(asctime)s %(levelname)s %(name)s: %(message)s"},
    },
    "handlers": {
        "console": {"class": "logging.StreamHandler", "formatter": "std"},
        "file": {
            "class": "logging.handlers.RotatingFileHandler",
            "filename": "app.log",
            "maxBytes": 5_000_000,
            "backupCount": 3,
            "encoding": "utf-8",
            "formatter": "std",
        },
    },
    "loggers": {
        "mojeapp": {"level": "DEBUG"},
        "httpx": {"level": "WARNING"},
    },
    "root": {"level": "INFO", "handlers": ["console", "file"]},
}

logging.config.dictConfig(LOGGING)

disable_existing_loggers: False je důležité – jinak se vypnou loggery, které už vznikly při importu modulů. Sekce loggers umožňuje ztlumit upovídané knihovny (httpx, urllib3, asyncio) bez vlivu na vaše logy.

Kontext ve zprávách

Chcete u každé zprávy ID požadavku nebo uživatele? Pomůže extra a vlastní formát:

logger.info("Platba přijata", extra={"user_id": 42})

Pokud ale formát obsahuje %(user_id)s, musí extra obsahovat klíč u každého volání, jinak formátování selže. Pro systematické doplňování kontextu použijte logging.Filter, který atribut přidá ke každému záznamu, nebo LoggerAdapter.

JSON logy pro produkci

Strojově čitelné logy se lépe vyhledávají v Lokim, Elasticu a podobných systémech. Jednoduchý formatter bez závislostí:

import json, logging

class JsonFormatter(logging.Formatter):
    def format(self, record):
        data = {
            "time": self.formatTime(record),
            "level": record.levelname,
            "logger": record.name,
            "msg": record.getMessage(),
        }
        if record.exc_info:
            data["exc"] = self.formatException(record.exc_info)
        return json.dumps(data, ensure_ascii=False)

Hotová řešení nabízí např. knihovna structlog nebo python-json-logger.

Co nelogovat

Hesla, tokeny, API klíče, celé hlavičky Authorization.
Čísla karet a citlivé osobní údaje.
Celá těla požadavků s daty uživatelů – při ladění lákavé, v produkci problém pro GDPR.

Kontrolní seznam

[ ] getLogger(__name__) v každém modulu
[ ] konfigurace jen ve vstupním bodě
[ ] logger.exception() v blocích except
[ ] rotace souborů nebo logování do journalu
[ ] ztlumené upovídané knihovny
[ ] žádná tajemství v logu