Логування в Python

Майже будь-який розробник не уявляє своєї роботи без логів. З ними легше зрозуміти особливості роботи програми, виявити сценарії поведінки, про які ви і не підозрювали.

Логи можна порівняти з додатковою парою очей, що постійно спостерігають за виконанням програми. Вони також можуть зберігати інформацію (наприклад, дані про користувача чи IP-адресу відвідувача). Якщо виникає помилка, вони знають про стан програми до виникнення помилки і дають більше інформації, ніж просто стек-трейс.

Якщо використовувати логи в правильному місці, ви з легкістю відловлюватимете помилки і зможете аналізувати продуктивність вашого застосунку для подальшого його вдосконалення.

У Python система логування є частиною стандартної бібліотеки, тому ви без труднощів можете використовувати її у застосунку. З цього матеріалу ви дізнаєтесь, чому використання модуля logging — найкращий спосіб організувати логи. Ми покажемо, як швидко все налаштувати, а бонусом стануть декілька просунутих фіч.

Модуль Logging

logging в Pytnon — потужний і готовий до використання модуль, який задовольняє потреби і початківців, і корпоративних команд. Він використовується багатьма сторонніми бібліотеками Python, тому ви можете інтегрувати їхні логи для однорідності.

Щоб додати модуль до своєї програми на Python, просто виконайте команду:

import logging

З імпортованим модулем ви можете використовувати так званий «логер». За замовчуванням є 5 ступенів серйозності подій. Кожен має відповідний метод для логування подій на кожному зі згаданих рівнів. Наведемо перелік рівнів повідомлень за зростанням їх серйозності:

• DEBUG
• INFO
• WARNING
• ERROR
• CRITICAL

Модуль logging передбачає логер за замовчуванням, який дозволяє почати роботу з мінімальною конфігурацією. Відповідні методи для кожного рівня логів можна викликати так:

import logging

logging.debug('This is a debug message')
logging.info('This is an info message')
logging.warning('This is a warning message')
logging.error('This is an error message')
logging.critical('This is a critical message')

Результат роботи програми:

WARNING:root:This is a warning message
ERROR:root:This is an error message
CRITICAL:root:This is a critical message

Тут ми бачимо повідомлення, які супроводжуються рівнем серйозності та root — назвою логера за замовчуванням (детальніше про логери розповімо далі). Подібний формат (рівень, назва та повідомлення, відокремлені двокрапкою) використовується за замовчуванням, проте його можна змінити, додавши вказівку часу, номер рядка та інші деталі.

Помітьте, що повідомлення з методів debug() та info() не відображаються в логах. Усе тому, що за замовчуванням логер обробляє лише повідомлення з рівнем WARNING та вище. Таку поведінку можна змінити, якщо налаштувати модуль. Ще можна визначити власні рівні, але не варто, тому що виникне плутанина при роботі з логами сторонніх бібліотек.

Базове налаштування

Ви можете використовувати метод basicConfig(**kwargs) для конфігурації.

Можна помітити, що модуль logging порушує угоду щодо стилю PEP8, оскільки використовується camelCase. Усе через запозичення модуля з Log4j, утиліти для логування в Java. Коли було вирішено додати модуль до стандартної бібліотеки, розробники вже звикли до такого формату іменування, а підлаштування під вимоги PEP8 могло викликати проблеми зі зворотною сумісністю.

Оглянемо деякі з найбільш використовуваних параметрів для basicConfig():

• level: рівень серйозності, який буде встановлено для кореневого логера;
• filename : визначає файл;
• filemode: якщо параметр filename задано, файл відкриється в зазначеному цим параметром режимі. За замовчування це а, що означає «приєднання в кінець».
• format: визначає формат кінцевого повідомлення.

Використовуючи параметр level, ви можете встановити потрібний рівень повідомлень, які хочете відстежувати. Як варіант, можна передавати одну з констант, що активує усі виклики зазначеного рівня серйозності та вище. Наприклад:

import logging

logging.basicConfig(level=logging.DEBUG)
logging.debug('This will get logged')

Результат:

