Logowanie w Pythonie: dogłębny samouczek

Opublikowany: 2022-03-11

Ponieważ aplikacje stają się coraz bardziej złożone, posiadanie dobrych dzienników może być bardzo przydatne, nie tylko podczas debugowania, ale także w celu zapewnienia wglądu w problemy z aplikacjami/wydajność.

Standardowa biblioteka Pythona zawiera moduł rejestrowania , który zapewnia większość podstawowych funkcji rejestrowania. Po prawidłowym skonfigurowaniu komunikat dziennika może przynieść wiele przydatnych informacji o tym, kiedy i gdzie dziennik jest uruchamiany, a także o kontekście dziennika, takim jak uruchomiony proces/wątek.

Pomimo zalet, moduł rejestrowania jest często pomijany, ponieważ prawidłowe skonfigurowanie zajmuje trochę czasu i, moim zdaniem, jest kompletnym oficjalnym dokumentem rejestrowania pod adresem https://docs.python.org/3/library/logging.html tak naprawdę nie podaje najlepszych praktyk w zakresie rejestrowania ani nie podkreśla niektórych niespodzianek związanych z rejestrowaniem.

Ten samouczek dotyczący rejestrowania w Pythonie nie ma być kompletnym dokumentem na temat modułu rejestrowania, ale raczej przewodnikiem „wprowadzenie”, który wprowadza pewne koncepcje rejestrowania, a także kilka „gotchas”, na które należy uważać. Post zakończy się najlepszymi praktykami i będzie zawierał wskazówki do bardziej zaawansowanych tematów dotyczących rejestrowania.

Pamiętaj, że wszystkie fragmenty kodu w poście zakładają, że zaimportowałeś już moduł logowania:

 import logging

Koncepcje dotyczące rejestrowania w Pythonie

Ta sekcja zawiera przegląd niektórych pojęć, które często występują w module rejestrowania.

Poziomy rejestrowania w Pythonie

Poziom dziennika odpowiada „ważności” nadanemu dziennikowi: dziennik „błędów” powinien być pilniejszy niż dziennik „ostrzeżenie”, natomiast dziennik „debugowania” powinien być przydatny tylko podczas debugowania aplikacji.

W Pythonie istnieje sześć poziomów logów; każdy poziom jest powiązany z liczbą całkowitą, która wskazuje wagę dziennika: NOTSET=0, DEBUG=10, INFO=20, WARN=30, ERROR=40 i CRITICAL=50.

Poziomy logów w Python Logging

Wszystkie poziomy są raczej proste (DEBUG <INFO<OSTRZEŻENIE) z wyjątkiem NOTSET, którego szczegółowość zostanie omówiona w dalszej części.

Formatowanie dzienników w Pythonie

Program formatujący dzienniki zasadniczo wzbogaca komunikat dziennika, dodając do niego informacje kontekstowe. Warto wiedzieć, kiedy dziennik jest wysyłany, gdzie (plik Pythona, numer wiersza, metoda itp.) oraz dodatkowy kontekst, taki jak wątek i proces (może być niezwykle przydatny podczas debugowania aplikacji wielowątkowej).

Na przykład, gdy dziennik „hello world” jest wysyłany przez program do formatowania dziennika:

 "%(asctime)s — %(name)s — %(levelname)s — %(funcName)s:%(lineno)d — %(message)s"

stanie się

 2018-02-07 19:47:41,864 - abc - WARNING - <module>:1 - hello world

Formatowanie komunikatów dziennika Pythona

Program obsługi logowania Pythona

Obsługa dziennika to komponent, który efektywnie zapisuje/wyświetla dziennik: wyświetlaj go w konsoli (poprzez StreamHandler), w pliku (poprzez FileHandler), a nawet wysyłając wiadomość e-mail przez SMTPHandler itp.

Każdy program do obsługi dziennika ma 2 ważne pola:

  • Program formatujący, który dodaje do dziennika informacje o kontekście.
  • Poziom rejestrowania, który odfiltrowuje logi o niższych poziomach. Tak więc program obsługi dziennika z poziomem INFO nie będzie obsługiwał dzienników DEBUG.

Program obsługi logowania Pythona

