Django Logging, The Right Way

Dobre logowanie jest krytyczne dla debugowania i rozwiązywania problemów. Jest ono pomocne nie tylko w rozwoju lokalnym, ale także w produkcji. Podczas przeglądania logów dotyczących problemu, rzadko można usłyszeć, że ktoś mówi: „Mamy za dużo logowania w naszej aplikacji”, ale często słyszy się odwrotnie. Tak więc, mając to na uwadze, zacznijmy.

A Crash Course in Python Loggers

Na górze każdego pliku powinieneś mieć coś takiego:

import logginglogger = logging.getLogger(__name__)

__name__ będzie oceniać do kropkowanej ścieżki Pythona modułu, np. myproject/myapp/views.py użyje myproject.myapp.views. Teraz możemy używać tego loggera w całym pliku w następujący sposób:

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

Uwaga: loggery Pythona poradzą sobie z wstawianiem zmiennych do wiadomości logu, jeśli przekażesz je jako argumenty w funkcji logowania. Jeśli log nie musi być wyprowadzany, podstawianie zmiennych nigdy nie będzie miało miejsca, co pomaga uniknąć niewielkiego uderzenia wydajnościowego dla logu, który nigdy nie będzie używany.

Oprósz swój kod tymi deklaracjami logowania. Oto zasada kciuka, której używam dla poziomów dziennika:

• debug: Informacje niepotrzebne do regularnego działania, ale przydatne w rozwoju.
• info: Informacje, które są pomocne podczas regularnego działania.
• warning: Informacje, które mogą być problematyczne, ale nie są pilne.
• error: Informacje, które są ważne i prawdopodobnie wymagają natychmiastowej uwagi.
• critical: Nie spotkałem się z używaniem tego w praktyce, ale jeśli potrzebujesz wyższego niż error, oto on

Gdzie logować

Twoja aplikacja nie powinna się martwić o to, gdzie trafiają jej dzienniki. Zamiast tego, powinna logować wszystko do konsoli (stdout/stderr) i pozwolić serwerowi zdecydować, co z tym zrobić. Zazwyczaj jest to umieszczane w dedykowanym (i logrotowanym) pliku, przechwytywane przez dziennik Systemd lub Docker, wysyłane do oddzielnej usługi, takiej jak ElasticSearch, lub jakaś kombinacja tych. Przechowywanie logów jest kwestią wdrożenia, a nie aplikacji.

Jedyną rzeczą, o którą musi się troszczyć Twoja aplikacja, jest format logów. Zazwyczaj jest to po prostu ciąg znaków z odpowiednimi danymi, ale jeśli twój serwer już dodaje znacznik czasu do dziennika, prawdopodobnie chcesz go wykluczyć z własnego formatter. Podobnie, jeśli Twój agregator logów może zaakceptować JSON, formatter taki jak python-json-logger może być bardziej odpowiedni.

Konfigurowanie loggera

Pisanie do loggerów w Pythonie jest łatwe. Skonfigurowanie ich tak, aby trafiały we właściwe miejsce, jest trudniejsze, niż można by się spodziewać. Zacznę od ominięcia domyślnego logowania w Django, jak opisałem to w poprzednim poście. To zapewni nam pustą przestrzeń do pracy.

Ustawianie Sentry

Usługi raportowania błędów są krytyczne dla każdej nietrywialnej witryny. Domyślnie łapią one nieprzechwycone wyjątki, powiadamiają o problemie (tylko raz na incydent) i zapewniają miły interfejs, aby zobaczyć stan aplikacji, gdy wystąpił wyjątek. Moją ulubioną usługą do tego celu jest Sentry.

Możemy pójść o krok dalej, wysyłając wszelkie komunikaty dziennika, które są warning lub wyższe do usługi, jak również. W przeciwnym razie zostałyby one utracone w morzu plików dziennika, które w praktyce rzadko są przeglądane. Aby to zrobić, dodamy „root” logger, który służy jako catch-all dla wszystkich logów, które są wysyłane z dowolnego modułu Pythona. Wygląda to mniej więcej tak w ustawieniach Django,

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

Choć możesz chcieć wiedzieć tylko o ostrzeżeniach i błędach z twoich zewnętrznych zależności, zazwyczaj chcesz mieć znacznie głębszy wgląd w kod twojej aplikacji. Idealnie byłoby, gdyby cały twój kod żył w jednej przestrzeni nazw, więc można go przechwycić za pomocą jednego dodatku do loggers. Załóżmy, że twój projekt używa przestrzeni nazw myproject, bazując na kodzie z góry, dodałbyś to:

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

A co jeśli chcesz zbadać coś w swojej aplikacji głębiej za pomocą logowania debug? Konieczność popełniania nowego kodu i wdrażania go czuje się jak overkill. To jest właśnie świetny przypadek użycia zmiennych środowiskowych. Możemy zmodyfikować poprzednią zwrotkę tak, aby wyglądała następująco:

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

Teraz logowanie naszej aplikacji będzie domyślnie ustawione na info, ale może być łatwo tymczasowo zwiększone poprzez ustawienie zmiennej środowiskowej LOGLEVEL=debug. Alternatywnie, jeśli przechowywanie logów nie jest problemem, rozważ zawsze logowanie na poziomie debug. Są one wystarczająco łatwe do odfiltrowania za pomocą prostego grep lub za pomocą narzędzia do wizualizacji logów, np. Kibana.

Wycinanie szumu

Po skonfigurowaniu i uruchomieniu logowania możesz zauważyć, że niektóre moduły rejestrują informacje, na których tak naprawdę ci nie zależy i służą tylko do tworzenia dodatkowego szumu (patrzę na ciebie newrelic). Dla tych modułów, możemy dodać kolejny logger, aby je wyciszyć. Pierwszą opcją jest logowanie ich do konsoli, ale unikanie propagowania ich do loggera głównego, który wysyłałby je 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, }, },})

Jeśli stwierdzimy, że są zbyt hałaśliwe, nawet jak na konsolę, możemy z nich całkowicie zrezygnować:

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

Lokalne logowanie żądań

Jednym z udogodnień w domyślnej konfiguracji Django jest logowanie żądań za pomocą runservera. Przez nadpisanie konfiguracji Django, tracimy to, ale jest to wystarczająco łatwe do dodania z powrotem:

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

.