DEBUG:root:This will get logged

Тепер усі події рівня DEBUG та вище будуть логуватися.

Те ж саме з логуванням до файлу: використовуйте filename та filemode, а також format, щоб визначити формат отриманих повідомлень. Ось так все працює:

import logging

logging.basicConfig(filename='app.log', filemode='w', format='%(name)s - %(levelname)s - %(message)s')
logging.warning('This will get logged to a file')

Результат:

root - ERROR - This will get logged to a file

Отримане повідомлення буде записане до файлу app.log, а не в консоль. Як filemode зазначено w, що дозволяє відкрити файл в режимі «запису» кожного разу, коли викликано basicConfig(), тобто при кожному запуску програми зміст файлу перезаписуватиметься. Значення за замовчуванням для filemode — a, що означає «приєднати в кінець».

Ви можете додати ще більше налаштувань, використовуючи додаткові параметри для basicConfig(), з якими можна ознайомитись за посиланням.

Варто помітити, що виклик basicConfig() для налаштування root-логера працюватиме, лише якщо він попередньо не налаштовувався. Тобто функція може викликатись лише одноразово.

debug(), info(), warning(), error() та critical() також викликають basicConfig() без аргументів автоматично, якщо це перший виклик. Якщо одна з перелічених функцій була викликана, ви більше не можете налаштувати root-логер, оскільки basicConfig() вже автоматично викликались.

За замовчування basicConfig() визначає такий формат повідомлень в консолі:

ERROR:root:This is an error message

Форматування результату

Ви можете передавати будь-яку змінну, представлену рядком, з вашої програми у якості повідомлення для логів. У складі LogRecord існують деякі базові елементи, які легко можна додати до результату.

Якщо ви хочете логувати ID процесу поруч з рівнем серйозності та повідомленням, можна зробити щось подібне:

import logging

logging.basicConfig(format='%(process)d-%(levelname)s-%(message)s')
logging.warning('This is a Warning')

Результат:

18472-WARNING-This is a Warning

format може приймати рядок з атрибутами LogRecord у будь-якій послідовності. Повний список доступних атрибутів можна знайти за посиланням.

Ще один приклад того, як можна додати інформацію про дату та час:

import logging

logging.basicConfig(format='%(asctime)s - %(message)s', level=logging.INFO)
logging.info('Admin logged in')

Результат:

2018-07-11 20:12:06,288 - Admin logged in

%(asctime)s визначає час створення LogRecord. Формат можна змінити, використовуючи атрибут datefmt за тим самим принципом форматування, що і в модулі datetime (на зразок time.strftime()).

import logging

logging.basicConfig(format='%(asctime)s - %(message)s', datefmt='%d-%b-%y %H:%M:%S')
logging.warning('Admin logged out')

Результат:

12-Jul-18 20:53:19 - Admin logged out

Детальніше за посиланням.

Логування змінюваних даних

У багатьох випадках виникає потреба додати в логи динамічну інформацію з вашого застосунку. Ви вже знаєте, що методи logging приймають як аргумент рядок. Виникає логічне запитання: чому ми не можемо додати до рядка потрібні змінні окремо, а потім передати сформований результат в метод логу? Однак зайвих дій можна уникнути, якщо передавати рядок зі змінюваними даними як аргумент одразу. Розглянемо приклад:

import logging

name = 'John'

logging.error('%s raised an error', name)

Результат:

ERROR:root:John raised an error

Аргументи, передані в метод, стануть частиною рядка.

Ви можете використовувати будь-який стиль форматування, але Python 3.6 запропонував чудовий спосіб для рядків — f-string. Так ваше форматування буде лаконічним та простим для розуміння:

import logging

name = 'John'

logging.error(f'{name} raised an error')

Результат:

ERROR:root:John raised an error

Охоплюємо стек-трейси

Модуль logging також дозволяє отримувати повний стек-трейс застосунку. Інформацію про виключення можна отримати, передавши значення параметра exc_info як true. Розглянемо на прикладі:

import logging

a = 5
b = 0

try:
  c = a / b