Biblioteka standardowa zapewnia garść programów obsługi, które powinny wystarczyć w typowych przypadkach użycia: https://docs.python.org/3/library/logging.handlers.html#module-logging.handlers. Najpopularniejsze z nich to StreamHandler i FileHandler:

 console_handler = logging.StreamHandler() file_handler = logging.FileHandler("filename")

Rejestrator Pythona

Logger to prawdopodobnie ten, który będzie najczęściej używany bezpośrednio w kodzie i który jest również najbardziej skomplikowany. Nowy rejestrator można uzyskać poprzez:

 toto_logger = logging.getLogger("toto")

Logger ma trzy główne pola:

  • Propaguj: Decyduje, czy dziennik powinien być propagowany do rodzica rejestratora. Domyślnie jego wartość to True.
  • Poziom: Podobnie jak poziom obsługi dziennika, poziom rejestratora służy do filtrowania „mniej ważnych” dzienników. Z wyjątkiem tego, że w przeciwieństwie do programu obsługi dziennika, poziom jest sprawdzany tylko w rejestratorze „podrzędnym”; po rozesłaniu dziennika do jego rodziców poziom nie będzie sprawdzany. To raczej nieintuicyjne zachowanie.
  • Programy obsługi: Lista programów obsługi, do których zostanie wysłany dziennik, gdy dotrze do rejestratora. Pozwala to na elastyczną obsługę dzienników — na przykład można mieć program obsługi dziennika plików, który rejestruje wszystkie dzienniki DEBUG, oraz program obsługi dziennika poczty e-mail, który będzie używany tylko w przypadku dzienników KRYTYCZNYCH. Pod tym względem relacja rejestrator-program obsługi jest podobna do relacji wydawca-konsument: dziennik zostanie rozesłany do wszystkich programów obsługi po przejściu sprawdzenia poziomu rejestratora.

Proces logowania w Pythonie

Rejestrator jest unikalny z nazwy, co oznacza, że ​​jeśli został utworzony rejestrator o nazwie „toto”, kolejne wywołania funkcji logging.getLogger("toto") zwrócą ten sam obiekt:

 assert id(logging.getLogger("toto")) == id(logging.getLogger("toto"))

Jak można się domyślić, rejestratory mają hierarchię. Na szczycie hierarchii znajduje się główny rejestrator, do którego można uzyskać dostęp za pośrednictwem logging.root. Ten rejestrator jest wywoływany, gdy używane są metody takie jak logging.debug() . Domyślnie głównym poziomem dziennika jest WARN, więc każdy dziennik o niższym poziomie (na przykład via logging.info("info") ) zostanie zignorowany. Inną szczególną cechą rejestratora głównego jest to, że jego domyślny program obsługi zostanie utworzony przy pierwszym logowaniu dziennika o poziomie wyższym niż WARN. Używanie głównego rejestratora bezpośrednio lub pośrednio za pomocą metod takich jak logging.debug() nie jest generalnie zalecane.

Domyślnie, gdy tworzony jest nowy rejestrator, jego rodzic zostanie ustawiony na rejestrator główny:

 lab = logging.getLogger("ab") assert lab.parent == logging.root # lab's parent is indeed the root logger

Jednak rejestrator używa „notacji kropkowej”, co oznacza, że ​​rejestrator o nazwie „ab” będzie dzieckiem rejestratora „a”. Jest to jednak prawdą tylko wtedy, gdy logger „a” został utworzony, w przeciwnym razie rodzic „ab” jest nadal rootem.

 la = logging.getLogger("a") assert lab.parent == la # lab's parent is now la instead of root

Gdy rejestrator decyduje, czy dziennik powinien przejść zgodnie z kontrolą poziomu (np. jeśli poziom dziennika jest niższy niż poziom rejestratora, dziennik zostanie zignorowany), używa swojego „poziomu efektywnego” zamiast rzeczywistego poziomu. Efektywny poziom jest taki sam jak poziom rejestratora, jeśli poziom nie jest USTAWIONY, tj. wszystkie wartości od DEBUG do CRITICAL; jednakże, jeśli poziom rejestratora to NIE USTAWIONY, to efektywnym poziomem będzie pierwszy poziom przodka, który nie ma poziomu NIEUSTAWIONE.

