Django Logging, The Right Way

Goede logging is essentieel voor het debuggen en het oplossen van problemen. Niet alleen is het nuttig bij lokale ontwikkeling, maar in productie is het onmisbaar. Als je de logs van een probleem bekijkt, hoor je zelden iemand zeggen: “We hebben te veel logging in onze app.”, maar vaak hoor je het omgekeerde. Dus, met dat in gedachten, laten we beginnen.

A Crash Course in Python Loggers

Op de top van elk bestand, zou je iets als dit moeten hebben:

import logginglogger = logging.getLogger(__name__)

__name__ zal evalueren naar het gestippelde Python pad van de module, b.v. myproject/myapp/views.py zal myproject.myapp.views gebruiken. Nu kunnen we die logger in het hele bestand gebruiken, als volgt:

# A simple string logged at the "warning" levellogger.warning("Your log message is here")# A string with a variable at the "info" levellogger.info("The value of var is %s", var)# Logging the traceback for a caught exceptiontry: function_that_might_raise_index_error()except IndexError: # equivalent to logger.error(msg, exc_info=True) logger.exception("Something bad happened")

Note: Python’s loggers zullen omgaan met het invoegen van variabelen in je log bericht als je ze als argumenten doorgeeft in de log functie. Als de log niet hoeft te worden uitgevoerd, zal de vervanging van variabelen nooit voorkomen, waardoor een kleine prestatie-impact wordt vermeden voor een log dat nooit zal worden gebruikt.

Pepper je code royaal met deze logging-statements. Hier is de vuistregel die ik gebruik voor log niveaus:

• debug: Info niet nodig voor reguliere werking, maar nuttig in ontwikkeling.
• info: Info die nuttig is tijdens reguliere werking.
• warning: Info die problematisch zou kunnen zijn, maar niet dringend is.
• error: Info die belangrijk is en waarschijnlijk onmiddellijke aandacht vereist.
• critical: Ik gebruik dit niet in de praktijk, maar als je er een nodig hebt die hoger is dan error, hier is het

Waar te loggen

Uw app zou zich niet bezig moeten houden met waar zijn logs heen gaan. In plaats daarvan zou het alles moeten loggen naar de console (stdout/stderr) en de server laten beslissen wat er vanaf daar mee te doen. Typisch wordt dit in een speciaal (en loggeroteerd) bestand gezet, opgevangen door het Systemd journaal of Docker, naar een aparte dienst zoals ElasticSearch gestuurd, of een combinatie van deze. Log opslag is een implementatie zorg, geen applicatie zorg.

Het enige waar je app zich mee bezig hoeft te houden is de opmaak van de logs. Typisch is dit gewoon een string met de relevante gegevens, maar als uw server al een timestamp toevoegt aan het log, wilt u deze waarschijnlijk uitsluiten van uw eigen formatter. Evenzo, als uw log aggregator JSON kan accepteren, kan een formatter als python-json-logger meer geschikt zijn.

Configureren van de Logger

Het schrijven naar loggers in Python is eenvoudig. Ze configureren om ze naar de juiste plaats te sturen is uitdagender dan je zou verwachten. Ik zal beginnen met het omzeilen van Django’s standaard logging, zoals beschreven in mijn vorige post. Dat zal ons een lege lei geven om mee te werken.

Set up Sentry

Fout rapportage diensten zijn van cruciaal belang voor elke niet-triviale site. Standaard vangen ze niet-gevangen uitzonderingen op, stellen u op de hoogte van het probleem (slechts eenmaal per incident), en bieden een mooie interface om de toestand van de app te zien toen de uitzondering zich voordeed. Mijn favoriete service hiervoor is Sentry.

We kunnen Sentry een stap verder brengen door alle log berichten die warning of hoger zijn ook naar de service te sturen. Deze zouden anders verloren gaan in een zee van logbestanden die in de praktijk zelden worden bekeken. Om dit te doen, voegen we een “root” logger toe die dient als catch-all voor alle logs die vanuit een Python module worden verstuurd. Dat ziet er ongeveer zo uit in de Django instellingen,

