Logging - logování v Pythonu

Jak to obvykle chodí při ladění

Znáte, to. Ladíte program a v kritických místech vkládáte nějaký ten print, který vypisuje obsah těžce zkoušené proměnné, nebo jen něco inteligentního jako "tady", abychom viděli, kudy to běželo.

Když je kritické místo v pohodě váháme, zda onen print vyhodit, nebo jen zakomentářovat. Co kdyby se ještě někdy hodil, že? A taky že při revizi kódu se nám podobná hláška od minula skutečně někdy hodí.

Ale proč to všechno dělat složitě a chaoticky, když máme v Pythonu vestavěný modul logging.

Příklad na úvod

import logging
logging.warning("Varovná hláška")

Po spuštění tohoto příkladu se vypíše:

WARNING:root:Varovná hláška

A je to. Jak vidíme, logování může fungovat bez jakéhokoliv dalšího nastavování. Výpisy vystupují na stderr, což je obvykle konzole z níž program spustíme.

Základní nastavení

Log, který vypisuje hlášky na konzoli ovšem není zpravidla to, co by nám stačilo. Navíc formát řádky se nám taky nemusí líbit. Takže využijme možnosti konfigurace:

import logging
logging.basicConfig(
    filename="program.log",
    format="%(asctime)s %(levelname)-8s %(message)s",
    level=logging.INFO)
logging.info("Nejaka informace")
logging.warning("A nejake varovani")

Nyní se bude logovat do souboru s názvem program.log. Jeho obsah bude:

2007-05-07 16:04:44,972 INFO     Nejaka informace
2007-05-07 16:04:51,802 WARNING  A nejake varovani

To už vypadá lépe, že?

Trocha teorie

Nechtěl jsem hned z počátku motat hlavu. To co jsme si ukázali jako návnada stačilo. Není nutné tu opisovat dokumentaci ke standardní knihovně - tu každý ví, kde má; pod polštářem.

Základním objektem modulu logging je objekt Logger. Jeho základní instance se jmenuje root a je vytvořena automaticky hned po načtení modulu. Proto jsme taky v prvním příkladu mohli hned logovat, a taky už víme, proč se ve výpisu jako druhá položka objevilo to slovo "root".

Každý Logger se projevuje prostřednictvím objektů Handler. Množné číslo je na místě - handlerů může mít jeden logger více. Pak se hlášky generované tímto loggerem objevují na více místech současně (třeba na konzoli a v souboru).

Aby hlášky nějak vypadaly, o to se stará objekt Formater. Každý handler může mít vlastní formát, takže když bychom si skutečně nechali vypisovat hlášky do souboru a ještě na konzoli, budeme v souboru chtít mít datum a čas, zatímco na konzoli by to asi byl tak nějak zbytečný údaj.

Protože ne vše musí být textový soubor, je tu ještě objekt LogRecord, který zajišťuje správně zformátování pro příslušný handler. Ten ale pracuje automaticky na pozadí a my se o něj starat nemusíme.

Modul logging má pět vestavěných úrovní - konstant s odpovídající číselnou hodnotou:

Každý logger má svoji nastavenou úroveň logování. Hlášky s nižší úrovní se do logu nedostanou. Logger může svou úroveň změnit pomocí metody setLevel. Např:

mylogger.setLevel(logging.INFO)

Nastaví úroveň logování pro logger "mylogger" na INFO.

