Aaron Maxwell er forfatter til Powerful Python.
Udtagelser sker. Og som udviklere er vi simpelthen nødt til at håndtere dem. Selv når vi skriver software, der skal hjælpe os med at finde burritos.
Wait, I’m getting ahead of myself… we’ll come back to that. Som jeg var ved at sige: Hvordan vi håndterer undtagelser afhænger af sproget. Og for software, der fungerer i stor skala, er logning et af de mest kraftfulde og værdifulde værktøjer, vi har til at håndtere fejltilstande. Lad os se på nogle måder, hvorpå disse arbejder sammen.
Det “Big Tarp”-mønster
Vi starter ved den ene yderlighed:
try: main_loop()except Exception: logger.exception("Fatal error in main loop")
Dette er en bred fangstmulighed. Det er velegnet til nogle kodeveje, hvor du ved, at blokken af kode (dvs. main_loop()) kan give anledning til en række undtagelser, som du måske ikke forudser. Og i stedet for at lade programmet afslutte, beslutter du, at det er at foretrække at logge fejloplysningerne og fortsætte derfra.
Det magiske her er med exception-metoden. (logger er dit programs loggerobjekt – noget, der f.eks. blev returneret fra logging.getLogger()). Denne vidunderlige metode opfanger den fulde stack trace i forbindelse med except-blokken og skriver den i sin helhed.
Bemærk, at du ikke behøver at videregive undtagelsesobjektet her. Du afleverer en beskedstreng. Dette vil logge den fulde stacktrace, men tilføje en linje med din besked i begyndelsen. Så den flerlinjede meddelelse, der vises i din log, kan se således ud:
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
Det er ligegyldigt med detaljerne i staksporet – dette er et legetøjseksempel, der illustrerer en voksen løsning på et problem fra den virkelige verden. Bemærk blot, at den første linje er den meddelelse, du har givet til logger.exception(), og at de efterfølgende linjer er den fulde stacktrace, herunder undtagelsestypen (ZeroDivisionError i dette tilfælde). Den vil fange og logge enhver form for fejl på denne måde.
Som standard bruger logger.exception logniveauet ERROR. Alternativt kan du bruge de almindelige logningsmetoder – logger.debug(), logger.info(), logger.warn() osv. – og overdrage parameteren exc_info ved at indstille den til True:
while True: try: main_loop() except Exception: logger.error("Fatal error in main loop", exc_info=True)
Indstiller du exc_info til True, vil logningen inkludere den fulde stack trace…. præcis som logger.exception() gør. Den eneste forskel er, at du nemt kan ændre logniveauet til noget andet end fejl: Du skal bare erstatte logger.error med logger.warn, for eksempel.
Sjovt faktum: Big Tarp-mønsteret har et næsten djævelsk modstykke, som du kan læse om nedenfor.
The “Pinpoint” Pattern
Nu skal vi se på den anden yderlighed. Forestil dig, at du arbejder med OpenBurrito SDK, et bibliotek, der løser det afgørende problem med at finde en sen burrito-butik i nærheden af din nuværende placering. Antag, at det har en funktion kaldet find_burrito_joints(), der normalt returnerer en liste over egnede restauranter. Men under visse sjældne omstændigheder kan den udløse en undtagelse kaldet 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 her er optimistisk at udføre noget kode – i dette tilfælde kaldet find_burrito_joints() – inden for en try block. I tilfælde af, at en bestemt undtagelsestype udløses, logger du en meddelelse, håndterer situationen og går videre.
Den vigtigste forskel er except-klausulen. Med Big Tarp fanger og logger du i princippet enhver mulig undtagelse. Med Pinpoint fanger du en meget specifik undtagelsestype, som har semantisk relevans på netop det sted i koden.
Bemærk også, at jeg bruger logger.warn() i stedet for logger.exception(). (I denne artikel kan du, hvor du ser warn(), erstatte det med info() eller error() osv.) Med andre ord logger jeg en meddelelse ved en bestemt sværhedsgrad i stedet for at logge hele stacktrace.
Hvorfor smider jeg stacktrace-oplysningerne væk? Fordi det ikke er så nyttigt i denne sammenhæng, hvor jeg fanger en bestemt undtagelsestype, som har en klar betydning i logikken i koden. For eksempel i dette uddrag:
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"
Her er KeyError ikke bare en hvilken som helst fejl. Når den udløses, betyder det, at der er opstået en bestemt situation – nemlig at der ikke er defineret nogen “sidekick”-rolle i min rollebesætning, så jeg må falde tilbage på en standard. At fylde loggen op med en stack trace vil ikke være nyttigt i denne slags situationer. Og det er her, du skal bruge Pinpoint.
Det “Transformer”-mønster
Her fanger du en undtagelse, logger den og rejser derefter en anden undtagelse. Først kan du se, hvordan det fungerer i Python 3:
try: something()except SomeError as err: logger.warn("...") raise DifferentError() from err
I Python 2 skal du droppe “from err”:
try: something()except SomeError as err: logger.warn("...") raise DifferentError()
(Det viser sig at have store konsekvenser. Mere om det om lidt.) Du vil bruge dette mønster, når der kan blive rejst en undtagelse, som ikke passer godt til logikken i din applikation. Dette sker ofte omkring biblioteksgrænser.
Forestil dig for eksempel, at du bruger openburrito SDK’et til din killer-app, der lader folk finde burrito-butikker til sent om aftenen. find_burrito_joints()-funktionen kan give anledning til BurritoCriteriaConflict, hvis vi er for kræsne. Dette er den API, der udsættes af SDK’et, men det er ikke praktisk muligt at mappe til logikken på højere niveau i din applikation. En bedre tilpasning på dette punkt i koden er en undtagelse, du har defineret, kaldet NoMatchingRestaurants.
I denne situation vil du anvende mønsteret således (for 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
Dette medfører en enkelt linje output i din log og udløser en ny undtagelse. Hvis den aldrig bliver fanget, ser denne undtagelses fejloutput således ud:
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 er dette interessant. Udgangen indeholder staksporet for NoMatchingRestaurants. Og det rapporterer også den igangsættende BurritoCriteriaConflict … med tydelig angivelse af, hvilken der var den oprindelige.
I Python 3 kan undtagelser nu kædes sammen. Syntaksen raise ... from ... giver mulighed for dette. Når du siger raise NoMatchingRestaurants(criteria) fra err, så rejser det en undtagelse på typeNoMatchingRestaurants. Denne hævede undtagelse har en attribut ved navn __cause__, hvis værdi er den igangsættende undtagelse. Python 3 gør brug af dette internt, når fejloplysningerne rapporteres.
Hvordan gør man dette i Python 2? Tja, det kan man ikke. Dette er en af de godbidder, som du bare skal opgradere for at få. I Python 2 understøttes syntaksen “raise … from” ikke, så dit undtagelsesoutput vil kun omfatte stacktrace for NoMatchingRestaurants. Transformer-mønsteret er selvfølgelig stadig helt brugbart.
Det “Message and Raise”-mønster
I dette mønster logger du, at en undtagelse opstår på et bestemt punkt, men lader den derefter forplante sig og blive behandlet på et højere niveau:
try: something()except SomeError: logger.warn("...") raise
Du behandler faktisk ikke undtagelsen. Du afbryder blot midlertidigt flowet for at logge en hændelse. Du vil gøre dette, når du specifikt har en håndtering på højere niveau for fejlen og ønsker at falde tilbage på denne, men også ønsker at logge, at fejlen opstod, eller betydningen af den, et bestemt sted i koden.
Dette kan være mest nyttigt ved fejlfinding – når du får en undtagelse, men forsøger at forstå den kaldende kontekst bedre. Du kan indskyde denne logningsangivelse for at give nyttige oplysninger og endda sikkert implementere til produktion, hvis du har brug for at observere resultaterne under realistiske forhold.
Antimønsteret “Cryptic Message”
Nu vil vi vende opmærksomheden mod nogle antimønstre… ting, du ikke bør gøre i din kode.
try: something()except Exception: logger.error("...")
Sæt, at du eller nogen på dit team skriver denne kode, og så seks måneder senere ser du en sjov besked i din log. Noget i retning af:
ERROR: something bad happened
Nu håber og beder jeg til, at du ikke vil se ordene “noget slemt er sket” i din faktiske log. Men den faktiske logtekst, du ser, kan være lige så forvirrende. Hvad gør du nu?
Den første ting er at finde ud af, hvor i kodebasen denne vage meddelelse bliver logget. Hvis du er heldig, vil du hurtigt kunne grepe koden igennem og finde præcis én mulighed. Hvis du ikke er heldig, kan du finde logmeddelelsen i flere helt forskellige kodeveje. Hvilket vil efterlade dig med flere spørgsmål:
- Hvilken af dem udløser fejlen?
- Og er det flere af dem? Eller ALLE?
- Hvilken post i loggen svarer til hvilket sted?
Sommetider er det dog ikke engang muligt at grepe eller søge i koden for at finde ud af, hvor det sker, fordi logteksten bliver genereret. Overvej:
what = "something" quality = "bad" event = "happened" logger.error("%s %s %s", what, quality, event)
Hvordan ville du overhovedet søge efter det? Du tænker måske ikke engang på det, medmindre du først søgte efter den fulde sætning og ikke fik nogen hits. Og hvis du fik et hit, kunne det nemt være en falsk positiv.
Den ideelle løsning er at videregive exc_info-argumentet:
try: something()except Exception: logger.error("something bad happened", exc_info=True)
Når du gør dette, medtages en fuld stack trace i programlogfilerne. Dette fortæller dig præcis, hvilken linje i hvilken fil der forårsager problemet, hvem der har påkaldt den osv… alle de oplysninger, du har brug for for at begynde at fejlfinde.
Det mest djævelske Python-antimønster
Hvis jeg nogensinde ser dig gøre dette, kommer jeg hjem til dig og konfiskerer dine computere, hvorefter jeg hacker mig ind på din github-konto og sletter alle dine repos:
try: something()except Exception: pass
I mit nyhedsbrev omtaler jeg dette som “Det mest djævelske Python-antimønster”. Bemærk, hvordan dette ikke kun undlader at give dig nogen brugbare undtagelsesoplysninger. Det formår også helt at skjule det faktum, at der overhovedet er noget galt. Du vil måske ikke engang vide, at du har skrevet et variablenavn forkert – ja, dette maskerer faktisk NameError – indtil du bliver kaldt kl. 2 om natten, fordi produktionen er gået i stykker på en måde, som det tager dig til daggry at finde ud af, fordi alle mulige oplysninger om fejlfinding bliver undertrykt.
Du skal bare lade være med at gøre det. Hvis du føler, at du simpelthen skal fange og ignorere alle fejl, så smid i det mindste en stor presenning under det (dvs. brug logger.exception() i stedet for pass).
Mere Exception Logging Patterns
Der er mange flere mønstre til logning af undtagelsesoplysninger i Python, med forskellige kompromisser, fordele og ulemper. Hvilke mønstre har du fundet nyttige, eller ikke? Lad alle vide det i kommentarerne.
Lær mere om Python Logging Basics.