Lekce 7 - Skákačka v Pygame - Logging

V předchozí lekci, Skákačka v Pygame - Plánujeme hru, jsme vytvořili koncept naší hry a k němu adekvátní složkovou strukturu. Přidali jsme také základní herní smyčku.

V následujícím tutoriálu Pygame v Pythonu budeme pokračovat v práci na projektu Skákačky. Ukážeme si jak pomocí knihovny logging provést záznam událostí v projektu. Události si pro přehlednost zaznamenáme do předem určeného souboru.

Spouštěcí soubor Skákačky

Ještě než začneme s prací na logování, upravíme zatím prázdný soubor main.py v naší projektové složce. Soubor se bude spouštět jako první, když se někdo pokusí hrát naši hru. Naimportujeme sem tedy třídu Game ze souboru game.py a vytvoříme funkci main(). V ní vytvoříme instanci třídy Game a spustíme na ní metodu run():

from engine.game import Game

def main():
    game = Game()
    game.run()

pak se vrátíme do našeho game.py souboru a smažeme zde řádky game = Game() a game.run(). Logicky už zde nebudou potřeba, když budeme hru spouštět přes main.py. Na konec main.py přidáme:

if __name__ == '__main__':
    main()

Hru spustíme, abychom se přesvědčili, že funguje stejně jako před těmito úpravami (tedy vytvoří okno s černou plochou). A nyní už se pustíme do dalšího kroku, kterým je logování programu.

Logování programu

Knihovna logging se používá pro záznam událostí v projektu, které pro přehlednost zaznamenává do předem určeného souboru. K popisu událostí používá krátké zprávy, které zadává programátor. Zprávy mohou obsahovat i hodnoty proměnných. Základní třídou této knihovny je Logger. Na ni se odkazujeme, chceme-li vytvořit zprávu o události. Nejprve si tedy vytvoříme její instanci. V souboru main.py si naimportujeme knihovnu logging a vytvoříme si objekt GameLogger, v němž bude instance třídy Logger:

import logging

GameLogger = logging.getLogger("Game")

Aby mohl objekt v GameLogger reagovat na události, musíme mu říct kdy a jak. Vytvoříme tedy první zprávu, konkrétně o začátku hry. Před příkaz pro spuštění funkce main() přidáme GameLogger.info("Starting up!"). Tento příkaz vytvoří informativní zprávu, ale to je asi tak všechno. Když nyní spustíme program, vše proběhne tak, jako dříve. Neobjeví se žádné obrovské vykřičníky přes celou obrazovku, ani nic podobného To proto, že jsme neprovedli základní nastavení knihovny logging a nedodali jednu důležitou informaci - knihovna logging neví, na jaké zprávy má reagovat. Je totiž připravena filtrovat zprávy podle potřebné úrovně, aby jimi nezahltila chudáky programátory. Standardně používané úrovně jsou následující:

• DEBUG – detailní zpráva používaná (jak už název napovídá) při debugování,
• INFO – kratší zpráva, že vše funguje tak, jak má,
• WARNING – nastala neočekávaná situace, program však stále pracuje tak, jak má,
• ERROR – vážnější situace, program nemusí zvládat některé funkce,
• CRITICAL – nastal problém a program s velkou pravděpodobností spadl.

Knihovna logging tedy umožňuje filtrovat zprávy podle důležitosti (úrovně v předchozím seznamu jsou řazeny vzestupně podle důležitosti – CRITICAL je nejdůležitější, DEBUG nejméně). Filtr pro každou úroveň pustí dál zprávy, pro které je určen plus všechny důležitější. My nicméně pro začátek chceme, aby se nám zobrazovaly všechny zprávy. Nastavíme tedy úroveň na NOTSET. Knihovna pak bude registrovat všechny zprávy bez ohledu na úroveň. Před naši zprávu Starting up! tedy přidáme:

_log_level = logging.NOTSET
logging.basicConfig(level=_log_level)

Po spuštění programu zjistíme, že se nám v konzoli objevila hláška:

Výstup logu:
INFO:Game:Starting up!

Objekt GameLogger už nám tedy podává hlášení. My jej ale chceme uložit i do souboru a navíc i v určitém formátu. K tomu slouží další třída knihovny logging, která se jmenuje Formatter. Ta naformátuje každou zprávu ve formátu zadaném při inicializaci. Jednu její instanci vytvoříme pod příkazy, které jsme právě vytvořili:

_log_formatter = logging.Formatter('%(asctime)s %(name)s %(levelname)s: %(message)s')

Instance třídy Formatter nám tedy bude vracet zprávu ve formátu čas, název objektu GameLogger, úroveň důležitosti zprávy a samotnou zprávu. Zprávu chceme uložit do souboru. S tím nám pomůže třída FileHandler. Její instanci v proměnné _log_fh jako parametr přidáme název souboru:

_log_fh = logging.FileHandler(filename="debug.log")

Soubor nemusíme vytvářet. V případě, že instance FileHandler zjistí, že takový soubor neexistuje, sama ho vytvoří ve složce našeho projektu. Instanci přidáme ještě odkaz na instanci objektu Formatter (tu máme uloženou v proměnné _log_formatter) a úroveň (_log_level). Poté instanci v proměnné _log_fh předáme jako handler objektu GameLogger:

