7. diel - Skákačka v Pygame - Logging

V predchádzajúcej lekcii, Skákačka v pygame - Engine a asset , sme sa naučili, ako rozdeľovať kód na logiku hry a engine, a tiež ako hľadať podklady pre našu hru.

V nasledujúcom tutoriále Pygame v Pythone budeme pokračovať v práci na projekte Skákačky. Ukážeme si ako pomocou knižnice logging urobiť záznam udalostí v projekte. Udalosti si pre prehľadnosť zaznamenáme do vopred určeného súboru.

Spúšťací súbor Skákačky

Ešte než začneme s prácou na logovaní, upravíme zatiaľ prázdny súbor main.py v našej projektovej zložke. Súbor sa bude spúšťať ako prvý, keď sa niekto pokúsi hrať našu hru. Naimportujeme sem teda triedu Game zo súboru game.py a vytvoríme funkciu main(). V nej vytvoríme inštanciu triedy Game a spustíme na nej metódu run():

from engine.game import Game

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

potom sa vrátime do nášho game.py súboru a zmažeme tu riadky game = Game() a game.run(). Logicky už tu nebudú potrebné, keď budeme hru spúšťať cez main.py Na koniec main.py pridáme:

if __name__ == '__main__':
    main()

Hru spustíme, aby sme sa presvedčili, že funguje rovnako ako pred týmito úpravami (teda vytvorí okno s čiernou plochou). A teraz už sa pustíme do ďalšieho kroku, ktorým je logovanie programu.

Logovanie programu

Knižnica logging sa používa na záznam udalostí v projekte, ktoré pre prehľadnosť zaznamenáva do vopred určeného súboru. Na opis udalostí používa krátke správy, ktoré zadáva programátor. Správy môžu obsahovať aj hodnoty premenných. Základnou triedou tejto knižnice je Logger. Na ňu sa odkazujeme, ak chceme vytvoriť správu o udalosti. Najprv si teda vytvoríme jej inštanciu. V súbore main.py si naimportujeme knižnicu logging a vytvoríme si objekt GameLogger, v ktorom bude inštancia triedy Logger:

import logging

GameLogger = logging.getLogger("Game")

Aby mohol objekt v GameLogger reagovať na udalosti, musíme mu povedať kedy a ako. Vytvoríme teda prvú správu, konkrétne o začiatku hry. Pred príkaz na spustenie funkcie main() pridáme GameLogger.info("Starting up!"). Tento príkaz vytvorí informatívnu správu, ale to je asi tak všetko. Keď teraz spustíme program, všetko prebehne tak, ako predtým. Neobjavia sa žiadne obrovské výkričníky cez celú obrazovku, ani nič podobné:-) To preto, že sme nevykonali základné nastavenia knižnice logging a nedodali jednu dôležitú informáciu - knižnica logging nevie, na aké správy má reagovať. Je totiž pripravená filtrovať správy podľa potrebnej úrovne, aby nimi nezahltila chudákov programátorov. Štandardne používané úrovne sú nasledujúce:

• DEBUG – detailná správa používaná (ako už názov napovedá) pri debugovaní,
• INFO – kratšia správa, že všetko funguje tak, ako má,
• WARNING – nastala neočakávaná situácia, program však stále pracuje tak, ako má,
• ERROR – vážnejšia situácia, program nemusí zvládať niektoré funkcie,
• CRITICAL – nastal problém a program s veľkou pravdepodobnosťou spadol.

Knižnica logging teda umožňuje filtrovať správy podľa dôležitosti (úrovne v predchádzajúcom zozname sú zoradené vzostupne podľa dôležitosti – CRITICAL je najdôležitejšie, DEBUG najmenej). Filter pre každú úroveň pustí ďalej správy, pre ktoré je určený plus všetky dôležitejšie. My však na začiatok chceme, aby sa nám zobrazovali všetky správy. Nastavíme teda úroveň na NOTSET. Knižnica potom bude registrovať všetky správy bez ohľadu na úroveň. Pred našu správu Starting up! teda pridáme:

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

Po spustení programu zistíme, že sa nám v konzole objavila hláška:

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

