Aaron Maxwell je autorem knihy Powerful Python.
Výjimky se stávají. A jako vývojáři se s nimi prostě musíme vypořádat. Dokonce i když píšeme software, který nám má pomoci najít burrito.
Počkat, to předbíhám… ještě se k tomu vrátíme. Jak jsem říkal: Jak se vypořádáme s výjimkami, záleží na jazyce. A pro software pracující v měřítku je protokolování jedním z nejmocnějších a nejcennějších nástrojů, které máme k dispozici pro řešení chybových stavů. Podívejme se na některé způsoby, jak tyto věci fungují společně.
Vzor „velká plachta“
Začneme od jednoho extrému:
try: main_loop()except Exception: logger.exception("Fatal error in main loop")
Jedná se o široký záchytný bod. Hodí se pro nějakou cestu kódu, kde víte, že blok kódu (tj. main_loop()) může vyvolat řadu výjimek, které nemusíte předpokládat. A než abyste nechali program ukončit, rozhodnete se, že je vhodnější zaznamenat informace o chybě a pokračovat dál.
Kouzlo zde spočívá v metodě exception. (logger je objekt loggeru vaší aplikace – něco, co bylo vráceno například pomocí logging.getLogger()). Tato úžasná metoda zachytí celý stack trace v kontextu bloku except a zapíše ho celý.
Všimněte si, že zde nemusíte předávat objekt výjimky. Předáváte však řetězec zprávy. Tímto způsobem se zaznamená úplný sled zásobníku, ale před něj se přidá řádek se zprávou. Takže víceřádková zpráva, která se zobrazí v protokolu, může vypadat takto:
Fatal error in main loopTraceback (most recent call last): File "bigtarp.py", line 14, in main_loop() File "bigtarp.py", line 9, in main_loop print(foo(x)) File "bigtarp.py", line 4, in foo return 10 // n ZeroDivisionError: integer division or modulo by zero
Na podrobnostech sledování zásobníku nezáleží – toto je příklad na hraní, který ilustruje dospělé řešení problému z reálného světa. Jen si všimněte, že první řádek je zpráva, kterou jste předali do logger.exception(), a další řádky jsou kompletní stopa zásobníku včetně typu výjimky (v tomto případě ZeroDivisionError). Tímto způsobem zachytí a zaznamená jakýkoli druh chyby.
Ve výchozím nastavení používá logger.exception úroveň záznamu ERROR. Alternativně můžete použít běžné metody protokolování – logger.debug(), logger.info(), logger.warn() atd. a předat parametr exc_info a nastavit jej na hodnotu True:
while True: try: main_loop() except Exception: logger.error("Fatal error in main loop", exc_info=True)
Nastavení exc_info na hodnotu True způsobí, že protokolování bude obsahovat úplnou stopu zásobníku…. přesně tak, jak to dělá logger.exception(). Jediný rozdíl je v tom, že můžete snadno změnit úroveň protokolování na jinou než chybovou:
Zábavný fakt: Vzor Big Tarp má téměř ďábelský protějšek, o kterém se dočtete níže.
Vzor „Pinpoint“
Nyní se podíváme na druhý extrém. Představte si, že pracujete s knihovnou OpenBurrito SDK, která řeší zásadní problém nalezení nočního podniku s burritem v blízkosti vaší aktuální polohy. Předpokládejme, že má funkci s názvem find_burrito_joints(), která normálně vrací seznam vhodných restaurací. Za určitých vzácných okolností však může vyvolat výjimku nazvanou BurritoCriteriaConflict.
from openburrito import find_burrito_joints, BurritoCriteriaConflict# "criteria" is an object defining the kind of burritos you want.try: places = find_burrito_joints(criteria)except BurritoCriteriaConflict as err: logger.warn("Cannot resolve conflicting burrito criteria: {}".format(err.message)) places = list()
Vzorem je zde optimistické provedení nějakého kódu – v tomto případě volání funkce find_burrito_joints() – v bloku try. V případě, že je vyvolán určitý typ výjimky, zaznamenáte zprávu, situaci vyřešíte a pokračujete dál.
Klíčovým rozdílem je klauzule except. S velkou plachtou v podstatě zachytíte a zaznamenáte jakoukoli možnou výjimku. U Pinpointu chytáte zcela konkrétní typ výjimky, který má v daném místě kódu sémantický význam.
Všimněte si také, že používám logger.warn() místo logger.exception(). (V tomto článku všude, kde vidíte warn(), můžete nahradit info() nebo error() atd.) Jinými slovy, místo logování celého stack trace loguji zprávu s určitou závažností.
Proč zahazuji informace o stack trace? Protože v tomto kontextu, kdy zachytávám konkrétní typ výjimky, která má v logice kódu jasný význam, není tak užitečná. Například v tomto úryvku:
characters = {"hero": "Homer", "villain": "Mr. Burns"}# Insert some code here that may or may not add a key called# "sidekick" to the characters dictionary.try: sidekick = charactersexcept KeyError: sidekick = "Milhouse"
Tady KeyError není jen tak nějaká chyba. Když je vyvolána, znamená to, že nastala specifická situace – konkrétně v mém obsazení postav není definována role „pomocník“, takže se musím vrátit k výchozímu nastavení. Zaplnění protokolu stopou zásobníku nebude v takové situaci užitečné. A právě zde využijete Pinpoint.
Vzor „transformátor“
Zde zachytíte výjimku, zaznamenáte ji a poté vyvoláte jinou výjimku. Nejprve se podívejte, jak to funguje v Pythonu 3:
try: something()except SomeError as err: logger.warn("...") raise DifferentError() from err
V Pythonu 2 musíte vypustit „from err“:
try: something()except SomeError as err: logger.warn("...") raise DifferentError()
(Ukazuje se, že to má velké důsledky. Více o tom za chvíli.) Tento vzor budete chtít použít, když může dojít k vyvolání výjimky, která dobře neodpovídá logice vaší aplikace. K tomu často dochází kolem hranic knihovny.
Představte si například, že používáte openburrito SDK pro svou zabijáckou aplikaci, která umožňuje lidem najít noční podniky s burritem. Funkce find_burrito_joints() může vyvolat BurritoCriteriaConflict, pokud budeme příliš vybíraví. Jedná se o rozhraní API vystavené SDK, které však není vhodně mapováno na logiku vyšší úrovně vaší aplikace. Lépe se v tomto místě kódu hodí vámi definovaná výjimka s názvem NoMatchingRestaurants.
V této situaci použijete vzor takto (pro Python 3):
from myexceptions import NoMatchingRestaurantstry: places = find_burrito_joints(criteria)except BurritoCriteriaConflict as err: logger.warn("Cannot resolve conflicting burrito criteria: {}".format(err.message)) raise NoMatchingRestaurants(criteria) from err
To způsobí jediný řádek výstupu v protokolu a vyvolá novou výjimku. Pokud nebude tato výjimka nikdy zachycena, bude její chybový výstup vypadat takto:
Traceback (most recent call last): File "transformerB3.py", line 8, in places = find_burrito_joints(criteria) File "/Users/amax/python-exception-logging-patterns/openburrito.py", line 7, in find_burrito_joints raise BurritoCriteriaConflictopenburrito.BurritoCriteriaConflictThe above exception was the direct cause of the following exception:Traceback (most recent call last): File "transformerB3.py", line 11, in raise NoMatchingRestaurants(criteria) from errmyexceptions.NoMatchingRestaurants: {'region': 'Chiapas'}
Teď je to zajímavé. Výstup obsahuje stopu zásobníku pro NoMatchingRestaurants. A hlásí také vyvolávající BurritoCriteriaConflict… jasně určuje, která byla původní.
V Pythonu 3 lze nyní výjimky řetězit. Syntaxe raise ... from ... to umožňuje. Když řeknete raise NoMatchingRestaurants(criteria) z err, vyvolá to výjimku typeNoMatchingRestaurants. Tato vyvolaná výjimka má atribut __cause__, jehož hodnotou je vyvolávající výjimka. Python 3 toho interně využívá při hlášení informací o chybě.
Jak to uděláte v Pythonu 2? No, nemůžete. Je to jedna z těch vychytávek, které prostě musíte upgradovat, abyste je získali. V Pythonu 2 není podporována syntaxe „raise … from“, takže váš výstup výjimky bude obsahovat pouze stopu zásobníku pro NoMatchingRestaurants. Vzor Transformer je samozřejmě stále dokonale užitečný.
Vzor „Message and Raise“
V tomto vzoru zaznamenáte, že v určitém bodě došlo k výjimce, ale pak ji necháte šířit a zpracovat na vyšší úrovni:
try: something()except SomeError: logger.warn("...") raise
Výjimku ve skutečnosti nezpracováváte. Pouze dočasně přerušíte tok, abyste zaznamenali událost. Uděláte to tehdy, když máte pro chybu konkrétně zpracovatele vyšší úrovně a chcete se k němu vrátit, ale zároveň chcete zaznamenat, že k chybě došlo, nebo její význam na určitém místě kódu.
To může být nejužitečnější při řešení problémů – když dostanete výjimku, ale snažíte se lépe pochopit kontext volání. Tento protokolovací příkaz můžete proložit užitečnými informacemi, a dokonce jej můžete bezpečně nasadit do produkce, pokud potřebujete pozorovat výsledky v reálných podmínkách.
Antivzor „kryptické zprávy“
Nyní se zaměříme na některé anti-vzory… věci, které byste ve svém kódu neměli dělat.
try: something()except Exception: logger.error("...")
Předpokládejme, že vy nebo někdo z vašeho týmu napíše tento kód a po šesti měsících se v protokolu objeví legrační zpráva. Něco jako:
ERROR: something bad happened
Teď doufám a modlím se, abyste ve svém aktuálním logu neviděli slova „stalo se něco špatného“. Stejně matoucí však může být i skutečný text protokolu, který uvidíte. Co budete dělat dál?
No, v první řadě je třeba zjistit, kde v kódové základně se tato nejasná zpráva zaznamenává. Pokud budete mít štěstí, podaří se vám rychle projít kód grepem a najít přesně jednu možnost. Pokud štěstí mít nebudete, můžete najít zprávu protokolu v několika zcela odlišných cestách kódu. Což vám zanechá několik otázek:
- Která z nich chybu vyvolává
- Nebo je to několik z nich? Nebo VŠECHNY?
- Který záznam v logu odpovídá kterému místu?
Někdy však ani není možné grepem nebo vyhledáváním v kódu zjistit, kde se to děje, protože se generuje text logu. Uvažujte:
what = "something" quality = "bad" event = "happened" logger.error("%s %s %s", what, quality, event)
Jak byste to vůbec hledali? Možná vás to ani nenapadne, ledaže byste nejprve hledali celou frázi a nedostali žádné nálezy. A pokud byste náhodou nějaký nález získali, mohl by být snadno falešně pozitivní.
Ideálním řešením je předat argument exc_info:
try: something()except Exception: logger.error("something bad happened", exc_info=True)
Když to uděláte, do protokolů aplikace se zahrne úplná stopa zásobníku. To vám přesně řekne, který řádek v jakém souboru způsobuje problém, kdo jej vyvolal atd… všechny informace, které potřebujete k zahájení ladění.
Nejďábelštější antipattern Pythonu
Jestli vás někdy uvidím dělat tohle, přijdu k vám domů, zabavím vám počítače, pak se nabourám do vašeho účtu na githubu a smažu všechna vaše repozitáře:
try: something()except Exception: pass
V mém zpravodaji tomu říkám „Nejďábelštější antipattern Pythonu“. Všimněte si, že vám to nejenže neposkytne žádné užitečné informace o výjimkách. Také se mu podařilo zcela skrýt skutečnost, že je vůbec něco špatně. Možná se ani nedozvíte, že jste špatně zadali jméno proměnné – ano, tohle vlastně maskuje NameError – dokud vám ve dvě hodiny v noci nepřijde stránka, protože produkce je rozbitá, a to způsobem, na který přijdete až za svítání, protože všechny možné informace o řešení problémů jsou potlačeny.
Prostě to nedělejte. Pokud máte pocit, že prostě musíte zachytit a ignorovat všechny chyby, hoďte pod to alespoň velkou plachtu (tj. místo pass použijte logger.exception()).
Další vzory protokolování výjimek
V Pythonu existuje mnoho dalších vzorů pro protokolování informací o výjimkách, s různými kompromisy, výhodami a nevýhodami. Jaké vzory se vám osvědčily, nebo naopak ne? Dejte všem vědět v komentářích.
Přečtěte si další informace o základech protokolování v jazyce Python.