_log_fh.setFormatter(_log_formatter)
_log_fh.setLevel(_log_level)
GameLogger.addHandler(_log_fh)

Díky tomu všechny zprávy, které jsou zapsány do logu pro objekt GameLogger, budou také zapsány do souboru debug.log v daném formátu.

Přidáme ještě poslední třídu knihovny logging. Třída StreamHandler pracuje v podstatě stejně jako třída FileHandler. Rozdíl je v tom, že předává hlášky do systémového ekvivalentu našeho souboru s názvem sys.stderr. I jeho založení je úplně stejné, jen nepotřebuje parametr o souboru:

_log_sh = logging.StreamHandler()
_log_sh.setFormatter(_log_formatter)
_log_sh.setLevel(_log_level)
GameLogger.addHandler(_log_sh)

Logujeme program

Když už teď umíme psát kontrolní zprávy o průběhu našeho programu, pojďme si je přidat korektně tam, kde jsou potřeba - do souboru main.py. V něm jsme si zatím experimentovali a nyní je čas kód upravit na konečnou podobu. V souboru je zatím jediná velmi riziková akce, kterou chceme okomentovat: spuštění programu. Program může spadnout z mnoha důvodů a je důležité vědět proč. Spuštění funkce main() tedy zabalíme do try bloku a přidáme dvě except větve: jednu pro úmyslné ukončení od uživatele, tedy výjimku KeyboardInterrupt a druhou pro všechny ostatní výjimky:

try:
    GameLogger.info("Starting up!")
    main()
except KeyboardInterrupt:
    GameLogger.info("Shutting down because interrupted")
except Exception:

Pro ostatní výjimky také potřebujeme podat zprávu, úroveň INFO nám na to ale nebude stačit. Teď sice máme nastaveno přijímání zpráv na úplně všechny úrovně, ale až bude program hotový, budeme chtít slyšet jen o fatálních zprávách. Proto místo INFO použijeme FATAL. Tato úroveň víceméně odpovídá úrovni CRITICAL, používá se však pro odlišení situací, kdy program stoprocentně spadne. Přidáme tedy chybovou hlášku pro úroveň FATAL: GameLogger.fatal("An fatal error has occurred"). Pro dodatečný kontext přidáme ještě záznam GameLogger.fatal(traceback.format_exc()). Funkce format_exc() z modulu traceback nám při případné chybě přidá do souboru sled zanoření funkcí, na kterých program spadl. Modul traceback nesmíme zapomenout naimportovat.

Další, tentokráte už pouze informační hláška, přijde do funkce main() pod metodu `game.run(). Hláška nám v konzoli i v logu dá informaci, že hra skončila:

GameLogger.info("The game_src was ended")

Celý soubor main.py tedy bude vypadat takto:

from engine.game import Game
import logging
import traceback


GameLogger = logging.getLogger("Game")


def main():
    game = Game()
    game.run()
    GameLogger.info("The game_src was ended")

if __name__ == '__main__':
    _log_level = logging.NOTSET
    logging.basicConfig(level=_log_level)
    _log_formatter = logging.Formatter('%(asctime)s %(name)s %(levelname)s: %(message)s')
    _log_fh = logging.FileHandler(filename="debug.log")
    _log_sh = logging.StreamHandler()
    _log_fh.setFormatter(_log_formatter)
    _log_sh.setFormatter(_log_formatter)
    _log_fh.setLevel(_log_level)
    _log_sh.setLevel(_log_level)
    _log_log = logging.getLogger()
    _log_log.addHandler(_log_fh)
    _log_log.addHandler(_log_sh)
    try:
        GameLogger.info("Starting up!")
        main()
    except KeyboardInterrupt:
        GameLogger.info("Shutting down because interrupted")
    except Exception:
        GameLogger.fatal("An fatal error has occurred")
        GameLogger.fatal(traceback.format_exc())

        _log_fh.setFormatter(_log_formatter)
_log_fh.setLevel(_log_level)
GameLogger.addHandler(_log_fh)

Po jeho spuštění se nám ukáže známé černé okno. Výstup v konzoli bude vypadat takto:

Výstup konzole:
INFO:Game:Starting up!
2023-05-08 22:30:52,283 Game INFO: Starting up!
INFO:Game:The game_src was ended
2023-05-08 22:30:57,045 Game INFO: The game_src was ended.

Pro kontrolu se ještě podíváme na log v souboru debug.log:

Obsah souboru debug.log:
2023-05-08 22:30:52,283 Game INFO: Starting up!
2023-05-08 22:30:57,045 Game INFO: The game_src was ended

Vidíme, že údaje konzole i logu se shodují a vše tedy funguje jak má. Zdrojové kódy jsou opět ke stažení na konci lekce.

V další lekci, Skákačka v Pygame - Obrázky, se budeme v naší Skákačce věnovat práci s obrázky.

Měl jsi s čímkoli problém? Stáhni si vzorovou aplikaci níže a porovnej ji se svým projektem, chybu tak snadno najdeš.