Aaron Maxwell is auteur van Powerful Python.
Excepties komen voor. En als ontwikkelaars moeten we er gewoon mee omgaan. Zelfs als we software schrijven om ons te helpen burrito’s te vinden.
Wacht, ik loop op de zaken vooruit… daar komen we nog op terug. Zoals ik al zei: Hoe we omgaan met uitzonderingen hangt af van de taal. En voor software die op schaal werkt, is logging een van de meest krachtige, waardevolle gereedschappen die we hebben om met foutcondities om te gaan. Laten we eens kijken naar enkele manieren waarop deze samenwerken.
Het “Big Tarp”-patroon
We beginnen bij het ene uiterste:
try: main_loop()except Exception: logger.exception("Fatal error in main loop")
Dit is een brede catch-all. Het is geschikt voor sommige codepaden waarvan u weet dat het codeblok (d.w.z. main_loop()) een aantal uitzonderingen kan oproepen die u misschien niet verwacht. En in plaats van het programma te laten beëindigen, besluit u dat het beter is om de foutinformatie te loggen, en van daaruit verder te gaan.
De magie zit hier in de exception methode. (logger is het logger-object van uw toepassing – iets dat is geretourneerd van logging.getLogger(), bijvoorbeeld). Deze prachtige methode vangt de volledige stack trace in de context van het except blok, en schrijft het in zijn geheel.
Merk op dat je hier niet het exception object hoeft door te geven. Je geeft wel een message string door. Dit logt de volledige stack trace, maar zet een regel voor met je bericht. Dus de meerregelige boodschap die in je log verschijnt zou er zo uit kunnen zien:
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
De details van de stack trace doen er niet toe- dit is een speelgoed voorbeeld dat een volwassen oplossing voor een echt wereldprobleem illustreert. Merk op dat de eerste regel het bericht is dat je doorgaf aan logger.exception(), en dat de volgende regels de volledige stack trace zijn, inclusief het type uitzondering (ZeroDivisionError in dit geval). Op deze manier worden alle soorten fouten opgevangen en gelogd.
Normaal gebruikt logger.exception het log-niveau ERROR. Als alternatief kunt u de reguliere logging methodes gebruiken- logger.debug(), logger.info(), logger.warn(), etc.-en de exc_info parameter doorgeven door deze op True te zetten:
while True: try: main_loop() except Exception: logger.error("Fatal error in main loop", exc_info=True)
Door exc_info op True te zetten zal de logging de volledige stack trace bevatten…. precies zoals logger.exception() doet. Het enige verschil is dat u eenvoudig het log-niveau kunt veranderen in iets anders dan error: Vervang gewoon logger.error door logger.warn, bijvoorbeeld.
Leuk weetje: Het Big Tarp patroon heeft een bijna duivelse tegenhanger, waarover je hieronder zult lezen.
Het “Pinpoint” Patroon
Laten we nu eens kijken naar het andere uiterste. Stel dat u werkt met de OpenBurrito SDK, een bibliotheek die het cruciale probleem oplost van het vinden van een late-night burrito tent in de buurt van uw huidige locatie. Stel dat het een functie heeft genaamd find_burrito_joints() die normaal een lijst van geschikte restaurants retourneert. Maar onder bepaalde zeldzame omstandigheden, kan het een uitzondering genaamd 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()
Het patroon hier is om optimistisch een aantal code uit te voeren-de aanroep van find_burrito_joints(), in dit geval-binnen een try-blok. In het geval dat een specifiek type uitzondering wordt opgeworpen, log je een bericht, handel je de situatie af, en ga je verder.
Het belangrijkste verschil is de except-clausule. Met de Big Tarp, vang je in principe alle mogelijke uitzonderingen op en log je ze. Met Pinpoint vang je een heel specifiek uitzonderingssoort op, die op die specifieke plaats in de code semantisch relevant is.
Merk ook op dat ik logger.warn() gebruik in plaats van logger.exception(). (In dit artikel kunt u warn() vervangen door info(), of error(), enz.) Met andere woorden, ik log een bericht bij een bepaalde ernst in plaats van de hele stack trace te loggen.
Waarom gooi ik de stack trace informatie weg? Omdat het niet zo nuttig is in deze context, waar ik een specifiek uitzonderingssoort vang, die een duidelijke betekenis heeft in de logica van de code. Bijvoorbeeld, in deze snippet:
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"
Hier, de KeyError is niet zomaar een fout. Wanneer het wordt verhoogd, betekent dat een specifieke situatie zich heeft voorgedaan – namelijk, er is geen “sidekick” rol gedefinieerd in mijn cast van tekens, dus ik moet terugvallen op een standaard. Het vullen van het log met een stack trace is niet nuttig in zo’n situatie. En dat is waar je Pinpoint zult gebruiken.
Het “Transformer” Patroon
Hier vang je een exception op, logt het, en roept dan een andere exception op. Ten eerste, hier is hoe het werkt in Python 3:
try: something()except SomeError as err: logger.warn("...") raise DifferentError() from err
In Python 2, moet u de “from err” laten vallen:
try: something()except SomeError as err: logger.warn("...") raise DifferentError()
(Dat blijkt grote implicaties te hebben. Meer daarover in een moment.) U zult dit patroon willen gebruiken wanneer een uitzondering kan worden opgeworpen die niet goed past bij de logica van uw toepassing. Dit gebeurt vaak rond de grenzen van de bibliotheek.
Bijvoorbeeld, stel dat u de openburrito SDK gebruikt voor uw killer-app waarmee mensen laat in de nacht burrito-tenten kunnen vinden. De find_burrito_joints() functie kan BurritoCriteriaConflict oproepen als we te kieskeurig zijn. Dit is de API die door de SDK wordt blootgesteld, maar het is niet handig om de logica van uw toepassing op een hoger niveau te plaatsen. Een betere oplossing op dit punt van de code is een uitzondering die u hebt gedefinieerd, genaamd NoMatchingRestaurants.
In deze situatie past u het patroon als volgt toe (voor 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
Dit veroorzaakt een enkele regel uitvoer in uw log, en triggert een nieuwe uitzondering. Als deze exception nooit wordt opgevangen, ziet de foutuitvoer er als volgt uit:
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 is dit interessant. De uitvoer bevat de stack trace voor NoMatchingRestaurants. En het rapporteert de initiërende BurritoCriteriaConflict ook … duidelijk aangevend welke de oorspronkelijke was.
In Python 3, kunnen uitzonderingen nu worden geketend. De raise ... from ... syntax biedt dit. Als je zegt raise NoMatchingRestaurants(criteria) from err, dan roept dat een exceptie van typeNoMatchingRestaurants op. Deze raise exceptie heeft een attribuut met de naam __cause__, waarvan de waarde de initiërende exceptie is. Python 3 maakt hier intern gebruik van bij het rapporteren van de fout informatie.
Hoe doe je dit in Python 2? Nou, dat kun je niet. Dit is een van die goodies die je gewoon moet upgraden om te krijgen. In Python 2 wordt de “raise … from” syntaxis niet ondersteund, dus je exception output zal alleen de stack trace voor NoMatchingRestaurants bevatten. Het Transformer patroon is natuurlijk nog steeds perfect bruikbaar.
Het “Message and Raise” patroon
In dit patroon log je dat een exceptie zich voordoet op een bepaald punt, maar dan sta je toe dat het zich voortplant en wordt afgehandeld op een hoger niveau:
try: something()except SomeError: logger.warn("...") raise
Je handelt de exceptie niet echt af. U onderbreekt alleen tijdelijk de stroom om een gebeurtenis te loggen. U zult dit doen wanneer u specifiek een hoger niveau handler voor de fout, en willen terugvallen op dat, maar ook willen loggen dat de fout is opgetreden, of de betekenis ervan, op een bepaalde plaats in de code.
Dit kan het meest nuttig zijn bij het oplossen van problemen – wanneer u een uitzondering, maar proberen om beter te begrijpen de aanroepende context. U kunt deze logging-instructie gebruiken om nuttige informatie te verstrekken, en zelfs veilig in productie nemen als u de resultaten onder realistische omstandigheden moet observeren.
Het “Cryptic Message”-antipatroon
Nu richten we onze aandacht op enkele antipatronen… dingen die u niet in uw code moet doen.
try: something()except Exception: logger.error("...")
Stel dat u of iemand in uw team deze code schrijft, en dan zes maanden later ziet u een grappige melding in uw logboek. Zoiets als:
ERROR: something bad happened
Nu hoop en bid ik dat je niet de woorden “er is iets ergs gebeurd” in je eigenlijke log zult zien. Maar de tekst die je ziet kan net zo verbijsterend zijn. Wat doet u nu?
Wel, het eerste wat u moet doen is uitvinden waar in de code base dit vage bericht wordt gelogd. Als je geluk hebt, kun je snel door de code heen bladeren en precies één mogelijkheid vinden. Als je geen geluk hebt, kan je het logbericht in verschillende codepaden vinden. Wat u achterlaat met een aantal vragen:
- Welke van hen veroorzaakt de fout?
- Of zijn het meerdere van hen? Of ALLE?
- Welke entry in het log komt overeen met welke plaats?
Soms is het echter niet eens mogelijk om de code te grep’en of te doorzoeken om te vinden waar het gebeurt, omdat de log tekst wordt gegenereerd. Denk aan:
what = "something" quality = "bad" event = "happened" logger.error("%s %s %s", what, quality, event)
Hoe zou je daar zelfs maar naar kunnen zoeken? Je zou er niet eens aan kunnen denken, tenzij je eerst op de volledige zin hebt gezocht en geen treffers kreeg. En als u wel een treffer kreeg, zou het gemakkelijk een vals-positief kunnen zijn.
De ideale oplossing is om het exc_info-argument door te geven:
try: something()except Exception: logger.error("something bad happened", exc_info=True)
Wanneer u dit doet, wordt een volledige stack trace opgenomen in de toepassingslogboeken. Dit vertelt u precies welke regel in welk bestand het probleem veroorzaakt, wie het aanriep, enzovoort… alle informatie die u nodig hebt om te beginnen met debuggen.
Het Meest Duivelse Python Antipatroon
Als ik je deze ooit zie doen, kom ik naar je huis om je computers in beslag te nemen, vervolgens je github account te hacken en al je repo’s te verwijderen:
try: something()except Exception: pass
In mijn nieuwsbrief verwijs ik hiernaar als “Het Meest Duivelse Python Antipatroon.” Merk op hoe dit je niet alleen geen bruikbare uitzonderingsinformatie geeft. Het slaagt er ook in om het feit dat er iets mis is in de eerste plaats volledig te verbergen. Je zult misschien nooit weten dat je een variabele naam verkeerd hebt getypt – ja, dit maskeert NameError – totdat je om 2 uur ’s nachts wordt opgepiept omdat de productie kapot is, op een manier die je tot de ochtend nodig hebt om erachter te komen, omdat alle mogelijke foutopsporingsinformatie wordt onderdrukt.
Doe het gewoon niet. Als je het gevoel hebt dat je gewoon alle fouten moet opvangen en negeren, gooi er dan op zijn minst een groot zeil onder (d.w.z. gebruik logger.exception() in plaats van pass).
Meer Exception Logging Patterns
Er zijn veel meer patronen voor het loggen van uitzonderingsinformatie in Python, met verschillende trade-offs, voors en tegens. Welke patronen heb je nuttig gevonden, of niet? Laat het iedereen weten in de comments.
Lees meer over Python Logging Basics.