Aaron Maxwell är författare till Powerful Python.
Exceptioner händer. Och som utvecklare måste vi helt enkelt hantera dem. Även när vi skriver programvara som hjälper oss att hitta burritos.
Vänta, jag går före mig själv… vi återkommer till det. Som jag sa: Hur vi hanterar undantag beror på språket. Och för programvara som fungerar i stor skala är loggning ett av de mest kraftfulla och värdefulla verktygen vi har för att hantera feltillstånd. Låt oss titta på några sätt som dessa fungerar tillsammans.
Mönstret ”Big Tarp”
Vi kommer att börja med den ena ytterligheten:
try: main_loop()except Exception: logger.exception("Fatal error in main loop")
Detta är en bred catch-all. Det är lämpligt för vissa kodvägar där du vet att kodblocket (dvs. main_loop()) kan ge upphov till ett antal undantag som du kanske inte räknar med. Och i stället för att låta programmet avslutas bestämmer du dig för att det är bättre att logga felinformationen och fortsätta därifrån.
Maginalen här är med exception-metoden. (logger är ditt programs loggningsobjekt – något som returnerades från logging.getLogger(), till exempel). Denna underbara metod fångar hela stacktrace i samband med except-blocket och skriver det i sin helhet.
Bemärk att du inte behöver lämna över undantagsobjektet här. Du lämnar dock över en meddelandesträng. Detta kommer att logga hela stacktrace, men sätta en rad med ditt meddelande före. Så det flerradiga meddelandet som visas i din logg kan se ut så här:
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
Detaljerna i stacktrace spelar ingen roll – detta är ett leksaksexempel som illustrerar en vuxen lösning på ett verkligt problem. Lägg bara märke till att den första raden är det meddelande som du skickade till logger.exception() och att de efterföljande raderna är hela stacktrace, inklusive undantagstypen (ZeroDivisionError i det här fallet). Den kommer att fånga och logga alla typer av fel på detta sätt.
Som standard använder logger.exception loggnivån ERROR. Alternativt kan du använda de vanliga loggningsmetoderna – logger.debug(), logger.info(), logger.warn(), etc. – och lämna över parametern exc_info och ställa in den på True:
while True: try: main_loop() except Exception: logger.error("Fatal error in main loop", exc_info=True)
Sätt exc_info på True för att få loggningen att inkludera hela stacken trace…. precis som logger.exception() gör. Den enda skillnaden är att du enkelt kan ändra loggningsnivån till något annat än fel: Det är bara att ersätta logger.error med logger.warn, till exempel.
Skojfråga: Big Tarp-mönstret har en nästan djävulsk motsvarighet, som du kan läsa om nedan.
The ”Pinpoint” Pattern
Nu ska vi titta på den andra extremen. Tänk dig att du arbetar med OpenBurrito SDK, ett bibliotek som löser det viktiga problemet att hitta en burrito-butik för sena kvällar i närheten av din nuvarande plats. Anta att det har en funktion som heter find_burrito_joints() som normalt returnerar en lista över lämpliga restauranger. Men under vissa sällsynta omständigheter kan den ge upphov till ett undantag kallat 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()
Mönstret här är att optimistiskt exekvera viss kod – anropet till find_burrito_joints(), i det här fallet – inom ett try block. I händelse av att ett specifikt undantag uppstår loggar du ett meddelande, hanterar situationen och går vidare.
Den viktigaste skillnaden är except-klausulen. Med Big Tarp fångar och loggar du i princip alla möjliga undantag. Med Pinpoint fångar du upp en mycket specifik undantagstyp, som har semantisk relevans på just den platsen i koden.
Märk också att jag använder logger.warn() i stället för logger.exception(). (I den här artikeln kan du ersätta warn() med info() eller error() osv.) Med andra ord loggar jag ett meddelande vid en viss svårighetsgrad i stället för att logga hela stacktrace.
Varför kastar jag bort stacktrace-informationen? Därför att den inte är lika användbar i det här sammanhanget, där jag fångar en specifik undantagstyp, som har en tydlig betydelse i kodens logik. Till exempel i detta utdrag:
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"
Här är KeyError inte vilket fel som helst. När det uppstår betyder det att en specifik situation har uppstått – nämligen att det inte finns någon ”sidekick”-roll definierad i min rollistan, så jag måste falla tillbaka till en standard. Att fylla loggen med en stacktrace kommer inte att vara användbart i den här typen av situation. Och det är där du kommer att använda Pinpoint.
The ”Transformer” Pattern
Här fångar du upp ett undantag, loggar det och tar sedan upp ett annat undantag. För det första, så här fungerar det i Python 3:
try: something()except SomeError as err: logger.warn("...") raise DifferentError() from err
I Python 2 måste du släppa ”from err”:
try: something()except SomeError as err: logger.warn("...") raise DifferentError()
(Det visar sig ha stora implikationer. Mer om det senare.) Du kommer att vilja använda det här mönstret när ett undantag kan tas upp som inte stämmer väl överens med logiken i ditt program. Detta sker ofta kring biblioteksgränser.
Föreställ dig till exempel att du använder openburrito SDK för din killer-app som låter folk hitta burrito-ställen på sena kvällar. Funktionen find_burrito_joints() kan ge upphov till BurritoCriteriaConflict om vi är för petiga. Detta är det API som SDK:n exponerar, men det är inte lämpligt att koppla det till logiken på högre nivå i din applikation. En bättre anpassning vid denna punkt i koden är ett undantag som du definierat, kallat NoMatchingRestaurants.
I denna situation tillämpar du mönstret så här (för 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
Detta orsakar en enda rad utdata i din logg och utlöser ett nytt undantag. Om det undantaget aldrig fångas upp ser felutgången ut så här:
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'}
Nu är det här intressant. Utdata inkluderar stacktrace för NoMatchingRestaurants. Och den rapporterar även det instigerande BurritoCriteriaConflict… och anger tydligt vilket som var det ursprungliga.
I Python 3 kan undantagen nu kedjas ihop. Syntaxen raise ... from ... ger detta. När du säger raise NoMatchingRestaurants(criteria) från err så väcker det ett undantag av typeNoMatchingRestaurants. Detta upphöjda undantag har ett attribut som heter __cause__, vars värde är det instigerande undantaget. Python 3 använder sig av detta internt när felinformationen rapporteras.
Hur gör man detta i Python 2? Jo, det kan man inte. Detta är en av de där godbitarna som du bara måste uppgradera för att få. I Python 2 stöds inte syntaxen ”raise … from”, så din undantagsutgång kommer endast att innehålla stacktrace för NoMatchingRestaurants. Transformer-mönstret är naturligtvis fortfarande helt användbart.
Mönstret ”Message and Raise”
I det här mönstret loggar du att ett undantag inträffar vid en viss punkt, men låter det sedan fortplanta sig och hanteras på en högre nivå:
try: something()except SomeError: logger.warn("...") raise
Du hanterar faktiskt inte undantaget. Du avbryter bara tillfälligt flödet för att logga en händelse. Du gör detta när du specifikt har en handläggare på högre nivå för felet och vill falla tillbaka på den, men också vill logga att felet inträffade, eller innebörden av det, på en viss plats i koden.
Detta kan vara mest användbart vid felsökning – när du får ett undantag, men försöker att bättre förstå den anropande kontexten. Du kan lägga in detta loggningsmeddelande för att ge användbar information och till och med säkert distribuera till produktion om du behöver observera resultaten under realistiska förhållanden.
The ”Cryptic Message” Antipattern
Nu ska vi rikta uppmärksamheten mot några anti-mönster… saker som du inte bör göra i din kod.
try: something()except Exception: logger.error("...")
Antag att du eller någon i ditt team skriver den här koden, och att du sedan, ett halvår senare, ser ett lustigt meddelande i din logg. Något i stil med:
ERROR: something bad happened
Nu hoppas och ber jag att du inte kommer att se orden ”något dåligt hände” i din faktiska logg. Den faktiska loggtexten du ser kan dock vara lika förbryllande. Vad gör du härnäst?
Det första är att ta reda på var i kodbasen detta vaga meddelande loggas. Om du har tur kan du snabbt greppa igenom koden och hitta exakt en möjlighet. Om du inte har tur kan du hitta loggmeddelandet i flera helt olika kodvägar. Vilket lämnar dig med flera frågor:
- Vilken av dem utlöser felet?
- Och är det flera av dem? Eller ALLA?
- Vilken post i loggen motsvarar vilket ställe?
I vissa fall är det dock inte ens möjligt att greppa eller söka i koden för att hitta var det händer, eftersom loggtexten genereras. Tänk på:
what = "something" quality = "bad" event = "happened" logger.error("%s %s %s", what, quality, event)
Hur skulle du ens kunna söka efter det? Du kanske inte ens tänker på det, om du inte sökte efter hela frasen först och inte fick några träffar. Och om du fick en träff kan det lätt vara ett falskt positivt resultat.
Den ideala lösningen är att skicka över exc_info-argumentet:
try: something()except Exception: logger.error("something bad happened", exc_info=True)
När du gör detta inkluderas en fullständig stacktrace i programloggarna. Detta berättar exakt vilken rad i vilken fil som orsakar problemet, vem som anropade den, et cetera… all information du behöver för att börja felsöka.
Det mest djävulska Python-antimönstret
Om jag någonsin ser dig göra det här kommer jag att komma hem till dig och konfiskera dina datorer, sedan hacka mig in på ditt github-konto och radera alla dina repos:
try: something()except Exception: pass
I mitt nyhetsbrev hänvisar jag till det här som ”Det mest djävulska Python-antimönstret”. Lägg märke till att detta inte bara misslyckas med att ge dig någon användbar undantagsinformation. Det lyckas också helt och hållet dölja det faktum att något är fel överhuvudtaget. Du kanske inte ens vet att du har skrivit fel på ett variabelnamn – ja, det här maskerar faktiskt NameError – tills du blir uppringd klockan två på natten för att produktionen är trasig, på ett sätt som det tar dig till gryningen att lista ut, eftersom all möjlig felsökningsinformation undertrycks.
Just gör det inte. Om du känner att du helt enkelt måste fånga och ignorera alla fel, kasta åtminstone en stor presenning under det (dvs. använd logger.exception() istället för pass).
Mer undantagsloggningsmönster
Det finns många fler mönster för loggning av undantagsinformation i Python, med olika avvägningar, för- och nackdelar. Vilka mönster har du funnit användbara, eller inte? Låt alla veta i kommentarerna.
Lär dig mer om grunderna för loggning i Python.