Понимайте свою программу без ущерба для производительности
Журналирование — это очень важная часть разработки ПО. Оно помогает разработчикам лучше понимать выполнение программы и судить о дефектах и непредвиденных сбоях. Журнальное сообщение может хранить информацию наподобие текущего статуса программы или того, в каком месте она выполняется. Если происходит ошибка, то разработчики могут быстро найти строку кода, которая вызвала проблему, и действовать с учетом этого.
Python предоставляет довольно мощный и гибкий встроенный модуль logging со множеством возможностей. В этой статье я хочу поделиться восемью продвинутыми возможностями, которые будут полезны при разработке ПО.
Основы модуля logging
Прежде чем приступить к рассмотрению продвинутых возможностей, давайте убедимся, что у нас есть базовое понимание модуля logging.
Логгер
Экземпляр, который мы создаем для генерации записей, называют логгером. Он инстанциируется через logger = logging.getLogger(name). Лучшая практика — это использовать name в качестве имени логгера. name включает в себя имя пакета и имя модуля. Имя будет появляться в журнальном сообщении, что поможет разработчикам быстро находить, где оно было сгенерировано.
Форматировщик и обработчик
У любого логгера есть несколько конфигураций, которые могут быть модифицированы. Более продвинутые конфигурации мы обсудим позже, а наиболее ходовые — это форматировщик (прим. пер.: formatter) и обработчик (прим. пер.: handler).
Форматировщик устанавливает структуру журнального сообщения. Каждое журнальное сообщение — это объект класса LogRecord с несколькими атрибутами (имя модуля — один из них). Когда мы определяем форматировщик, мы можем решить, как должно выглядеть журнальное сообщение вместе с этими атрибутами и, возможно, с атрибутами, созданными нами. Стандартный форматировщик выглядит так:
серьезность ошибки:имя логгера:сообщение
# например: WARNING:root:Программа стартует!Кастомизированный форматировщик может выглядеть так:
"%(asctime)s - [%(levelname)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s"
# 2020-07-26 23:37:15,374 - [INFO] - __main__ - (main.py).main(18) - Программа стартует!Обработчик задает целевое местонахождение журнальных сообщений. Журнальное сообщение может быть отправлено в более чем одно место. Собственно говоря, модуль logging предоставляет довольно много стандартных обработчиков. Самые популярные — FileHandler, который отправляет записи в файл, и StreamHandler, который отправляет записи в потоки, такие как sys.stderr или sys.stdout. Экземпляр логгера поддерживает ноль или более обработчиков. Если никакие обработчики не определены, тогда он будет отправлять записи в sys.stderr. Если определен более чем один обработчик, тогда целевое местонахождение журнального сообщения зависит от его уровня и от уровня обработчика.
Например, у меня есть FileHandler с уровнем WARNING (прим. пер.: предупреждение) и StreamHandler с уровнем INFO (прим. пер.: информация). Если я напишу в журнал сообщение об ошибке, то оно будет отправлено как в sys.stdout, так и в файл журнала.
Например:
В этом примере мы создали main.py, package1.py, и app_logger.py. Модуль app_logger.py содержит функцию get_logger, которая возвращает экземпляр логгера. Экземпляр логгера включает в себя кастомный форматировщик и два обработчика: StreamHandler с уровнем INFO и FileHandler с уровнем WARNING. Важно установить базовый уровень в INFO или DEBUG (уровень журналирования по умолчанию — WARNING), в противном случае любые записи журнала по уровню ниже, чем WARNING, будут отфильтрованы. И main.py, и package1.py, используют get_logger, чтобы создавать свои собственные логгеры.
Диаграмма Xiaoxu Gao
# app_logger.py
import logging
_log_format = f"%(asctime)s - [%(levelname)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s"
def get_file_handler():
file_handler = logging.FileHandler("x.log")
file_handler.setLevel(logging.WARNING)
file_handler.setFormatter(logging.Formatter(_log_format))
return file_handler
def get_stream_handler():
stream_handler = logging.StreamHandler()
stream_handler.setLevel(logging.INFO)
stream_handler.setFormatter(logging.Formatter(_log_format))
return stream_handler
def get_logger(name):
logger = logging.getLogger(name)
logger.setLevel(logging.INFO)
logger.addHandler(get_file_handler())
logger.addHandler(get_stream_handler())
return logger
# package1.py
import app_logger
logger = app_logger.get_logger(__name__)
def process(msg):
logger.info("Перед процессом")
print(msg)
logger.info("После процесса")
# main.py
import package1
import app_logger
logger = app_logger.get_logger(__name__)
def main():
logger.info("Программа стартует")
package1.process(msg="сообщение")
logger.warning("Это должно появиться как в консоли, так и в файле журнала")
logger.info("Программа завершила работу")
if __name__ == "__main__":
main()
# 2020-07-25 21:06:06,657 - [INFO] - __main__ - (main.py).main(8) - Программа стартует
# 2020-07-25 21:06:06,658 - [INFO] - package1 - (package1.py).process(7) - Перед процессом
# сообщение
# 2020-07-25 21:06:06,658 - [INFO] - package1 - (package1.py).process(9) - После процесса
# 2020-07-25 21:06:06,658 - [WARNING] - __main__ - (main.py).main(10) - Это должно появиться как в консоли, так и в файле журнала
# 2020-07-25 21:06:06,658 - [INFO] - __main__ - (main.py).main(11) - Программа завершила работу
# cat x.log
# 2020-07-25 21:06:06,658 - [WARNING] - __main__ - (main.py).main(10) - Это должно появиться как в консоли, так и в файле журнала
basic-logging.py
Записи с уровнем INFO отправляются как в консольный вывод (sys.stdout), так и в файл журнала, а записи с уровнем WARNING пишутся только в файл журнала. Если вы можете полностью понять, что и почему происходит в этом примере, то мы готовы приступить к более продвинутым возможностям.
1. Создавайте заданные пользователем атрибуты объектов класса LogRecord, используя класс LoggerAdapter
Как я упоминал ранее, у LogRecord есть несколько атрибутов. Разработчики могут выбрать наиболее важные атрибуты и использовать в форматировщике. Помимо того, модуль logging также предоставляет возможность добавить в LogRecord определенные пользователем атрибуты.
Один из способов сделать это — использовать LoggerAdapter. Когда вы создаете адаптер, вы передаете ему экземпляр логгера и свои атрибуты (в словаре). Этот класс предоставляет тот же интерфейс, что и класс Logger, поэтому вы все еще можете вызывать методы наподобие logger.info.
Новый атрибут с фиксированным значением
Если вы хотите иметь что-то вроде атрибута с фиксированным значением в журнальном сообщении, например имя приложения, то вы можете использовать стандартный класс LoggerAdapter и получать значение атрибута при создании логгера (прим. пер.: вероятно, получать откуда-либо, чтобы затем передать конструктору). Не забывайте добавлять этот атрибут в форматировщик. Местоположение атрибута вы можете выбрать по своему усмотрению. В следующем коде я добавляю атрибут app, значение которого определяется, когда я создаю логгер.
import logging
logging.basicConfig(
level=logging.INFO,
format="%(asctime)s - [%(levelname)s] - %(app)s - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",
)
logger = logging.getLogger(__name__)
logger = logging.LoggerAdapter(logger, {"app": "тестовое приложение"})
logger.info("Программа стартует")
logger.info("Программа завершила работу")
# 2020-07-25 21:36:20,709 - [INFO] - тестовое приложение - __main__ - (main.py).main(8) - Программа стартует
# 2020-07-25 21:36:20,709 - [INFO] - тестовое приложение - __main__ - (main.py).main(11) - Программа завершила работу
logging_adapter_fixed_value.py
Новый атрибут с динамическим значением
В других ситуациях вам, возможно, понадобятся динамические атрибуты, например что-то вроде динамического идентификатора. В таком случае вы можете расширить базовый класс LoggerAdapter и создать свой собственный. Метод process() — то место, где дополнительные атрибуты добавляются к журнальному сообщению. В коде ниже я добавляю динамический атрибут id, который может быть разным в каждом журнальном сообщении. В этом случае вам не нужно добавлять атрибут в форматировщик.
import logging
class CustomAdapter(logging.LoggerAdapter):
def process(self, msg, kwargs):
my_context = kwargs.pop('id', self.extra['id'])
return '[%s] %s' % (my_context, msg), kwargs
logging.basicConfig(
level=logging.INFO,
format="%(asctime)s - [%(levelname)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",
)
logger = logging.getLogger(__name__)
logger = CustomAdapter(logger, {"id": None})
logger.info('ID предоставлен', id='1234')
logger.info('ID предоставлен', id='5678')
logger.info('Отсутствует информация об ID')
# 2020-07-25 22:12:06,715 - [INFO] - __main__ - (main.py).<module>(38) - [1234] ID предоставлен# 2020-07-25 22:12:06,715 - [INFO] - __main__ - (main.py).<module>(38) - [1234] ID предоставлен
# 2020-07-25 22:21:31,568 - [INFO] - __main__ - (main.py).<module>(39) - [5678] ID предоставлен# 2020-07-25 22:21:31,568 - [INFO] - __main__ - (main.py).<module>(39) - [5678] ID предоставлен
# 2020-07-25 22:12:06,715 - [INFO] - __main__ - (main.py).<module>(39) - [None] Отсутствует информация об ID# 2020-07-25 22:12:06,715 - [INFO] - __main__ - (main.py).<module>(39) - [None] Отсутствует информация об ID
logging_adapter_dynamic_value.py
2. Создавайте определенные пользователем атрибуты объектов класса LogRecord, используя класс Filter
Другой способ добавления определенных пользователем атрибутов — использование кастомного Filter. Фильтры предоставляют дополнительную логику для определения того, какие журнальные сообщения выводить. Это шаг после проверки базового уровня журналирования, но до передачи журнального сообщения обработчикам. В дополнение к определению, должно ли журнальное сообщение двигаться дальше, мы также можем вставить новые атрибуты в методе filter().
Диаграмма из официальной документации Python
В этом примере мы добавляем новый атрибут color (прим. пер.: цвет) в методе filter(), значение которого определяется на основе имени уровня в журнальном сообщении. В этом случае имя атрибута снова должно быть добавлено в форматировщик.
import logging
class CustomFilter(logging.Filter):
COLOR = {
"DEBUG": "GREEN",
"INFO": "GREEN",
"WARNING": "YELLOW",
"ERROR": "RED",
"CRITICAL": "RED",
}
def filter(self, record):
record.color = CustomFilter.COLOR[record.levelname]
return True
logging.basicConfig(
level=logging.DEBUG,
format="%(asctime)s - [%(levelname)s] - [%(color)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",
)
logger = logging.getLogger(__name__)
logger.addFilter(CustomFilter())
logger.debug("сообщение для отладки, цвет — зеленый")
logger.info("информационное сообщение, цвет — зеленый")
logger.warning("предупреждающее сообщение, цвет — желтый")
logger.error("сообщение об ошибке, цвет — красный")
logger.critical("сообщение о критической ошибке, цвет — красный")
# 2020-07-25 22:45:17,178 - [DEBUG] - [GREEN] - __main__ - (main.py).<module>(52) - сообщение для отладки, цвет — зеленый
# 2020-07-25 22:45:17,179 - [INFO] - [GREEN] - __main__ - (main.py).<module>(53) - информационное сообщение, цвет — зеленый
# 2020-07-25 22:45:17,179 - [WARNING] - [YELLOW] - __main__ - (main.py).<module>(54) - предупреждающее сообщение, цвет — желтый
# 2020-07-25 22:45:17,179 - [ERROR] - [RED] - __main__ - (main.py).<module>(55) - сообщение об ошибке, цвет — красный
# 2020-07-25 22:45:17,179 - [CRITICAL] - [RED] - __main__ - (main.py).<module>(56) - сообщение о критической ошибке, цвет — красный
logging_filter_dynamic_attributes.py
3. Многопоточность с модулем logging
Модуль logging на самом деле реализован потокобезопасным способом, поэтому нам не нужны дополнительные усилия. Код ниже показывает, что MainThread и WorkThread разделяют один и тот же экземпляр логгера без проблемы состояния гонки. Также есть встроенный атрибут threadName для форматировщика.
import logging
import threading
logging.basicConfig(
level=logging.INFO,
format="%(asctime)s - [%(levelname)s] - [%(threadName)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",
)
logger = logging.getLogger(__name__)
def worker():
for i in range(5):
logger.info(f"журнальное сообщение {i} из рабочего потока")
thread = threading.Thread(target=worker)
thread.start()
for i in range(5):
logger.info(f"журнальное сообщение {i} из главного потока")
thread.join()
# 2020-07-26 15:33:21,078 - [INFO] - [Thread-1] - __main__ - (main.py).worker(62) - 0-ое журнальное сообщение из рабочего потока
# 2020-07-26 15:33:21,078 - [INFO] - [Thread-1] - __main__ - (main.py).worker(62) - 1-ое журнальное сообщение из рабочего потока
# 2020-07-26 15:33:21,078 - [INFO] - [Thread-1] - __main__ - (main.py).worker(62) - 2-ое журнальное сообщение из рабочего потока
# 2020-07-26 15:33:21,078 - [INFO] - [Thread-1] - __main__ - (main.py).worker(62) - 3-ое журнальное сообщение из рабочего потока
# 2020-07-26 15:33:21,078 - [INFO] - [Thread-1] - __main__ - (main.py).worker(62) - 4-ое журнальное сообщение из рабочего потока
# 2020-07-26 15:33:21,078 - [INFO] - [MainThread] - __main__ - (main.py).<module>(69) - 0-ое журнальное сообщение из главного потока
# 2020-07-26 15:33:21,078 - [INFO] - [MainThread] - __main__ - (main.py).<module>(69) - 1-ое журнальное сообщение из главного потока
# 2020-07-26 15:33:21,078 - [INFO] - [MainThread] - __main__ - (main.py).<module>(69) - 2-ое журнальное сообщение из главного потока
# 2020-07-26 15:33:21,078 - [INFO] - [MainThread] - __main__ - (main.py).<module>(69) - 3-ое журнальное сообщение из главного потока
# 2020-07-26 15:33:21,078 - [INFO] - [MainThread] - __main__ - (main.py).<module>(69) - 4-ое журнальное сообщение из главного потока
logging_multi_threading.py
Под капотом модуль logging использует threading.RLock() практически везде. Отличия между RLock от Lock:
Lock может быть получен только один раз и больше не может быть получен до тех пор, пока он не будет освобожден. С другой стороны, RLock может быть получен неоднократно до своего освобождения, но он должен быть освобожден столько же раз.
Lock может быть освобожден любым потоком, а RLock — только тем потоком, который его удерживает.
Любой обработчик, который наследуется от класса Handler, обладает методом handle(), предназначенным для генерации записей. Ниже представлен блок кода метода Handler.handle(). Как видите, обработчик получит и освободит блокировку до и после генерации записи соответственно. Метод emit() может быть реализован по-разному в разных обработчиках.
def handle(self, record):
"""
При определенных условиях генерирует журнальную запись.
Генерация зависит от фильтров, которые могут быть добавлены в обработчик.
Оборачивает настоящую генерацию записи получением/освобождением
блокировки потока ввода-вывода. Возвращает значение, свидетельствующее о том, пропустил ли фильтр запись на
генерацию.
"""
rv = self.filter(record)
if rv:
self.acquire()
try:
self.emit(record)
finally:
self.release()
return rv
logging_handle.py
4. Многопроцессная обработка с модулем logging — QueueHandler
Несмотря на то, что модуль logging потокобезопасен, он не процессобезопасен. Если вы хотите, чтобы несколько процессов вели запись в один и тот же файл журнала, то вы должны вручную позаботиться о доступе к вашему файлу. В соответствии с учебником по logging, есть несколько вариантов.
QueueHandler + «процесс-потребитель»
Один из вариантов — использование QueueHandler. Идея заключается в том, чтобы создать экземпляр класса multiprocessing.Queue и поделить его между любым количеством процессов. В примере ниже у нас есть 2 «процесса-производителя», которые отправляют записи журнала в очередь и «процесс-потребитель», читающий записи из очереди и пишущий их в файл журнала.
У записей журнала в очереди будут, вероятно, разные уровни, так что в функции log_processor мы используем logger.log(record.levelno, record.msg) вместо logger.info() или logger.warning(). В конце (прим. пер.: функции main) мы отправляем сигнал, чтобы позволить процессу log_processor остановиться. Деление экземпляра очереди между множеством процессов или потоков — не новшество, но модуль logging как бы помогает нам справиться с этой ситуацией.
import os
from logging.handlers import QueueHandler
formatter = "%(asctime)s - [%(levelname)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s"
logging.basicConfig(level=logging.INFO)
def log_processor(queue):
logger = logging.getLogger(__name__)
file_handler = logging.FileHandler("a.log")
file_handler.setFormatter(logging.Formatter(formatter))
logger.addHandler(file_handler)
while True:
try:
record = queue.get()
if record is None:
break
logger.log(record.levelno, record.msg)
except Exception as e:
pass
def log_producer(queue):
pid = os.getpid()
logger = logging.getLogger(__name__)
queue_handler = QueueHandler(queue)
logger.addHandler(QueueHandler(queue))
logger.info(f"уровень INFO - производитель {pid}")
logger.warning(f"уровень WARNING - производитель {pid}")
def main():
queue = multiprocessing.Queue(-1)
listener = multiprocessing.Process(target=log_processor, args=(queue,))
listener.start()
workers = []
for i in range(2):
worker = multiprocessing.Process(target=log_producer, args=(queue,))
workers.append(worker)
worker.start()
for w in workers:
w.join()
queue.put_nowait(None)
listener.join()
if __name__ == '__main__':
main()
# >> cat a.log
# 2020-07-26 18:38:10,525 - [INFO] - __mp_main__ - (main.py).log_processer(118) - уровень INFO - производитель 32242
# 2020-07-26 18:38:10,525 - [WARNING] - __mp_main__ - (main.py).log_processer(118) - уровень WARNING - производитель 32242
# 2020-07-26 18:38:10,530 - [INFO] - __mp_main__ - (main.py).log_processer(118) - уровень INFO - производитель 32243
# 2020-07-26 18:38:10,530 - [WARNING] - __mp_main__ - (main.py).log_processer(118) - уровень WARNING - производитель 32243
logging_queue_handler.py
QueueHandler + QueueListener
В модуле logging.handlers есть особый класс с именем QueueListener. Этот класс создает экземпляр слушателя с очередью журнальных сообщений и списком обработчиков для обработки записей журнала. QueueListener может заменить процесс, который мы создали в предыдущем примере, поместив его в переменную listener. При этом будет использовано меньше кода.
def log_producer(queue):
pid = os.getpid()
logger = logging.getLogger(__name__)
logger.addHandler(QueueHandler(queue))
logger.info(f"уровень INFO - производитель {pid}")
logger.warning(f"уровень WARNING - производитель {pid}")
def main():
queue = multiprocessing.Queue(-1)
file_handler = logging.FileHandler("b.log")
file_handler.setFormatter(logging.Formatter(formatter))
queue_listener = QueueListener(queue, file_handler)
queue_listener.start()
workers = []
for i in range(2):
worker = multiprocessing.Process(target=log_producer, args=(queue,))
workers.append(worker)
worker.start()
for w in workers:
w.join()
queue_listener.stop()
if __name__ == '__main__':
main()
# >> cat b.log
# 2020-07-26 20:15:58,656 - [INFO] - __mp_main__ - (main.py).log_producer(130) - уровень INFO - производитель 34199
# 2020-07-26 20:15:58,656 - [WARNING] - __mp_main__ - (main.py).log_producer(131) - уровень WARNING - производитель 34199
# 2020-07-26 20:15:58,662 - [INFO] - __mp_main__ - (main.py).log_producer(130) - уровень INFO - производитель 34200
# 2020-07-26 20:15:58,662 - [WARNING] - __mp_main__ - (main.py).log_producer(131) - уровень WARNING - производитель 34200
logging_queue_listener.py
SocketHandler
Другое решение, предлагаемое учебником, — отправлять записи из нескольких процессов в SocketHandler и иметь отдельный процесс, который реализует сокет-сервер, читающий записи и отправляющий их в место назначения. В этих источниках есть довольно подробная реализация.
Все эти решения, в основном, следуют одному принципу: отправлять записи из разных процессов в централизованное место — либо в очередь, либо на удаленный сервер. Получатель на другой стороне ответственен за их запись в места назначения.
5. По умолчанию не генерируйте какие-либо журнальные записи библиотеки — NullHandler
На данный момент мы упомянули несколько обработчиков, реализованных модулем logging.
Другой полезный встроенный обработчик — NullHandler. В реализации NullHandler практически ничего нет. Тем не менее, он помогает разработчикам отделить библиотечные записи журнала от записей приложения.
Ниже приведена реализация обработчика NullHandler.
class NullHandler(Handler):
"""
Этот обработчик ничего не делает. Предполагается использовать его, чтобы избежать
разового предупреждения "Для логгера XXX не найдено никаких обработчиков". Это
важно для кода библиотеки, который может содержать код для журналирования событий. Если пользователь
библиотеки не настроил конфигурацию журналирования, то может быть
создано разовое предупреждение; чтобы избежать этого, разработчику библиотеку нужно просто создать экземпляр класса
NullHandler и добавить его в логгер верхнего уровня модуля библиотеки или
пакета.
"""
def handle(self, record):
"""Заглушка."""
def emit(self, record):
"""Заглушка."""
def createLock(self):
self.lock = None
logging_nullhandler.py
Почему нам нужно отделять записи библиотеки от записей приложения?
По словам автора модуля logging, Vinay Sajip:
Сторонняя библиотека, которая использует logging, по умолчанию не должна выбрасывать вывод журналирования, так как он может быть не нужен разработчику/пользователю приложения, которое использует библиотеку.
Наилучшая практика — по умолчанию не генерировать библиотечные записи журнала и давать пользователю библиотеки возможность решить, хочет ли он получать и обрабатывать эти записи в приложении.
В роли разработчика библиотеки нам нужна только одна строка кода внутри init.py, чтобы добавить NullHandler. Во вложенных пакетах и модулях логгеры остаются прежними. Когда мы устанавливаем этот пакет в наше приложение через pip install, мы по умолчанию не увидим библиотечные записи журнала.
# package/
# │
# ├── __init__.py
# └── module1.py
# __init__.py
import logging
logging.getLogger(__name__).addHandler(logging.NullHandler())
# module1.py
logger = logging.getLogger(__name__)
logger.info("это информационное журнальное сообщение")
logging_nullhandler_example.py
Чтобы сделать эти записи видимыми, нужно добавить обработчики в логгер библиотеки в своем приложении.
# ваше приложение
logging.getLogger("package").addHandler(logging.StreamHandler())
Если библиотека не использует NullHandler, но вы хотите отключить записи из библиотеки, то можете установить logging.getLogger("package").propagate = False. Если propagate установлен в False, то записи журнала не будут передаваться обработчикам.
6. Делайте ротацию своих файлов журнала — RotatingFileHandler, TimedRotatingFileHandler
RotatingFileHandler поддерживает ротацию файлов журнала, основанную на максимальном размере файла. Здесь должны быть определено два параметра: maxBytes и backupCount. Параметр maxBytes сообщает обработчику, когда делать ротацию журнала. Параметр backupCount — количество файлов журнала. У каждого «продолженного» файла журнала есть суффикс «.1», «.2» в конце имени файла. Если текущее журнальное сообщение вот-вот позволит файлу журнала превысить максимальный размер, то обработчик закроет текущий файл и откроет следующий.
Вот этот пример очень похож на пример из учебника. Должно получиться 6 файлов журнала.
import logging
from logging.handlers import RotatingFileHandler
def create_rotating_log(path):
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)
handler = RotatingFileHandler(path, maxBytes=20, backupCount=5)
logger.addHandler(handler)
for i in range(100):
logger.info("Это тестовая строка-запись в журнале %s" % i)
if __name__ == "__main__":
log_file = "test.log"
create_rotating_log(log_file)
logging_file_rotation.py
Другой обработчик для ротации файлов — TimeRotatingFileHandler, который позволяет разработчикам создавать ротационные журналы, основываясь на истекшем времени. Условия времени включают: секунду, минуту, час, день, день недели (0=Понедельник) и полночь (журнал продлевается в полночь).
В следующем примере мы делаем ротацию файла журнала каждую секунду с пятью резервными файлами. В каждом резервном файле есть временная метка в качестве суффикса.
import logging
import time
from logging.handlers import TimedRotatingFileHandler
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)
handler = TimedRotatingFileHandler(
"timed_test.log", when="s", interval=1, backupCount=5
)
logger.addHandler(handler)
for i in range(6):
logger.info(i)
time.sleep(1)
time_file_rotation.py
7. Исключения в процессе журналирования
Зачастую мы используем logger.error() или logger.exception() при обработке исключений. Но что если сам логгер генерирует исключение? Что случится с программой? Ну, зависит от обстоятельств.
Ошибка логгера обрабатывается, когда обработчик вызывает метод emit(). Это означает, что любое исключение, связанное с форматированием или записью, перехватывается обработчиком, а не поднимается. Если конкретнее, метод handleError() будет выводить трассировку в stderr, и программа продолжится. Если у вас есть кастомный обработчик, наследуемый от класса Handler, то вы можете реализовать свой собственный handleError().
def emit(self, record):
"""
Генерирует запись.
Если форматировщик указан, он используется для форматирования записи.
Затем запись пишется в поток с завершающим символом переноса строки. Если
предоставлена информация об исключении, то она форматируется с использованием
traceback.print_exception и добавляется в конец потока. Если у потока
есть атрибут 'encoding', он используется для определения того, как делать
вывод в поток.
"""
try:
msg = self.format(record)
stream = self.stream
# issue 35046: merged two stream.writes into one.
stream.write(msg + self.terminator)
self.flush()
except RecursionError: # See issue 36272
raise
except Exception:
self.handleError(record)
logging_emit.py
В этом примере во втором журнальном сообщении слишком много аргументов. Поэтому в консольном выводе мы получили трассировку, и выполнение программы все еще могло быть продолжено.
import logging
logging.basicConfig(
level=logging.INFO,
format="%(asctime)s - [%(levelname)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",
)
logger = logging.getLogger(__name__)
logger.info("Программа стартует")
logger.info("У этого сообщения %s слишком много аргументов", "msg", "other")
logger.info("Программа завершила работу")
# 2020-07-26 23:37:15,373 - [INFO] - __main__ - (main.py).main(16) - Программа стартует
# --- Logging error ---
# Traceback (most recent call last):
# File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 1197, in emit
# msg = self.format(record)
# File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 1032, in format
# return fmt.format(record)
# File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 756, in format
# record.message = record.getMessage()
# File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 443, in getMessage
# msg = msg % self.args
# TypeError: not all arguments converted during string formatting (прим. пер.: не все аргументы конвертированы при форматировании строки)
# Call stack:
# File "/Users/ie15qx/repo/compare_xml_files/source/main.py", line 22, in <module>
# main()
# File "/Users/ie15qx/repo/compare_xml_files/source/main.py", line 17, in main
# logger.info("У этого сообщения %s слишком много аргументов", "msg", "other")
# Message: 'У этого сообщения %s слишком много аргументов'
# Arguments: ('msg', 'other')
# 2020-07-26 23:37:15,374 - [INFO] - __main__ - (main.py).main(18) - Программа завершила работу
logging_error_handle.py
Однако, если исключение произошло за пределами emit(), то оно может быть поднято, и программа остановится. Например, в коде ниже мы добавляем дополнительный атрибут id в logger.info без его обработки в LoggerAdapter. Эта ошибка не обработана и приводит к остановке программы.
import logging
logging.basicConfig(
level=logging.INFO,
format="%(asctime)s - [%(levelname)s] - %(app)s - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",
)
logger = logging.getLogger(__name__)
logger = logging.LoggerAdapter(logger, {"app": "тестовое приложение"})
logger.info("Программа стартует", id="123")
logger.info("Программа завершила работу")
# source/main.py
# Traceback (most recent call last):
# File "/Users/ie15qx/repo/compare_xml_files/source/main.py", line 10, in <module>
# logger.info("Программа стартует", id="123")
# File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 1960, in info
# self.log(INFO, msg, *args, **kwargs)
# File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 2001, in log
# self.logger.log(level, msg, *args, **kwargs)
# File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 1637, in log
# self._log(level, msg, args, **kwargs)
# TypeError: _log() got an unexpected keyword argument 'id' (прим. пер.: _log() получил непредвиденный именованный аргумент 'id')
logging_exception_raise.py
8. Три разных способа конфигурирования своего логгера
Последний пункт, которым я хотел поделиться, — о конфигурировании своего логгера. Есть три способа конфигурирования логгера.
используйте код
Самый простой вариант — использовать код для конфигурирования своего логгера, так же, как во всех примерах, что мы видели ранее в этой статье. Но недостаток этого варианта в том, что любая модификация (прим. пер.: конфигурации) требует внесения изменений в исходном коде.
use dictConfig
Второй вариант — записывать конфигурацию в словарь и использовать logging.config.dictConfig, чтобы читать ее. Вы также можете сохранить словарь в JSON-файл и читать оттуда. Плюс в том, что этот файл может быть загружен как внешняя конфигурация, но он может способствовать появлению ошибок из-за своей структуры.
import logging
import logging.config
LOGGING_CONFIG = {
'version': 1,
'disable_existing_loggers': True,
'formatters': {
'standard': {
'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s'
},
},
'handlers': {
'default': {
'level': 'INFO',
'formatter': 'standard',
'class': 'logging.StreamHandler',
'stream': 'ext://sys.stdout',
},
},
'loggers': {
'': { # root logger
'handlers': ['default'],
'level': 'DEBUG',
'propagate': True,
}
},
}
logging.config.dictConfig(LOGGING_CONFIG)
if __name__ == "__main__":
log = logging.getLogger(__name__)
log.info("hello world")
# 2020-07-28 21:44:09,966 [INFO] __main__: hello world
logging_configure_json.py
используйте fileConfig
И последний, но не менее важный, третий вариант — использовать logging.config.fileConfig Конфигурация записывается в отдельный файл формата .ini.
# logging_config.ini
# [loggers]
# keys=root
# [handlers]
# keys=stream_handler
# [formatters]
# keys=formatter
# [logger_root]
# level=DEBUG
# handlers=stream_handler
# [handler_stream_handler]
# class=StreamHandler
# level=DEBUG
# formatter=formatter
# args=(sys.stderr,)
# [formatter_formatter]
# format=%(asctime)s %(name)-12s %(levelname)-8s %(message)s
import logging
from logging.config import fileConfig
fileConfig('logging_config.ini')
logger = logging.getLogger()
logger.debug('hello world')
logging_configure_file.py
Есть возможность обновлять конфигурацию во время выполнения программы через сервер конфигурации. Учебник показывает пример как со стороны клиента, так и со стороны сервера. Конфигурация обновляется посредством подключения через сокет, а на стороне клиента мы используем c = logging.config.listen(PORT) c.start(), чтобы получать самую новую конфигурацию.
Надеюсь, эти советы и приемы, связанные с модулем logging, могут помочь вам создать вокруг вашего приложения хороший фреймворк для журналирования без ущерба для производительности. Если у вас есть что-нибудь, чем можно поделиться, пожалуйста, оставьте комментарий ниже!