import logging.configLOGGING_CONFIG = Nonelogging.config.dictConfig({ 'version': 1, 'disable_existing_loggers': False, 'formatters': { 'console': { # exact format is not important, this is the minimum information 'format': '%(asctime)s %(name)-12s %(levelname)-8s %(message)s', }, }, 'handlers': { 'console': { 'class': 'logging.StreamHandler', 'formatter': 'console', }, # Add Handler for Sentry for `warning` and above 'sentry': { 'level': 'WARNING', 'class': 'raven.contrib.django.raven_compat.handlers.SentryHandler', }, }, 'loggers': { # root logger '': { 'level': 'WARNING', 'handlers': , }, },})

Logging From Your Application

Hoewel u misschien alleen wilt weten over waarschuwingen en fouten van uw afhankelijkheden van derden, wilt u meestal veel dieper inzicht in uw applicatie code. In het ideale geval staat al uw code onder een enkele namespace, zodat deze kan worden vastgelegd met een enkele toevoeging aan de loggers. Laten we aannemen dat uw project de namespace myproject gebruikt, voortbouwend op de code van hierboven zou u dit toevoegen:

logging.config.dictConfig({ # ... 'loggers': { '': { 'level': 'WARNING', 'handlers': , }, 'myproject': { 'level': 'INFO', 'handlers': , # required to avoid double logging with root logger 'propagate': False, }, },})

Maar wat als u iets in uw applicatie dieper wilt onderzoeken met debug logging? Nieuwe code moeten committen en uitrollen voelt als overkill. Dit is een geweldig gebruik van omgevingsvariabelen. We kunnen de vorige stanza als volgt aanpassen:

import osLOGLEVEL = os.environ.get('LOGLEVEL', 'info').upper()logging.config.dictConfig({ # ... 'loggers': { '': { 'level': 'WARNING', 'handlers': , }, 'myproject': { 'level': LOGLEVEL, 'handlers': , # required to avoid double logging with root logger 'propagate': False, }, },})

Nu zal de logging van onze applicatie standaard op info staan, maar kan eenvoudig tijdelijk worden verhoogd door de omgevingsvariabele LOGLEVEL=debug in te stellen. Als alternatief, als logopslag geen probleem is, overweeg dan om altijd te loggen op het niveau debug. Ze zijn eenvoudig genoeg om eruit te filteren met een eenvoudige grep of via uw log visualisatie tool, bijvoorbeeld Kibana.

Cutting out the Noise

Als u uw logging eenmaal heeft ingesteld en draait, kunt u merken dat sommige modules informatie loggen waar u niet echt om geeft en alleen maar dienen om extra ruis te creëren (ik kijk naar u newrelic). Voor deze modules kunnen we een andere logger toevoegen om ze uit te schakelen. De eerste optie is om ze naar de console te loggen, maar te voorkomen dat ze naar de root logger gaan, die ze naar Sentry zou sturen:

logging.config.dictConfig({ # ... 'loggers': { '': { 'level': 'WARNING', 'handlers': , }, 'myproject': { 'level': LOGLEVEL, 'handlers': , # required to avoid double logging with root logger 'propagate': False, }, # Don't send this module's logs to Sentry 'noisy_module': { 'level':'ERROR', 'handlers': , 'propagate': False, }, },})

Als u vindt dat ze te veel lawaai maken, zelfs voor de console, kunnen we ze helemaal laten vallen:

logging.config.dictConfig({ # ... 'loggers': { # ... # Don't log this module at all 'noisy_module': { 'level': 'NOTSET', 'propagate': False, }, },})

Local Request Logging

Een van de schoonheden in Django’s standaard configuratie is request logging met runserver. Door Django’s configuratie op te heffen, verliezen we dit, maar het is gemakkelijk genoeg om het weer toe te voegen:

from django.utils.log import DEFAULT_LOGGINGlogging.config.dictConfig({ # ... 'formatters': { # ... 'django.server': DEFAULT_LOGGING, }, 'handlers': { # ... 'django.server': DEFAULT_LOGGING, }, 'loggers': { # ... 'django.server': DEFAULT_LOGGING, },})