Django-logning på den rigtige måde

God logning er afgørende for fejlfinding og fejlfinding af problemer. Det er ikke kun nyttigt i lokal udvikling, men i produktion er det uundværligt. Når man gennemgår logs for et problem, er det sjældent at høre nogen sige: “Vi har for meget logning i vores app.” Men det er almindeligt at høre det omvendte. Så med det i tankerne, lad os komme i gang.

Et lynkursus i Python-loggere

Top af hver fil bør du have noget som dette:

import logginglogger = logging.getLogger(__name__)

__name__ vil evaluere til modulets sti i Python med prikker, f.eks. vil myproject/myapp/views.py bruge myproject.myapp.views. Nu kan vi bruge denne logger i hele filen på følgende måde:

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

Bemærk: Pythons loggere håndterer at indsætte variabler i din logmeddelelse, hvis du angiver dem som argumenter i logningsfunktionen. Hvis loggen ikke skal udskrives, vil variabelerstatningen aldrig finde sted, hvilket hjælper med at undgå et lille ydelseshit for en log, der aldrig vil blive brugt.

Påfyld din kode generøst med disse logningsanvisninger. Her er den tommelfingerregel, jeg bruger for logniveauerne:

• debug: Oplysninger, der ikke er nødvendige for almindelig drift, men nyttige i forbindelse med udvikling.
• info: Oplysninger, der er nyttige under almindelig drift.
• warning: Oplysninger, der kunne være problematiske, men som ikke er presserende.
• error: Info, der er vigtig og sandsynligvis kræver øjeblikkelig opmærksomhed.
• critical: Jeg finder ikke selv ud af at bruge dette i praksis, men hvis du har brug for et højere niveau end error, er det her

Hvor skal logges

Din app bør ikke bekymre sig om, hvor dens logs går hen. I stedet bør den logge alt til konsollen (stdout/stderr) og lade serveren bestemme, hvad den skal gøre med det derfra. Typisk lægges dette i en dedikeret (og logroteret) fil, opfanges af Systemd-journalen eller Docker, sendes til en separat tjeneste som ElasticSearch eller en kombination af disse. Logopbevaring er et problem i forbindelse med implementering, ikke et problem i forbindelse med applikationen.

Det eneste, som din app behøver at bekymre sig om, er loggenes format. Typisk er dette blot en streng med de relevante data, men hvis din server allerede tilføjer et tidsstempel til loggen, vil du sandsynligvis udelukke det fra din egen formatter. Ligeledes, hvis din logaggregator kan acceptere JSON, kan en formatter som python-json-logger være mere passende.

Konfigurering af loggeren

Skrivning til loggere i Python er let. At konfigurere dem til at gå til det rigtige sted er mere udfordrende, end man skulle tro. Jeg vil starte med at omgå Djangos standardlogning som beskrevet i mit tidligere indlæg. Det vil give os en tom tavle at arbejde med.

Opsætning af Sentry

Fejlerapporteringstjenester er kritiske for ethvert ikke-trivielt websted. Som standard fanger disse uopfangede undtagelser, giver dig besked om problemet (kun én gang pr. hændelse) og giver en fin grænseflade til at se appens tilstand, da undtagelsen opstod. Min yndlingstjeneste til dette er Sentry.

Vi kan tage Sentry et skridt videre ved også at sende alle logmeddelelser, der er warning eller højere, til tjenesten. Disse ville ellers gå tabt i et hav af logfiler, som i praksis sjældent bliver gennemgået. For at gøre dette tilføjer vi en “root”-logger, der tjener som opsamlingssted for alle logs, der sendes fra et hvilket som helst Python-modul. Det ser nogenlunde sådan ud i Django-indstillingerne,

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

Logføring fra din applikation

Mens du måske kun ønsker at vide noget om advarsler og fejl fra dine tredjepartsafhængigheder, ønsker du typisk en meget dybere indsigt i din applikationskode. Ideelt set lever al din kode under et enkelt namespace, så den kan opfanges med en enkelt tilføjelse til loggers. Lad os antage, at dit projekt bruger namespace myproject, og med udgangspunkt i koden fra ovenfor ville du tilføje dette:

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

Men hvad nu, hvis du vil undersøge noget i din applikation dybere med debug-logning? At skulle committe ny kode og implementere den føles som overkill. Dette er et godt anvendelsestilfælde for miljøvariabler. Vi kan ændre den foregående stanza til at se således ud:

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 vil vores applikationslogning som standard være info, men kan nemt øges midlertidigt ved at indstille miljøvariablen LOGLEVEL=debug. Alternativt, hvis loglagring ikke er et problem, kan du overveje altid at logge på niveauet debug. De er nemme nok til at filtrere ud med en simpel grep eller via dit logvisualiseringsværktøj, f.eks. Kibana.

Skærer støjen ud

Når du har din logning opsat og kørende, kan du finde nogle moduler logoplysninger, som du ikke rigtig bekymrer dig om, og som kun tjener til at skabe ekstra støj (jeg kigger på dig newrelic). For disse moduler kan vi tilføje en anden logger for at tune dem ud. Den første mulighed er at logge dem til konsollen, men undgå at propagere dem til root-loggeren, som ville sende dem til 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, }, },})

Hvis du finder, at de er for støjende, selv til konsollen, kan vi helt droppe dem:

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

Local Request Logging

En finesse i Djangos standardkonfiguration er request logging med runserver. Ved at tilsidesætte Djangos config mister vi den, men det er nemt nok at tilføje 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, },})