Objekt GameLogger už nám teda podáva hlásenie. My ho ale chceme uložiť aj do súboru a navyše aj v určitom formáte. K tomu slúži ďalšia trieda knižnice logging, ktorá sa volá Formatter. Tá naformátuje každú správu vo formáte zadanom pri inicializácii. Jednu jej inštanciu vytvoríme pod príkazmi, ktoré sme práve vytvorili:

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

Inštancia triedy Formatter nám teda bude vracať správu vo formáte čas, názov objektu GameLogger, úroveň dôležitosti správy a samotnú správu. Správu chceme uložiť do súboru. S tým nám pomôže trieda FileHandler. Jej inštanciu v premennej _log_fh ako parameter pridáme názov súboru:

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

Súbor nemusíme vytvárať. V prípade, že inštancia FileHandler zistí, že takýto súbor neexistuje, sama ho vytvorí v priečinku nášho projektu. Inštanciu pridáme ešte odkaz na inštanciu objektu Formatter (tú máme uloženú v premennej _log_formatter) a úroveň (_log_level). Potom inštanciu v premennej _log_fh odovzdáme ako handler objektu GameLogger:

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

Vďaka tomu všetky správy, ktoré sú zapísané do logu pre objekt GameLogger, budú tiež zapísané do súboru debug.log v danom formáte.

Pridáme ešte poslednú triedu knižnice logging. Trieda StreamHandler pracuje v podstate rovnako ako trieda FileHandler. Rozdiel je v tom, že odovzdáva hlášky do systémového ekvivalentu nášho súboru s názvom sys.stderr. Aj jeho založenie je úplne rovnaké, len nepotrebuje parameter o súbore:

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

Logujeme program

Keď už teraz vieme písať kontrolné správy o priebehu nášho programu, poďme si ich pridať korektne tam, kde sú potrebné - do súboru main.py. V ňom sme si zatiaľ experimentovali a teraz je čas kód upraviť na konečnú podobu. V súbore je zatiaľ jediná veľmi riziková akcia, ktorú chceme okomentovať: spustenie programu. Program môže spadnúť z mnohých dôvodov a je dôležité vedieť prečo. Spustenie funkcie main() teda zabalíme do try bloku a pridáme dve except vetvy: jednu pre úmyselné ukončenie od užívateľa, teda výnimku KeyboardInterrupt a druhú pre všetky ostatné výnimky:

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

Pre ostatné výnimky tiež potrebujeme podať správu, ale úroveň INFO nám na to nebude stačiť. Teraz síce máme nastavené prijímanie správ na úplne všetky úrovne, ale keď bude program hotový, budeme chcieť počuť len o fatálnych správach. Preto namiesto INFO použijeme FATAL. Táto úroveň viac-menej zodpovedá úrovni CRITICAL, používa sa však na odlíšenie situácií, kedy program stopercentne spadne. Pridáme teda chybovú hlášku pre úroveň FATAL: GameLogger.fatal("An fatal error has occurred"). Pre dodatočný kontext pridáme ešte záznam GameLogger.fatal(traceback.format_exc()). Funkcia format_exc() z modulu traceback nám pri prípadnej chybe pridá do súboru sled zanorenia funkcií, na ktorých program spadol. Modul traceback nesmieme zabudnúť naimportovať.

Ďalší, tentoraz už iba informačná hláška, príde do funkcie main() pod metodu `game.run(). Hláška nám v konzole aj v logu dá informáciu, že hra skončila:

GameLogger.info("The game_src was ended")

Celý súbor main.py teda bude vyzerať 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 spustení sa nám ukáže známe čierne okno. Výstup v konzole bude vyzerať 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.

Pre kontrolu sa ešte pozrieme na log v súbore 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 konzoly aj logu sa zhodujú a všetko teda funguje ako má. Zdrojové kódy sú opäť na stiahnutie na konci lekcie.

V ďalšej lekcii, Skákačka v Pygame - Obrázky, sa budeme v našej Skákačke venovať práci s obrázkami.

 

Mal si s čímkoľvek problém? Stiahni si vzorovú aplikáciu nižšie a porovnaj ju so svojím projektom, chybu tak ľahko nájdeš.