Django Logování, správný způsob

Dobré logování je klíčové pro ladění a řešení problémů. Je užitečné nejen při lokálním vývoji, ale ve výrobě je nepostradatelné. Při prohlížení logů při řešení problémů se málokdy stane, že někdo řekne: „V naší aplikaci máme příliš mnoho logování.“ Často však slyšíme opak. S tímto vědomím tedy začněme.

A Crash Course in Python Loggers

Na začátku každého souboru by mělo být něco takového:

import logginglogger = logging.getLogger(__name__)

__name__ vyhodnotí se tečkovaná cesta Pythonu k modulu, např. myproject/myapp/views.py použije myproject.myapp.views. Nyní můžeme tento logger používat v celém souboru takto:

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

Poznámka: Loggery Pythonu si poradí s vkládáním proměnných do zprávy logu, pokud je předáte jako argumenty v logovací funkci. Pokud není třeba protokol vypisovat, k záměně proměnných nikdy nedojde, což pomůže vyhnout se malému zásahu do výkonu pro protokol, který nebude nikdy použit.

Proto svůj kód hojně prošpikujte těmito příkazy pro protokolování. Zde je pravidlo, které používám pro úrovně protokolů:

• debug: Informace, které nejsou potřebné pro běžný provoz, ale jsou užitečné při vývoji.
• info: Informace, které jsou užitečné při běžném provozu.
• warning: Informace, které by mohly být problematické, ale nejsou naléhavé.
• error: Informace, které jsou důležité a pravděpodobně vyžadují okamžitou pozornost.
• critical: V praxi se nesetkávám s tím, že bych to používal, ale pokud potřebujete vyšší hodnotu než error, tady je

Kam logovat

Vaše aplikace by se neměla zabývat tím, kam se její logy ukládají. Místo toho by měla vše logovat do konzoly (stdout/stderr) a odtud nechat server rozhodnout, co s tím udělá. Obvykle se to ukládá do vyhrazeného (a logrotovaného) souboru, zachycuje se to pomocí žurnálu Systemd nebo Docker, posílá se to do samostatné služby, jako je ElasticSearch, nebo se to nějak kombinuje. Ukládání protokolů je záležitostí nasazení, nikoli aplikace.

Jediné, čím se vaše aplikace musí zabývat, je formát protokolů. Obvykle se jedná pouze o řetězec s příslušnými údaji, ale pokud váš server již do protokolu přidává časovou značku, pravděpodobně ji budete chtít ze svého formattervyjmout. Stejně tak pokud váš agregátor logů umí přijímat JSON, může být vhodnější formátovač jako python-json-logger.

Konfigurace loggeru

Zápis do loggerů v jazyce Python je snadný. Konfigurace jejich odesílání na správné místo je náročnější, než byste čekali. Začnu tím, že obejdu výchozí logování Djanga, jak jsem popsal v předchozím příspěvku. To nám poskytne čistý štít, se kterým budeme pracovat.

Nastavení Sentry

Služby hlášení chyb jsou kritické pro každý netriviální web. Ve výchozím nastavení zachycují nezachycené výjimky, upozorňují na problém (pouze jednou za incident) a poskytují příjemné rozhraní pro zobrazení stavu aplikace v okamžiku výskytu výjimky. Mou oblíbenou službou pro tyto účely je Sentry.

Službu Sentry můžeme posunout o krok dále tím, že do ní budeme posílat také všechny zprávy protokolu, které mají hodnotu warning nebo vyšší. Ty by se jinak ztratily v moři souborů protokolu, které se v praxi málokdy prohlížejí. Za tímto účelem přidáme „kořenový“ logger, který bude sloužit jako záchytný soubor pro všechny logy odesílané z libovolného modulu Pythonu. V nastavení Djanga to vypadá nějak takto,

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

Záznamy z vaší aplikace

Ačkoli můžete chtít vědět pouze o varováních a chybách ze závislostí třetích stran, obvykle chcete mít mnohem hlubší vhled do kódu své aplikace. V ideálním případě žije celý váš kód v jednom jmenném prostoru, takže jej lze zachytit jediným přidáním do loggers. Předpokládejme, že váš projekt používá jmenný prostor myproject, na základě kódu z výše uvedeného byste přidali toto:

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

Ale co když chcete něco ve své aplikaci prozkoumat hlouběji pomocí debug protokolování? Nutnost odevzdávat nový kód a nasazovat ho mi připadá přehnaná. To je skvělý případ použití proměnných prostředí. Předchozí strofu můžeme upravit takto:

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

Nyní bude logování naší aplikace ve výchozím nastavení info, ale lze ho snadno dočasně zvýšit nastavením proměnné prostředí LOGLEVEL=debug. Případně, pokud není problém s ukládáním logů, zvažte možnost logovat vždy na úrovni debug. Lze je snadno odfiltrovat pomocí jednoduchého grep nebo prostřednictvím nástroje pro vizualizaci logů, například Kibana.

Odstranění šumu

Jakmile máte nastaveno a spuštěno logování, možná zjistíte, že některé moduly logují informace, které vás ve skutečnosti nezajímají a slouží pouze k vytváření dalšího šumu (dívám se na tebe newrelic). U těchto modulů můžeme přidat další logger, který je odladí. První možností je logovat je do konzole, ale vyhnout se jejich šíření do kořenového loggeru, který by je posílal do 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, }, },})

Pokud zjistíte, že jsou příliš hlučné i pro konzoli, můžeme je úplně vypustit:

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

Lokální logování požadavků

Jednou z příjemností ve výchozí konfiguraci Djanga je logování požadavků pomocí runserveru. Přepsáním konfigurace Djanga o něj přijdeme, ale lze jej snadno přidat zpět:

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