В этом разделе разберем примеры продвинутого использования пакета журналирования событий logging.
Пакет logging использует модульный подход и предлагает несколько категорий компонентов: регистраторы, обработчики, фильтры и форматеры.
Logger предоставляют интерфейс, который непосредственно использует код приложения.Handler отправляют записи журнала (созданные регистраторами) в соответствующий пункт назначения.Filter предоставляют более точную возможность определить, какие записи журнала выводить.Formatter определяют расположение записей журнала в конечном выводе.Создание регистраторов, обработчиков и форматтеров в явном виде с использованием кода Python, который вызывает методы конфигурации.
# test.py import logging # создаем регистратор logger = logging.getLogger('logger') logger.setLevel(logging.DEBUG) # создаем обработчик для файла и # установим уровень отладки ch = logging.FileHandler('example.log') ch.setLevel(logging.DEBUG) # строка формата сообщения strfmt = '[%(asctime)s] [%(name)s] [%(levelname)s] > %(message)s' # строка формата времени datefmt = '%Y-%m-%d %H:%M:%S' # создаем форматтер formatter = logging.Formatter(fmt=strfmt, datefmt=datefmt) # добавляем форматтер к 'ch' ch.setFormatter(formatter) # добавляем ch в регистратор logger.addHandler(ch) # вызов функций, регистрирующих # события в коде logger.debug('debug message') logger.info('info message') logger.warning('warn message') logger.error('error message') logger.critical('critical message')
Запуск этого кода приведет к созданию файла 'example.log' с записями внутри:
[2020-06-08 07:42:59] [logger] [DEBUG] > debug message [2020-06-08 07:42:59] [logger] [INFO] > info message [2020-06-08 07:42:59] [logger] [WARNING] > warn message [2020-06-08 07:42:59] [logger] [ERROR] > error message [2020-06-08 07:42:59] [logger] [CRITICAL] > critical message
Следующий код Python создает регистратор, обработчик и форматер, почти идентичные тем, что в приведенном выше примере, только конфигурацию будет брать из файла logging.conf:
# test.py import logging import logging.config # читаем конфигурацию из файла logging.config.fileConfig('logging.conf') # создаем регистратор logger = logging.getLogger('logger') # вызов функций, регистрирующих # события в коде logger.debug('debug message') logger.info('info message') logger.warning('warn message') logger.error('error message') logger.critical('critical message')
Листинг файла конфигурации logging.conf
# logging.conf [loggers] keys=root,logger [handlers] keys=FileHandler [formatters] keys=loggerFormatter [logger_root] level=DEBUG handlers=FileHandler [logger_logger] level=DEBUG handlers=FileHandler qualname=logger propagate=0 [handler_FileHandler] class=FileHandler level=DEBUG formatter=loggerFormatter args=('example.log',) [formatter_loggerFormatter] format=[%(asctime)s] [%(name)s] [%(levelname)s] > %(message)s datefmt=%Y-%m-%d %H:%M:%S
Многократные вызовы logging.getLogger('someLogger') возвращают ссылку на один и тот же объект logger. Это верно не только в пределах одного и того же модуля, но и между модулями, если он находится в одном и том же процессе интерпретатора Python. Так же это поведение распространяется для ссылок на один и тот же объект.
Код приложения может определять и настраивать корневой регистратор в одном модуле и создавать, но не настраивать дочерний регистратор в отдельном модуле, и все вызовы регистратора для дочернего объекта будут передаваться родительскому.
Код основного модуля:
# test.py import logging import aux # создаем регистратор с именем 'logger' logger = logging.getLogger('log') logger.setLevel(logging.DEBUG) # создаем файловый обработчик, который # регистрирует отладочные сообщения fh = logging.FileHandler('spam.log') fh.setLevel(logging.DEBUG) # создаем консольный обработчик # с более высоким уровнем журнала ch = logging.StreamHandler() ch.setLevel(logging.ERROR) # создаем форматтер и добавляем его в обработчики fmtstr = '%(asctime)s - %(name)s - %(levelname)s - %(message)s' fmtdate = '%H:%M:%S' formatter = logging.Formatter(fmtstr, fmtdate) fh.setFormatter(formatter) ch.setFormatter(formatter) # добавляем настроенные обработчики в логгер logger.addHandler(fh) logger.addHandler(ch) # вызов функций, регистрирующих # события в коде logger.info('создание объекта Auxiliary') a = auxiliary.Auxiliary() logger.info('объект Auxiliary создан') logger.info('вызов метода .something') a.something() logger.info('вызов .something закончен') logger.info('вызов some_func()') auxiliary.some_func() logger.info('работа с Auxiliary закончена')
Для приложения будет полезно записывать все сообщения всех уровней логирования в текстовый файл, одновременно регистрируя уровень ERROR или выше в консоли. Что бы настроить такое поведение, необходимо определить соответствующий обработчик handler как показано в примере выше. Метод logger.addHandler() не имеет минимальной или максимальной квоты для количества добавляемых обработчиков.
Код импортируемого модуля.
# aux.py import logging # создание регистратора с именем log.aux module = logging.getLogger('log.aux') class Auxiliary: def __init__(self): # создание регистратора с именем log.aux.Auxiliary self.logger = logging.getLogger('log.aux.Auxiliary') self.logger.debug('__Init__ Auxiliary') def something(self): self.logger.debug('start .something') a = 1 + 1 self.logger.debug('end .something') def some_func(): module.debug('call to some_func')
Обратите внимание на имена регистраторов, создаваемых в импортируемом модуле. Имена должны соблюдать иерархию, т. е. в данном случае, в модуле aux.py имя регистратора должно начинаться с имени корневого регистратора 'log.'. Передаваемое имя в logging.getLogger() представляет собой ссылку на объект регистратора и если getLogger() не находит объекта с соответствующим именем, то он считает себя корневым регистратором. Другими словами, если не соблюдать это правило, то соответствующие сообщения не будут записываться в файл или выводится на консоль.
Вывод будет выглядеть так:
08:52:46 - log - INFO - создание объекта Auxiliary 08:52:46 - log.aux.Auxiliary - DEBUG - __Init__ Auxiliary 08:52:46 - log - INFO - объект Auxiliary создан 08:52:46 - log - INFO - вызов метода .something 08:52:46 - log.aux.Auxiliary - DEBUG - start .something 08:52:46 - log.aux.Auxiliary - DEBUG - end .something 08:52:46 - log - INFO - вызов .something закончен 08:52:46 - log - INFO - вызов some_func() 08:52:46 - log.aux - DEBUG - call to some_func 08:52:46 - log - INFO - работа с Auxiliary закончена
Возможность создания новых обработчиков с фильтрами более высокой или более низкой важности может быть очень полезна при написании и тестировании приложения. Вместо использования функций print() для отладки используйте метод logger.debug(): в отличие от операторов print(), которые придется удалить или закомментировать позже, функции logger.debug() могут оставаться нетронутыми в исходном коде и оставаться неактивными, пока они вам не понадобятся снова. Единственное изменение, которое необходимо сделать - это изменить уровень логирования и/или обработчика для отладки.
Ведение журнала из нескольких потоков не требует особых усилий. В следующем примере показано ведение журнала из основного потока mail и потока Thread-1:
import logging import threading import time def worker(arg): while not arg['stop']: logging.debug('Hi from myfunc') time.sleep(0.5) def main(): format='%(relativeCreated)6d %(threadName)s %(message)s' logging.basicConfig(level=logging.DEBUG, format=format) info = {'stop': False} thread = threading.Thread(target=worker, args=(info,)) thread.start() while True: try: logging.debug('Hello from main') time.sleep(0.75) except KeyboardInterrupt: info['stop'] = True break thread.join() if __name__ == '__main__': main()
При запуске скрипт должен напечатать что-то вроде этого:
0 Thread-1 Hi from myfunc 0 MainThread Hello from main 501 Thread-1 Hi from myfunc 751 MainThread Hello from main 1002 Thread-1 Hi from myfunc 1502 MainThread Hello from main 1502 Thread-1 Hi from myfunc 2003 Thread-1 Hi from myfunc 2253 MainThread Hello from main 2504 Thread-1 Hi from myfunc 3004 MainThread Hello from main ... ...
Вывод логов на консоль показывает, что выходные данные журнала перемещаются, как и следовало ожидать. Этот подход работает для бОльшего количества потоков, чем здесь показано.
При записи событий регистратора в файл иногда необходимо, чтобы размер файла журнала не рос бесконечно, а увеличился до определенного размера, после чего открывался новый файл для записи логов. Возможно, еще необходимо будет хранение определенного количество таких файлов, а при достижении этого количества возобновлялась запись в лог-файл, который создался первым. Для такого шаблонного поведения пакет logging предоставляет обработчик с именем logging.handlers.RotatingFileHandler():
import logging, glob import logging.handlers LOG_FILENAME = 'log.out' # создадим регистратор с желаемым уровнем логирования logger = logging.getLogger('log') logger.setLevel(logging.DEBUG) # создадим обработчик с ротацией по объему файла handler = logging.handlers.RotatingFileHandler( LOG_FILENAME, maxBytes=1000, backupCount=5) # создаем форматтер и добавляем его в обработчики fmtstr = '[%(asctime)s] [%(levelname)s] => %(message)s' fmtdate = '%H:%M:%S' formatter = logging.Formatter(fmtstr, fmtdate) # установим формат обработчику handler.setFormatter(formatter) # добавим обработчик сообщений журнала в регистратор logger.addHandler(handler) # Log some messages for i in range(150): # подготовим сообщение msg = f'Итерация № {i}' logger.debug(msg) # смотрим, какие файлы созданы logfiles = glob.glob(f'{LOG_FILENAME}*') for filename in logfiles: print(filename) # log.out.1 # log.out.5 # log.out.2 # log.out.3 # log.out # log.out.4
Если необходима ротация логов не по объему файла, а по времени накопления событий, например 24 часа, то можно использовать обработчик с именем logging.handlers.TimedRotatingFileHandler():