except Exception as e:
  logging.error("Exception occurred", exc_info=True)

Вивід у консоль:

ERROR:root:Exception occurred
Traceback (most recent call last):
  File "exceptions.py", line 6, in <module>
    c = a / b
ZeroDivisionError: division by zero
[Finished in 0.2s]

Якщо ми не встановимо значення exc_info як true, то не побачимо у консолі жодної інформації про виключення. А в реальних випадках це може бути щось серйозніше за ZeroDivisionError. Уявімо ситуацію, за якої вам треба відловити помилку у складній кодовій базі, а ваші логи мають такий вигляд:

ERROR:root:Exception occurred

Одразу порадимо: якщо ви логуєте з обробника виключень, використовуйте метод logging.exception(), який працює з повідомленням рівня ERROR та додає інформацію про виключення. Простіше кажучи, виклик logging.exception() — це як logging.error(exc_info=True). Оскільки ці методи завжди працюють з інформацією про виключення, їх слід викликати лише з обробника виключень.

Розглянемо такий приклад:

import logging

a = 5
b = 0
try:
  c = a / b
except Exception as e:
  logging.exception("Exception occurred")

Результат:

ERROR:root:Exception occurred
Traceback (most recent call last):
  File "exceptions.py", line 6, in <module>
    c = a / b
ZeroDivisionError: division by zero
[Finished in 0.2s]

Тут ми бачимо, як logging.exception() показує повідомлення рівня ERROR. Якщо ви такого не хочете, можете викликати будь-який інший метод логування (від debug() до critical()) та передати параметр exc_info зі значенням true.

Класи та функції

Досі ми мали справу лише з логером за замовчуванням root, який використовується logging кожен раз, коли його функції викликаються у такий спосіб: logging.debug(). Ви можете (це навіть бажано) визначити власний логер, створивши об'єкт класу Logger, особливо якщо ваш застосунок має декілька модулів.

Оглянемо деякі класи та функції модуля детальніше:

• Logger: клас, чиї об'єкти ми використовуватимемо для виклику функцій;
• LogRecord: логери автоматично створюють об'єкти LogRecord, які містять всю інформацію стосовно події, яка логується (як от назва логера, функція, номер рядка, повідомлення тощо).
• Handler: відправляє LogRecord в потрібне місце виводу (наприклад, консоль чи файл). Handler є батьківським класом для StreamHandler, FileHandler, SMTPHandler, HTTPHandler та інших. Вказані підкласи направляють вивід до відповідного місця (як от sys.stdout чи файл на диску).
• Formatter: визначає формат виводу шляхом визначення рядка з атрибутами, які повинен містити кінцевий результат.

З усього переліченого ми в основному маємо справу з об'єктами класу Logger, які створюються з використанням функції logging.getLogger(name). Кілька викликів getLogger() з однаковим параметром name повертають посилання на той самий об'єкт Logger, що вберігає нас від передачі об'єкта в декілька місць в коді. Розглянемо приклад:

import logging

logger = logging.getLogger('example_logger')
logger.warning('This is a warning')

Результат в консолі:

This is a warning

Тут ми створюємо користувацький логер example_logger, але на відміну від root, його назва не входить до відформатованого результату. Однак, додавши трохи налаштувань, отримаємо потрібний результат:

WARNING:example_logger:This is a warning

Знову ж таки: на відміну від root-логера, користувацький логер не можна налаштувати з basicConfig(). Для цього слід використовувати об'єкти Handler та Formatter.

При створенні об'єкта логера рекомендується передавати __name__ як параметр назви в getLogger(), оскільки сама по собі назва логера показує нам, звідки ми отримали подію. __name__ є спеціальною вбудованою змінною в Python, яка зіставляється з назвою поточного модуля.

Використання обробників

Обробники приходять на допомогу, коли вам треба налаштувати власні логери та виводити логи в різних місцях. Обробники надсилають повідомлення до визначеного місця, на зразок стандартного потоку виводу чи файлу через HTTP, або ж на ваш імейл через SMTP.

