Django-loggning på rätt sätt

God loggning är avgörande för felsökning och felsökning av problem. Det är inte bara till hjälp vid lokal utveckling, utan i produktion är det oumbärligt. När man granskar loggar för ett problem är det sällsynt att höra någon säga: ”Vi har för mycket loggning i vår app.” Men det är vanligt att höra det omvända. Så med det i åtanke kan vi börja.

En snabbkurs i Python-loggare

Till toppen av varje fil bör du ha något som liknar detta:

import logginglogger = logging.getLogger(__name__)

__name__ kommer att utvärderas till modulens punktformade Python-sökväg, t.ex. myproject/myapp/views.py kommer att använda myproject.myapp.views. Nu kan vi använda den loggaren i hela filen på följande sätt:

# 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")

Notera: Pythons loggare hanterar att infoga variabler i loggningsmeddelandet om du skickar dem som argument i loggningsfunktionen. Om loggen inte behöver skickas ut kommer variabelersättningen aldrig att ske, vilket bidrar till att undvika en liten prestandaskada för en logg som aldrig kommer att användas.

Pappa din kod generöst med dessa loggningsanvisningar. Här är den tumregel jag använder för loggningsnivåer:

• debug: Information som inte behövs för ordinarie drift, men som är användbar vid utveckling.
• info: Information som är användbar vid ordinarie drift.
• warning: Information som skulle kunna vara problematisk, men som inte är brådskande.
• error: Info som är viktig och sannolikt kräver snabb uppmärksamhet.
• critical: Jag tycker inte att jag använder detta i praktiken, men om du behöver en högre nivå än error, så är den här

Where to Log

Din app bör inte bry sig om var dess loggar hamnar. Istället bör den logga allt till konsolen (stdout/stderr) och låta servern bestämma vad den ska göra med det därifrån. Vanligtvis läggs detta i en dedikerad (och loggrotad) fil, fångas upp av Systemd-journalen eller Docker, skickas till en separat tjänst som ElasticSearch, eller någon kombination av dessa. Logglagring är en fråga om distribution, inte en fråga om tillämpning.

Det enda som din tillämpning behöver bry sig om är loggarnas format. Vanligtvis är detta bara en sträng med relevanta data, men om din server redan lägger till en tidsstämpel i loggen vill du förmodligen utesluta den från din egen formatter. På samma sätt, om din loggaggregator kan acceptera JSON, kan en formaterare som python-json-logger vara mer lämplig.

Konfigurera loggare

Att skriva till loggare i Python är enkelt. Att konfigurera dem så att de går till rätt ställe är mer utmanande än vad du kan förvänta dig. Jag börjar med att kringgå Djangos standardloggning som beskrivs i mitt tidigare inlägg. Det kommer att ge oss ett tomt blad att arbeta med.

Inställning av Sentry

Felrapporteringstjänster är kritiska för alla icke-triviala webbplatser. Som standard fångar dessa upp okontrollerade undantag, meddelar dig om problemet (endast en gång per incident) och tillhandahåller ett trevligt gränssnitt för att se tillståndet i appen när undantaget inträffade. Min favorittjänst för detta är Sentry.

Vi kan ta Sentry ett steg längre genom att skicka alla loggmeddelanden som är warning eller högre till tjänsten också. Dessa skulle annars gå förlorade i ett hav av loggfiler som i praktiken sällan granskas. För att göra detta lägger vi till en ”root”-loggare som fungerar som en samlingsplats för alla loggar som skickas från någon Pythonmodul. Det ser ut ungefär så här i Django-inställningarna,

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': , }, },})

Loggning från din applikation

Men även om du kanske bara vill känna till varningar och fel från dina tredjepartsberoenden vill du vanligtvis ha en mycket djupare inblick i din applikationskod. I idealfallet lever all din kod under ett enda namnområde så att den kan fångas med ett enda tillägg till loggers. Låt oss anta att ditt projekt använder namnområdet myproject, genom att bygga vidare på koden från ovan skulle du lägga till detta:

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

Men vad händer om du vill undersöka något i ditt program djupare med debug loggning? Att behöva lägga in ny kod och distribuera den känns som en överdrift. Detta är ett utmärkt användningsområde för miljövariabler. Vi kan ändra föregående stans så att den ser ut så här:

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 kommer vår programloggning som standard att vara info, men kan enkelt ökas tillfälligt genom att ställa in miljövariabeln LOGLEVEL=debug. Alternativt, om logglagring inte är ett problem, kan du överväga att alltid logga på nivån debug. De är tillräckligt lätta att filtrera bort med en enkel grep eller via ditt loggvisualiseringsverktyg, t.ex. Kibana.

Skära ut bruset

När du väl har konfigurerat och kört din loggning kan du upptäcka att vissa moduler loggar information som du egentligen inte bryr dig om och som bara tjänar till att skapa extra brus (jag tittar på dig newrelic). För dessa moduler kan vi lägga till ytterligare en loggare för att stämma av dem. Det första alternativet är att logga dem till konsolen, men undvika att propagera dem till rotloggaren som skulle skicka dem till Sentry:

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, }, },})

Om du tycker att de är för högljudda, även för konsolen, kan vi släppa dem helt:

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

Lokal loggning av begäranden

En finess i Djangos standardkonfiguration är begärsloggning med runserver. Genom att åsidosätta Djangos konfiguration förlorar vi den, men det är lätt att lägga till den igen:

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