Djangon kirjaaminen, oikea tapa

Hyvä kirjaaminen on kriittinen tekijä ongelmien vianmäärityksessä ja -etsinnässä. Se ei ole avuksi vain paikallisessa kehityksessä, vaan myös tuotannossa se on välttämätön. Kun tarkastellaan lokitietoja ongelman löytämiseksi, on harvinaista kuulla jonkun sanovan: ”Sovelluksessamme on liikaa lokitietoja.” Mutta on yleistä kuulla päinvastaista. Joten, tämä mielessä, aloitetaan.

A Crash Course in Python Loggers

Kaiken tiedoston yläosassa pitäisi olla jotain tällaista:

import logginglogger = logging.getLogger(__name__)

__name__ arvioi moduulin pistemäisen Python-polun, esim. myproject/myapp/views.py käyttää myproject.myapp.views. Nyt voimme käyttää tuota loggeria koko tiedostossa näin:

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

Huomaa: Pythonin loggerit hoitavat muuttujien lisäämisen lokiviestiin, jos annat ne argumentteina lokifunktiossa. Jos lokia ei tarvitse tulostaa, muuttujien korvaamista ei tapahdu koskaan, mikä auttaa välttämään pienen suorituskykyhaitan lokille, jota ei koskaan käytetä.

Pepperoi koodisi runsaasti näillä lokilausekkeilla. Tässä on nyrkkisääntö, jota käytän lokitasojen suhteen:

• debug: Tieto, jota ei tarvita tavallisessa toiminnassa, mutta joka on hyödyllistä kehitystyössä.
• info: Tieto, joka on hyödyllistä tavallisessa toiminnassa.
• warning: Tieto, joka voi olla ongelmallista, mutta ei ole kiireellistä.
• error: Info, joka on tärkeää ja vaatii todennäköisesti pikaista huomiota.
• critical: En huomaa käyttäväni tätä käytännössä, mutta jos tarvitset korkeamman kuin error, tässä se on

Mihin lokitiedostot tallennetaan

Sovelluksesi ei pitäisi olla huolissaan siitä, minne sen lokitiedot menevät. Sen sijaan sen pitäisi lokata kaikki konsoliin (stdout/stderr) ja antaa palvelimen päättää, mitä sille tehdään. Tyypillisesti tämä laitetaan omaan (ja lokitettuun) tiedostoon, kaapataan Systemd-päiväkirjalla tai Dockerilla, lähetetään erilliseen palveluun, kuten ElasticSearchiin, tai jokin näiden yhdistelmä. Lokien varastointi on käyttöönottoon liittyvä asia, ei sovellukseen liittyvä asia.

Ainoa asia, josta sovelluksesi tarvitsee huolehtia, on lokien muoto. Tyypillisesti tämä on vain merkkijono, jossa on asiaankuuluvat tiedot, mutta jos palvelimesi jo lisää lokiin aikaleiman, haluat luultavasti jättää sen pois omasta formatter. Samoin, jos lokiaggregaattorisi voi hyväksyä JSON:n, python-json-logger:n kaltainen muotoilija voi olla sopivampi.

Loggaajan konfigurointi

Loggaajiin kirjoittaminen Pythonissa on helppoa. Niiden konfiguroiminen oikeaan paikkaan on haastavampaa kuin luulisi. Aloitan ohittamalla Djangon oletusarvoisen lokituksen, kuten edellisessä viestissäni kuvattiin. Se antaa meille tyhjän pöydän, jonka kanssa voimme työskennellä.

Sentryn asentaminen

Virheiden raportointipalvelut ovat kriittisiä mille tahansa ei-triviaalille sivustolle. Oletusarvoisesti nämä nappaavat tavoittamattomat poikkeukset, ilmoittavat ongelmasta (vain kerran tapausta kohden) ja tarjoavat mukavan käyttöliittymän, josta näkee sovelluksen tilan poikkeuksen tapahtumahetkellä. Suosikkipalveluni tähän on Sentry.

Voidaan viedä Sentryä askeleen pidemmälle lähettämällä palveluun myös kaikki lokiviestit, jotka ovat warning tai korkeampia. Nämä katoaisivat muuten lokitiedostojen mereen, jota käytännössä harvoin tarkastellaan. Tätä varten lisäämme ”root”-loggerin, joka toimii kaikkien minkä tahansa Python-moduulin lähettämien lokien kerääjänä. Se näyttää Djangon asetuksissa jotakuinkin tältä,

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

Loggaaminen sovelluksestasi

Vaikka saatat haluta tietää vain kolmannen osapuolen riippuvuussuhteista tulevista varoituksista ja virheistä, haluat yleensä paljon syvällisempää tietoa sovelluskoodistasi. Ihannetapauksessa kaikki koodisi elää yhden nimiavaruuden alla, joten se voidaan kaapata yhdellä lisäyksellä loggers. Oletetaan, että projektisi käyttää nimiavaruutta myproject, ja yllä olevan koodin pohjalta lisäisit tämän:

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

Mutta entä jos haluat tutkia jotain sovelluksessasi syvällisemmin debug-lokituksella? Uuden koodin sitouttaminen ja käyttöönotto tuntuu ylivoimaiselta. Tämä on hyvä käyttötapaus ympäristömuuttujille. Voimme muuttaa edellisen stanzan näyttämään tältä:

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

Nyt sovelluksemme lokitus on oletusarvoisesti info, mutta sitä voidaan helposti lisätä tilapäisesti asettamalla ympäristömuuttuja LOGLEVEL=debug. Vaihtoehtoisesti, jos lokitallennus ei ole ongelma, kannattaa harkita kirjaamista aina tasolla debug. Ne on helppo suodattaa pois yksinkertaisella grep:llä tai lokien visualisointityökalun, esimerkiksi Kibanan, avulla.

Cutting out the Noise

Kun olet asentanut lokinhallinnan ja ottanut sen käyttöön, saatat huomata joidenkin moduulien lokitietojen olevan sellaisia, joista et oikeastaan välitä ja jotka vain aiheuttavat ylimääräistä kohinaa (katson sinua newrelic). Näille moduuleille voimme lisätä toisen loggaajan, jolla ne voidaan virittää pois. Ensimmäinen vaihtoehto on lokata ne konsoliin, mutta välttää niiden etenemistä root-loggeriin, joka lähettäisi ne Sentryyn:

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

Jos ne ovat mielestäsi liian äänekkäitä jopa konsoliin, voimme jättää ne kokonaan pois:

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

Lokaali pyyntöjen lokitus

Yksi hienous Djangon oletuskonfiguraatiossa on pyyntöjen lokitus runserverillä. Ohittamalla Djangon configin menetämme sen, mutta se on helppo lisätä takaisin:

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