Pro logování hlášek pak používáme metody loggeru s názvy, odpovídajícími příslušným levelům: .debug('zpráva'), .info(... Krom toho máme k dispozici obecnou metodu log(level, 'zprava'), díky níž můžeme zprávu zalogovat s úrovní jakou chceme (třeba 36).

Dokumentace odhalí i další možnosti těchto metod.

Takže znovu prakticky

Po přečtení předchozí kapitoly a se spuštěným interpreterem Pythonu ve druhé ruce bude následující příklad převzatý z originální dokumentace lahůdka. V tomto příkladu vidíme, jak nastavit dva handlery s různými formáty výstupu. Jeden (základní) jde do souboru, druhý s názvem console se vypisuje v konzoli. Taky vidíme vytvoření dvou loggerů, které pracují s nastavenou konfigurací.

import logging
logging.basicConfig(level=logging.DEBUG,
    format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
    datefmt='%Y-%m-%d %H:%M:%S',
    filename='myapp.log',
    filemode='w')
console = logging.StreamHandler()
console.setLevel(logging.INFO)
formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
console.setFormatter(formatter)
logging.getLogger('').addHandler(console)
logging.info('Jackdaws love my big sphinx of quartz.')
logger1 = logging.getLogger('myapp.area1')
logger2 = logging.getLogger('myapp.area2')
logger1.debug('Quick zephyrs blow, vexing daft Jim.')
logger1.info('How quickly daft jumping zebras vex.')
logger2.warning('Jail zesty vixen who grabbed pay from quack.')
logger2.error('The five boxing wizards jump quickly.')

Na výstupu z konzole obdržíte:

root        : INFO     Jackdaws love my big sphinx of quartz.
myapp.area1 : INFO     How quickly daft jumping zebras vex.
myapp.area2 : WARNING  Jail zesty vixen who grabbed pay from quack.
myapp.area2 : ERROR    The five boxing wizards jump quickly.

A v logovacím souboru myapp.log bude tohle:

2007-05-07 16:33:33 root         INFO     Jackdaws love my big sphinx of quartz.
2007-05-07 16:33:33 myapp.area1  DEBUG    Quick zephyrs blow, vexing daft Jim.
2007-05-07 16:33:33 myapp.area1  INFO     How quickly daft jumping zebras vex.
2007-05-07 16:33:33 myapp.area2  WARNING  Jail zesty vixen who grabbed pay from quack.
2007-05-07 16:33:33 myapp.area2  ERROR    The five boxing wizards jump quickly.

Příklad s více moduly

V praxi sestávají naše aplikace z více modulů. Tady je hlavní úlevou dovědět se, že konfigurace loggeru se do importovaných modulů přenáší automaticky a my se o to starat nemusíme.

Ukažme si to na příkladu. Základní konfiguraci loggeru jsem dal do samostatného modulu mylog.py. Ten si každá aplikace může načíst hned na začátku (možnost logovat chceme asi pořád, že?).

A pak tu máme ještě vymyšlený modul mydbmod.py, který předstírá otevírání databáze. My ho tu máme ale hlavně proto, abychom ukázali, že konfigurace loggeru se opravdu přenáší automaticky všude - do všech modulů importovaných po inicializaci loggeru.

mylog.py:

import logging

# jmeno souboru pro logovani:
logfile = "prog.log"
# nejnizsi logovana uroven:
loglevel = logging.INFO

def logstart():
    logging.basicConfig(
        filename=logfile,
        format="%(asctime)s %(levelname)-8s %(name)-10s %(message)s",
        level=loglevel)
    logging.info("Logovani zapnuto")

def logstop():
    logging.info("Logovani ukonceno")

logstart()

prog.py:

import logging, mylog
mylogprg = logging.getLogger('prog')
mylogprg.info("Hlavni modul aplikace startuje...")

import mydbmod

class App:
    def __init__(self):
        mydbmod.opendb()

if __name__ == '__main__':
    app = App()
    mylog.logstop()

mydbmod.py:

import logging

mylogdb = logging.getLogger('prog.dbmod')
mylogdb.info('Zavadeni modulu mydbmod - start')
mylogdb.setLevel(logging.DEBUG)

# Tady je obsah modulu...
def opendb():
    # neco co otevre databazi
    # ...
    mylogdb.debug('Databaze otevrena.')

mylogdb.info('Zavadeni modulu mydbmod - hotovo.')

Závěrem

Logování v Pythonu je významná pomůcka jak pro vývojáře, tak pro uživatele a administrátory. Nemusíme nic vymýšlet. Logovací nástroje máme ve standardní knihovně. Další podrobnosti hledejte v originální dokumentaci.

Zdraví Strýček Grumpa :o)