Сообщить об ошибке.

Примеры продвинутого использования модуля logging.

В этом разделе разберем примеры продвинутого использования пакета журналирования событий 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():