Створений вами логер може мати декілька обробників, тобто ви можете зберегти його у файл і водночас відправити електронною поштою.

Як і в логерах, в обробниках можна встановити рівень серйозності. Це особливо корисно, якщо ви хочете встановити декілька обробників для того самого логера, але з різним рівнем серйозності для кожного. Наприклад, логи рівня WARNING та вище вам потрібні в консолі, а все, що рівня ERROR та вище, треба додатково зберігати до файлу.

Реалізуємо таку поведінку:

# logging_example.py

import logging

# Створюємо користувацький логер
logger = logging.getLogger(__name__)

# Створюємо обробники
c_handler = logging.StreamHandler()
f_handler = logging.FileHandler('file.log')
c_handler.setLevel(logging.WARNING)
f_handler.setLevel(logging.ERROR)

# Створюємо форматувальники та передаємо їх обробникам 
c_format = logging.Formatter('%(name)s - %(levelname)s - %(message)s')
f_format = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
c_handler.setFormatter(c_format)
f_handler.setFormatter(f_format)

# Додаємо обробники до логера
logger.addHandler(c_handler)
logger.addHandler(f_handler)

logger.warning('This is a warning')
logger.error('This is an error')

Результат в консолі:

__main__ - WARNING - This is a warning
__main__ - ERROR - This is an error

Тут logger.warning() створює LogRecord, який зберігає усю інформацію про подію та передає її визначеним обробникам: c_handler та f_handler.

c_handler створено як StreamHandler з рівнем WARNING. Він бере інформацію з LogRecord для генерації виводу у визначеному форматі та друкує в консоль. f_handler визначено як FileHandler з рівнем ERROR. Він ігнорує попередній LogRecord, оскільки його рівень — WARNING.

Коли викликається logger.error(), c_handler поводиться так само, як і раніше, а f_handler отримує LogRecord з рівнем ERROR, тому продовжує виводити інформацію як c_handler, але тепер не в консоль, а до файлу з таким форматом:

2018-08-03 16:12:21,723 - __main__ - ERROR - This is an error

Назва логера відповідає змінній __name__. Python призначає цій змінній назву модуля, де починається виконання. Якщо цей файл імпортовано іншим модулем, то змінна __name__ могла б відповідати його назві (наприклад, logging_example).

Поглянемо, як все працює:

# run.py

import logging_example

Результат:

logging_example - WARNING - This is a warning
logging_example - ERROR - This is an error

Інші конфігураційні методи

Ви можете налаштувати вказане вище логування, якщо використаєте модуль та функції класу або ж створите файл конфігу чи словник, а тоді завантажите його, послуговуючись fileConfig() або dictConfig() відповідно. Такий підхід корисний, якщо ви хочете змінити конфігурацію вашого логування у вже запущеному застосунку.

Приклад файлу конфігурації:

[loggers]
keys=root,sampleLogger

[handlers]
keys=consoleHandler

[formatters]
keys=sampleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_sampleLogger]
level=DEBUG
handlers=consoleHandler
qualname=sampleLogger
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=sampleFormatter
args=(sys.stdout,)

[formatter_sampleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s

Вище визначено два логера: один обробник та один форматувальник. Перед зазначеними назвами додаються logger, handler та formatter відповідно, відокремлені нижнім підкресленням.

Щоб завантажити такий конфіг, викликаємо fileConfig():

import logging
import logging.config

logging.config.fileConfig(fname='file.conf', disable_existing_loggers=False)

# Отримуємо логер, визначений у файлі
logger = logging.getLogger(__name__)

logger.debug('This is a debug message')

Результат:

2018-07-13 14:05:03,766 - __main__ - DEBUG - This is a debug message

Висновок

Модуль logging вважається дуже гнучким та практичним, тому він підійде до ваших вимог вже «з коробки». Ви можете реалізувати базове логування для маленького проекту чи піти далі та створити власні користувацькі рівні логів, класи обробників тощо.

Якщо ви досі не використовували логи у своєму застосунку, саме час почати. За правильної організації, логування справді збереже від помилок і допоможе вдосконалити ваш застосунок.