Domyślnie nowy program rejestrujący ma poziom NOTSET, a ponieważ główny program rejestrujący ma poziom WARN, efektywnym poziomem programu rejestrującego będzie WARN. Więc nawet jeśli nowy rejestrator ma dołączone jakieś procedury obsługi, te procedury obsługi nie zostaną wywołane, chyba że poziom dziennika przekroczy WARN:

 toto_logger = logging.getLogger("toto") assert toto_logger.level == logging.NOTSET # new logger has NOTSET level assert toto_logger.getEffectiveLevel() == logging.WARN # and its effective level is the root logger level, ie WARN # attach a console handler to toto_logger console_handler = logging.StreamHandler() toto_logger.addHandler(console_handler) toto_logger.debug("debug") # nothing is displayed as the log level DEBUG is smaller than toto effective level toto_logger.setLevel(logging.DEBUG) toto_logger.debug("debug message") # now you should see "debug message" on screen

Domyślnie do decydowania o przejściu dziennika będzie używany poziom rejestratora: Jeśli poziom dziennika jest niższy niż poziom rejestratora, dziennik zostanie zignorowany.

Najlepsze praktyki dotyczące rejestrowania w Pythonie

Moduł logowania jest rzeczywiście bardzo przydatny, ale zawiera pewne dziwactwa, które mogą powodować długie godziny bólu głowy nawet najlepszym programistom Pythona. Oto moim zdaniem najlepsze praktyki korzystania z tego modułu:

  • Skonfiguruj główny rejestrator, ale nigdy nie używaj go w swoim kodzie — np. nigdy nie wywołuj funkcji takiej jak logging.info() , która faktycznie wywołuje główny rejestrator w tle. Jeśli chcesz przechwycić komunikaty o błędach z używanych bibliotek, upewnij się, że główny rejestrator został skonfigurowany do zapisywania do pliku, na przykład w celu ułatwienia debugowania. Domyślnie główny rejestrator wysyła dane wyjściowe tylko do stderr , więc dziennik można łatwo zgubić.
  • Aby użyć rejestrowania, upewnij się, że utworzyłeś nowy rejestrator przy użyciu logging.getLogger(logger name) . Zwykle używam __name__ jako nazwy rejestratora, ale można użyć wszystkiego, o ile jest spójne. Aby dodać więcej programów obsługi, zwykle mam metodę, która zwraca logger (istotę można znaleźć na https://gist.github.com/nguyenkims/e92df0f8bd49973f0c94bddf36ed7fd0).
 import logging import sys from logging.handlers import TimedRotatingFileHandler FORMATTER = logging.Formatter("%(asctime)s — %(name)s — %(levelname)s — %(message)s") LOG_FILE = "my_app.log" def get_console_handler(): console_handler = logging.StreamHandler(sys.stdout) console_handler.setFormatter(FORMATTER) return console_handler def get_file_handler(): file_handler = TimedRotatingFileHandler(LOG_FILE, when='midnight') file_handler.setFormatter(FORMATTER) return file_handler def get_logger(logger_name): logger = logging.getLogger(logger_name) logger.setLevel(logging.DEBUG) # better to have too much log than not enough logger.addHandler(get_console_handler()) logger.addHandler(get_file_handler()) # with this pattern, it's rarely necessary to propagate the error up to parent logger.propagate = False return logger

Po utworzeniu nowego rejestratora i użyciu go:

 my_logger = get_logger("my module name") my_logger.debug("a debug message")
  • Użyj klas RotatingFileHandler, takich jak TimedRotatingFileHandler użyty w przykładzie zamiast FileHandler, ponieważ spowoduje to automatyczne obrócenie pliku, gdy plik osiągnie limit rozmiaru lub robi to codziennie.
  • Użyj narzędzi, takich jak Sentry, Airbrake, Raygun itp., aby automatycznie przechwytywać dzienniki błędów. Jest to szczególnie przydatne w kontekście aplikacji internetowych, w których dziennik może być bardzo szczegółowy, a dzienniki błędów można łatwo zgubić. Kolejną zaletą korzystania z tych narzędzi jest to, że można uzyskać szczegółowe informacje na temat wartości zmiennych w błędzie, dzięki czemu można wiedzieć, jaki adres URL powoduje błąd, którego użytkownika dotyczy itp.

Jeśli jesteś zainteresowany innymi najlepszymi praktykami, przeczytaj 10 najczęstszych błędów popełnianych przez programistów Pythona autorstwa innego Toptalera, Martina Chikiliana.