Поваренная книга логирования¶

Автор:	Винай Саджип

Данный документ содержит ряд рецептов, связанных с журналированием, которые были признаны полезными.

Использование логирования в нескольких модулях¶

Несколько вызовов logging.getLogger('someLogger') возвращают ссылку на один и тот же объект логгера. Это верно не только для одного модуля, но и для разных модулей, если они находятся в одном процессе интерпретатора Python. Это верно для ссылок на один и тот же объект; кроме того, код приложения может определять и настраивать родительский логгер в одном модуле и создавать (но не настраивать) дочерний логгер в отдельном модуле, и все вызовы логгера дочернему элементу будут передаваться родительскому. Далее пример основного модуля:

import logging
import auxiliary_module

# создать логгер 'spam_application'
logger = logging.getLogger('spam_application')
logger.setLevel(logging.DEBUG)
# создать обработчик файлов, который журналирует даже отладочные сообщения
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# создать обработчик консоли с более высоким уровнем журналирования
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
# создать форматтер и добавить его в обработчики
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)
# добавить обработчики в логгер
logger.addHandler(fh)
logger.addHandler(ch)

logger.info('creating an instance of auxiliary_module.Auxiliary')
a = auxiliary_module.Auxiliary()
logger.info('created an instance of auxiliary_module.Auxiliary')
logger.info('calling auxiliary_module.Auxiliary.do_something')
a.do_something()
logger.info('finished auxiliary_module.Auxiliary.do_something')
logger.info('calling auxiliary_module.some_function()')
auxiliary_module.some_function()
logger.info('done with auxiliary_module.some_function()')

Вспомогательный модуль:

import logging

# создать логгер
module_logger = logging.getLogger('spam_application.auxiliary')

class Auxiliary:
    def __init__(self):
        self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
        self.logger.info('creating an instance of Auxiliary')

    def do_something(self):
        self.logger.info('doing something')
        a = 1 + 1
        self.logger.info('done doing something')

def some_function():
    module_logger.info('received a call to "some_function"')

Результат выглядит так:

2005-03-23 23:47:11,663 - spam_application - INFO -
   creating an instance of auxiliary_module.Auxiliary
2005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -
   creating an instance of Auxiliary
2005-03-23 23:47:11,665 - spam_application - INFO -
   created an instance of auxiliary_module.Auxiliary
2005-03-23 23:47:11,668 - spam_application - INFO -
   calling auxiliary_module.Auxiliary.do_something
2005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -
   doing something
2005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -
   done doing something
2005-03-23 23:47:11,670 - spam_application - INFO -
   finished auxiliary_module.Auxiliary.do_something
2005-03-23 23:47:11,671 - spam_application - INFO -
   calling auxiliary_module.some_function()
2005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -
   received a call to 'some_function'
2005-03-23 23:47:11,673 - spam_application - INFO -
   done with auxiliary_module.some_function()

Логирование из нескольких потоков¶

Логирование из нескольких потоков не требует особых усилий. В следующем примере показано журналирование из основного (начального) потока и другого потока:

import logging
import threading
import time

def worker(arg):
    while not arg['stop']:
        logging.debug('Hi from myfunc')
        time.sleep(0.5)

def main():
    logging.basicConfig(level=logging.DEBUG, format='%(relativeCreated)6d %(threadName)s %(message)s')
    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()

При запуске скрипт должен напечатать что-то вроде следующего:

Thread-1 Hi from myfunc
MainThread Hello from main
Thread-1 Hi from myfunc
MainThread Hello from main
Thread-1 Hi from myfunc
MainThread Hello from main
Thread-1 Hi from myfunc
Thread-1 Hi from myfunc
MainThread Hello from main
Thread-1 Hi from myfunc
MainThread Hello from main
Thread-1 Hi from myfunc
Thread-1 Hi from myfunc
MainThread Hello from main
Thread-1 Hi from myfunc
MainThread Hello from main
Thread-1 Hi from myfunc

Это показывает, как и следовало ожидать, перемежающийся вывод журнала . Конечно, этот подход работает для бОльшего количества потоков, чем здесь показано.

Несколько обработчиков и форматтеров¶

Логеры — простые объекты Python. Метод addHandler() не имеет минимальной или максимальной квоты на количество добавляемых обработчиков. Иногда приложению будет полезно записывать все сообщения всех уровней серьезности в текстовый файл, одновременно записывая ошибки или выше в консоль. Чтобы это настроить, просто настройте соответствующие обработчики. Вызовы журналирования в коде приложения останутся неизменными. Вот небольшая модификация предыдущего простого примера конфигурации на основе модулей:

import logging

logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)
# создать файловый обработчик, который журналирует даже отладочные сообщения
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# создать консольный обработчик с более высоким уровнем журналирования
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
# создать форматтер и добавить его в обработчики
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(formatter)
fh.setFormatter(formatter)
# добавить обработчики в логгер
logger.addHandler(ch)
logger.addHandler(fh)

# код "приложения"
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')

Обратите внимание, что код «приложения» не заботится о нескольких обработчиках. Всё, что изменилось — это добавление и настройка нового обработчика с именем fh.

Возможность создавать новые обработчики с фильтрами более высокого или низкого уровня серьезности может быть очень полезной при написании и тестировании приложения. Вместо использования множества операторов print для отладки используйте logger.debug: в отличие от операторов print, которые вам придется удалить или закомментировать позже, операторы logger.debug могут оставаться нетронутыми в исходном коде и оставаться бездействующими до тех пор, пока они вам снова не понадобятся. В то время единственное изменение, которое должно произойти — это изменить уровень серьезности логгера и/или обработчика для отладки.

Логирование для нескольких назначений¶

Допустим, вы хотите логировать в консоль и файл с разными форматами сообщений и при разных обстоятельствах. Допустим, вы хотите логировать сообщения с уровнями DEBUG и выше в файл, а сообщения с уровнем INFO и выше — в консоль. Предположим также, что файл должен содержать временные метки, а сообщения консоли — нет. Вот как этого добиться:

import logging

# настроить журналирование в файл, см. предыдущий раздел для более подробной информации
logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
                    datefmt='%m-%d %H:%M',
                    filename='/temp/myapp.log',
                    filemode='w')
# определить обработчик, который записывает сообщения INFO или выше в sys.stderr
console = logging.StreamHandler()
console.setLevel(logging.INFO)
# установить формат, который проще для использования консоли
formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
# сказать обработчику использовать этот формат
console.setFormatter(formatter)
# добавить обработчик в корневой логгер
logging.getLogger('').addHandler(console)

# Теперь мы можем логировать в корневой логгер или любой другой логгер. Сначала корневой ...
logging.info('Jackdaws love my big sphinx of quartz.')

# Теперь определим пару других логгеров, которые могут представлять области в вашем
# приложении:

logger1 = logging.getLogger('myapp.area1')
logger2 = logging.getLogger('myapp.area2')

logger1.debug('Quick zephyrs blow, vexing daft Jim.')
logger1.info('How quickly daft jumping zebras vex.')
logger2.warning('Jail zesty vixen who grabbed pay from quack.')
logger2.error('The five boxing wizards jump quickly.')

Когда вы запустите скрипт, в консоли вы увидите:

root        : INFO     Jackdaws love my big sphinx of quartz.
myapp.area1 : INFO     How quickly daft jumping zebras vex.
myapp.area2 : WARNING  Jail zesty vixen who grabbed pay from quack.
myapp.area2 : ERROR    The five boxing wizards jump quickly.

и в файле вы увидите что-то вроде:

10-22 22:19 root         INFO     Jackdaws love my big sphinx of quartz.
10-22 22:19 myapp.area1  DEBUG    Quick zephyrs blow, vexing daft Jim.
10-22 22:19 myapp.area1  INFO     How quickly daft jumping zebras vex.
10-22 22:19 myapp.area2  WARNING  Jail zesty vixen who grabbed pay from quack.
10-22 22:19 myapp.area2  ERROR    The five boxing wizards jump quickly.

Как видите, сообщение DEBUG отображается только в файле. Остальные сообщения отправляются обоим адресатам.

В этом примере используются консоль и файловые обработчики, но вы можете использовать любое количество и любую комбинацию обработчиков по вашему выбору.

Пример сервера конфигурации¶

Далее пример модуля, использующего сервер конфигурации журналирования:

import logging
import logging.config
import time
import os

# прочитать исходный файл конфигурации
logging.config.fileConfig('logging.conf')

# создать и запустить прослушиватель на порту 9999
t = logging.config.listen(9999)
t.start()

logger = logging.getLogger('simpleExample')

try:
    # цикл через протоколирование вызовов, чтобы увидеть разницу
    # создание новой конфигурации до тех пор, пока не будет нажата Ctrl+C
    while True:
        logger.debug('debug message')
        logger.info('info message')
        logger.warning('warn message')
        logger.error('error message')
        logger.critical('critical message')
        time.sleep(5)
except KeyboardInterrupt:
    # очистить
    logging.config.stopListening()
    t.join()

А вот сценарий, который принимает имя файла и отправляет этот файл на сервер, которому должным образом предшествует длина в двоичной кодировке, в качестве новой конфигурации логгирования:

#!/usr/bin/env python
import socket, sys, struct

with open(sys.argv[1], 'rb') as f:
    data_to_send = f.read()

HOST = 'localhost'
PORT = 9999
s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
print('connecting...')
s.connect((HOST, PORT))
print('sending config...')
s.send(struct.pack('>L', len(data_to_send)))
s.send(data_to_send)
s.close()
print('complete')

Работа с блокирующими обработчиками¶

Иногда вам нужно заставить обработчики журналирования выполнять свою работу, не блокируя поток, из которого вы выполняете логирование. Это обычное дело в веб- приложениях, хотя, конечно, также происходит и в других сценариях.

Распространенным виновником, демонстрирующим вялое поведение, является SMTPHandler: отправка электронных писем может занять много времени по ряду причин, не зависящих от разработчика (например, плохая работа почты или сетевой инфраструктуры). Но почти любой сетевой обработчик может блокировать: даже операция SocketHandler может выполнять DNS-запрос под капотом, который слишком медленный (и этот запрос может находиться глубоко в коде библиотеки сокетов, ниже уровня Python и вне вашего контроля).

Одно из решений — использовать двухэтапный подход. Для первой части подключается только QueueHandler к тем логгерам, к которым осуществляется доступ из потоков, критичных к производительности. Они просто записывают в свою очередь, размер которой может быть достаточно большой, или инициализироваться без ограничения их размера сверху. Запись в очередь обычно принимается быстро, хотя вам, вероятно, потребуется перехватить исключение queue.Full в качестве меры предосторожности в вашем коде. Если вы разработчик библиотеки, у которого в коде есть потоки, критичные к производительности, обязательно задокументируйте это (вместе с предложением присоединить к вашим логгерам только QueueHandlers) в интересах других разработчиков, которые будут использовать ваш код.

Вторая часть решения — QueueListener, разработанный как аналог QueueHandler. QueueListener очень прост: он передаёт очередь и некоторые обработчики и запускает внутренний поток, который прослушивает свою очередь на предмет LogRecords, отправленных из QueueHandlers (или любого другого источника LogRecords, если на то пошло). LogRecords удаляются из очереди и передаются обработчикам для обработки.

Преимущество наличия отдельного класса QueueListener заключается в том, что вы можете использовать один и тот же экземпляр для обслуживания нескольких QueueHandlers. Это более дружественно к ресурсам, чем, скажем, наличие потоковых версий существующих классов обработчиков, которые потребляли бы один поток на обработчик без особой выгоды.

Ниже приводится пример использования этих двух классов (импорт пропущен):

que = queue.Queue(-1)  # нет ограничений на размер
queue_handler = QueueHandler(que)
handler = logging.StreamHandler()
listener = QueueListener(que, handler)
root = logging.getLogger()
root.addHandler(queue_handler)
formatter = logging.Formatter('%(threadName)s: %(message)s')
handler.setFormatter(formatter)
listener.start()
# Вывод журнала будет отображать поток, который был сгенерирован
# событие (основной поток), а не внутренний
# поток, который отслеживает внутреннюю очередь.
root.warning('Look out!')
listener.stop()

который при запуске будет производить:

MainThread: Look out!

Изменено в версии 3.5: До Python 3.5 QueueListener всегда передавал каждое сообщение, полученное из очереди, каждому обработчику, которым он был инициализирован. (Это произошло потому, что предполагалось, что фильтрация уровней была полностью выполнена на другой стороне, где очередь заполнена.) Начиная с версии 3.5, это поведение можно изменить, передав ключевой аргумент respect_handler_level=True конструктору слушателя. Когда это будет сделано, слушатель сравнивает уровень каждого сообщения с уровнем обработчика и передаёт сообщение обработчику только в том случае, если это необходимо.

Отправка и получение событий журналирования по сети¶

Допустим, вы хотите отправлять события журналирования по сети и обрабатывать их на принимающей стороне. Простой способ сделать это — присоединить экземпляр SocketHandler к корневому логгеру на отправляющей стороне:

import logging, logging.handlers

rootLogger = logging.getLogger('')
rootLogger.setLevel(logging.DEBUG)
socketHandler = logging.handlers.SocketHandler('localhost',
                    logging.handlers.DEFAULT_TCP_LOGGING_PORT)
# не беспокойтесь о форматере, так как обработчик сокета отправляет событие как
# неформатированный пикл
rootLogger.addHandler(socketHandler)

# Теперь мы можем логировать в корневой логгер или любой другой логгер. Сначала корневой...
logging.info('Jackdaws love my big sphinx of quartz.')

# Теперь определите пару других логгеров, которые могут представлять области в вашем
# приложении:

logger1 = logging.getLogger('myapp.area1')
logger2 = logging.getLogger('myapp.area2')

logger1.debug('Quick zephyrs blow, vexing daft Jim.')
logger1.info('How quickly daft jumping zebras vex.')
logger2.warning('Jail zesty vixen who grabbed pay from quack.')
logger2.error('The five boxing wizards jump quickly.')

На принимающей стороне вы можете настроить приёмник с помощью модуля socketserver. Далее базовый рабочий пример:

import pickle
import logging
import logging.handlers
import socketserver
import struct


class LogRecordStreamHandler(socketserver.StreamRequestHandler):
    """Обработчик для запроса потокового журналирования.

    В основном запись логируется с использованием любой локальной политики
    логирования.
    """

    def handle(self):
        """
        Обработка нескольких запросов, каждый из которых должен иметь длину в 4 байта,
        после чего следует запись LogRecord в формате пикл. Регистрирует запись в
        соответствии с локальной политикой.
        """
        while True:
            chunk = self.connection.recv(4)
            if len(chunk) < 4:
                break
            slen = struct.unpack('>L', chunk)[0]
            chunk = self.connection.recv(slen)
            while len(chunk) < slen:
                chunk = chunk + self.connection.recv(slen - len(chunk))
            obj = self.unPickle(chunk)
            record = logging.makeLogRecord(obj)
            self.handleLogRecord(record)

    def unPickle(self, data):
        return pickle.loads(data)

    def handleLogRecord(self, record):
        # если имя определено, мы используем именованный логгер, а не тот,
        # реализуется записью.
        if self.server.logname is not None:
            name = self.server.logname
        else:
            name = record.name
        logger = logging.getLogger(name)
        # Нотабене. КАЖДАЯ запись записывается в журнал. Это потому что Logger.handle
        # обычно вызывается ПОСЛЕ фильтрацией на уровне журнала. Если нужно
        # выполнить фильтрацию, сделайте это на стороне клиента, чтобы сохранить расходы
        # циклы и пропускной способности сети!
        logger.handle(record)

class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):
    """
    Простой основанный на сокетах приёмник TCP логирования, подходящий для тестирования.
    """

    allow_reuse_address = True

    def __init__(self, host='localhost',
                 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
                 handler=LogRecordStreamHandler):
        socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)
        self.abort = 0
        self.timeout = 1
        self.logname = None

    def serve_until_stopped(self):
        import select
        abort = 0
        while not abort:
            rd, wr, ex = select.select([self.socket.fileno()],
                                       [], [],
                                       self.timeout)
            if rd:
                self.handle_request()
            abort = self.abort

def main():
    logging.basicConfig(
        format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')
    tcpserver = LogRecordSocketReceiver()
    print('About to start TCP server...')
    tcpserver.serve_until_stopped()

if __name__ == '__main__':
    main()

Сначала запустите сервер, а затем клиент. На стороне клиента на консоли ничего не печатается; на стороне сервера вы должны увидеть что-то вроде:

About to start TCP server...
root            INFO     Jackdaws love my big sphinx of quartz.
myapp.area1     DEBUG    Quick zephyrs blow, vexing daft Jim.
myapp.area1     INFO     How quickly daft jumping zebras vex.
myapp.area2     WARNING  Jail zesty vixen who grabbed pay from quack.
myapp.area2     ERROR    The five boxing wizards jump quickly.

Обратите внимание, что в некоторых сценариях есть некоторые проблемы с безопасностью. Если это важно для вас, вы можете использовать альтернативную схему сериализации, переопределив метод makePickle() и реализовав там свою альтернативу, а также адаптируя приведенный выше сценарий для использования альтернативной сериализации.

Добавление контекстной информации к выходным данным журнала¶

Иногда вам нужно, чтобы вывод журнала содержал контекстную информацию в дополнение к параметрам, передаваемым в вызов логгера. Например, в сетевом приложении может быть желательно логировать в журнале информацию о клиенте (например, имя пользователя или IP-адрес удаленного клиента). Хотя для этого можно использовать extra параметр, не всегда удобно передавать информацию таким образом. Хотя может возникнуть соблазн создать экземпляры Logger для каждого соединения, это не лучшая идея, поскольку эти экземпляры не собираются сборщиком мусора. Хотя на практике это не проблема, когда количество экземпляров Logger зависит от уровня детализации, который вы хотите использовать при ведении журнала приложения, может быть трудно управлять, если количество экземпляров Logger станет фактически неограниченным.

Использование LoggerAdapters для передачи контекстной информации¶

Простой способ передать контекстную информацию для вывода вместе с информацией о событиях в журнале — это использовать класс LoggerAdapter. Этот класс выглядит как Logger, поэтому вы можете вызвать debug(), info(), warning(), error(), exception(), critical() и log(). Эти методы содержат те же сигнатуры, что и их аналоги в Logger, поэтому вы можете использовать два типа экземпляров как взаимозаменяемые.

Когда вы создаете экземпляр LoggerAdapter, вы передаёте ему экземпляр Logger и dict-подобный объект, который содержит вашу контекстную информацию. Когда вы вызываете один из методов журналирования в экземпляре LoggerAdapter, он делегирует вызов базовому экземпляру Logger, переданному его конструктору, и организует передачу контекстной информации в делегированном вызове. Вот отрывок из кода LoggerAdapter:

def debug(self, msg, /, *args, **kwargs):
    """
    Делегировать вызов отладки базовому журналу после добавления контекстной
    информации с сущности адаптера.
    """
    msg, kwargs = self.process(msg, kwargs)
    self.logger.debug(msg, *args, **kwargs)

Метод process() для LoggerAdapter — это то место, где контекстная информация добавляется к выходным данным журнала. Он передал аргументы сообщения и ключевые аргументы вызова logging и возвращает (потенциально) модифицированные версии этих аргументов для использования в вызове в базового логгера. Реализация этого метода по умолчанию оставляет сообщение в покое, но вставляет «extra» ключ в ключевом аргументе, значением которого является dict-подобный объект, переданный конструктору. Конечно, если вы передали «extra» ключевой аргумент при вызове адаптера, он будет автоматически перезаписан.

Преимущество использования «extra» состоит в том, что значения в объекте, подобном dict, объединяются в __dict__ экземпляра LogRecord, что позволяет использовать настраиваемые строки с экземплярами Formatter, которые знают о ключах объекта, подобного dict. Если вам нужен другой метод, например если вы хотите добавить или добавить контекстную информацию к строке сообщения, вам просто нужно создать подкласс LoggerAdapter и переопределить process(), чтобы сделать то, что вам нужно. Вот простой пример:

class CustomAdapter(logging.LoggerAdapter):
    """
    В этом примере адаптер ожидает, что переданный объект подобный dict содержит ключ
    "connid", значение которого в скобках добавляется к лог сообщению.
    """
    def process(self, msg, kwargs):
        return '[%s] %s' % (self.extra['connid'], msg), kwargs

который вы можете использовать вот так:

logger = logging.getLogger(__name__)
adapter = CustomAdapter(logger, {'connid': some_conn_id})

Тогда все события, которые вы регистрируете в адаптере, будут иметь значение some_conn_id, добавленное к сообщениям журнала.

Использование объектов, отличных от dicts, для передачи контекстной информации¶

Вам не нужно передавать фактический dict в LoggerAdapter — вы можете передать экземпляр класса, который реализует __getitem__ и __iter__, чтобы он выглядел как dict для логгирования. Это было бы полезно, если вы хотите динамически генерировать значения (тогда как значения в dict будут постоянными).

Использование фильтров для передачи контекстной информации¶

Вы также можете добавить контекстную информацию в вывод журнала, используя определяемый пользователем Filter. Экземплярам Filter разрешено изменять переданный им LogRecords, включая добавление дополнительных атрибутов, которые затем могут выводиться с использованием подходящей строки формата или, если необходимо, пользовательского Formatter.

Например, в веб-приложении обрабатываемый запрос (или, по крайней мере, его интересующие части) можно сохранить в переменной threadlocal (threading.local), а затем получить к нему доступ из Filter, чтобы добавить, скажем, информацию из запроса, например, удаленный IP-адрес и имя пользователя удаленного пользователя на LogRecord, используя имена атрибутов ip и user, как в примере LoggerAdapter выше. В этом случае можно использовать ту же строку формата для получения вывода, аналогичного показанному выше. Пример сценария:

import logging
from random import choice

class ContextFilter(logging.Filter):
    """
    Фильтр, который вводит контекстную информацию в журнал.

    Вместо того, чтобы использовать фактическую контекстуальную информацию, мы
    просто используем случайные данные в этой демонстрации.
    """

    USERS = ['jim', 'fred', 'sheila']
    IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']

    def filter(self, record):

        record.ip = choice(ContextFilter.IPS)
        record.user = choice(ContextFilter.USERS)
        return True

if __name__ == '__main__':
    levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)
    logging.basicConfig(level=logging.DEBUG,
                        format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')
    a1 = logging.getLogger('a.b.c')
    a2 = logging.getLogger('d.e.f')

    f = ContextFilter()
    a1.addFilter(f)
    a2.addFilter(f)
    a1.debug('A debug message')
    a1.info('An info message with %s', 'some parameters')
    for x in range(10):
        lvl = choice(levels)
        lvlname = logging.getLevelName(lvl)
        a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')

который при запуске производит что-то вроде:

2010-09-06 22:38:15,292 a.b.c DEBUG    IP: 123.231.231.123 User: fred     A debug message
2010-09-06 22:38:15,300 a.b.c INFO     IP: 192.168.0.1     User: sheila   An info message with some parameters
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters
2010-09-06 22:38:15,300 d.e.f ERROR    IP: 127.0.0.1       User: jim      A message at ERROR level with 2 parameters
2010-09-06 22:38:15,300 d.e.f DEBUG    IP: 127.0.0.1       User: sheila   A message at DEBUG level with 2 parameters
2010-09-06 22:38:15,300 d.e.f ERROR    IP: 123.231.231.123 User: fred     A message at ERROR level with 2 parameters
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1     User: jim      A message at CRITICAL level with 2 parameters
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters
2010-09-06 22:38:15,300 d.e.f DEBUG    IP: 192.168.0.1     User: jim      A message at DEBUG level with 2 parameters
2010-09-06 22:38:15,301 d.e.f ERROR    IP: 127.0.0.1       User: sheila   A message at ERROR level with 2 parameters
2010-09-06 22:38:15,301 d.e.f DEBUG    IP: 123.231.231.123 User: fred     A message at DEBUG level with 2 parameters
2010-09-06 22:38:15,301 d.e.f INFO     IP: 123.231.231.123 User: fred     A message at INFO level with 2 parameters

Запись в один файл из нескольких процессов¶

Хотя журналирование является потокобезопасным и поддерживается Логирование в один файл из нескольких потоков в одном процессе, журналирование в один файл из нескольких процессов не поддерживается, поскольку нет стандартного способа сериализации доступа к одному файлу из нескольких процессов в Python. Если вам нужно логировать в один файл из нескольких процессов, один из способов сделать это — сделать так, чтобы все процессы логировали в SocketHandler и имели отдельный процесс, который реализует сервер сокетов, который читает из сокета и записывает в файл. (Если вы предпочитаете, вы можете выделить один поток в одном из существующих процессов для выполнения этой функции.) Секция документирует этот подход более подробно и включает рабочий приёмник сокетов, который можно использовать в качестве отправной точки для адаптации к собственному усмотрению приложений.

Вы также можете написать свой собственный обработчик, который использует класс Lock из модуля multiprocessing для сериализации доступа к файлу из ваших процессов. Существующие FileHandler и подклассы не используют multiprocessing в настоящее время, хотя они могут использовать это в будущем. Обратите внимание, что в настоящее время модуль multiprocessing не обеспечивает функциональность рабочей блокировки на всех платформах (см. описание ошибки).

В качестве альтернативы вы можете использовать Queue и QueueHandler для отправки всех событий логировании в один из процессов в многопроцессорном приложении. В следующем примере сценария показано, как это можно сделать; в этом примере отдельный процесс прослушивателя прослушивает события, отправленные другими процессами, и регистрирует их в соответствии со своей собственной конфигурацией логирования. Хотя пример демонстрирует только один способ сделать это (например, вы можете использовать поток слушателя, а не отдельный процесс слушателя — реализация будет аналогичной), он позволяет использовать совершенно разные конфигурации логирования для слушателя и других процессов в вашем приложении и могут быть использованы в качестве основы для кода, отвечающего вашим собственным требованиям:

# Импорт потребуется в собственном коде
import logging
import logging.handlers
import multiprocessing

# Следующие две строки импорта только для этой демонстрации
from random import choice, random
import time

#
# Поскольку требуется определить конфигурации логирование для прослушивателя и
# работников, функции прослушивателя и рабочего процесса принимают параметр
# конфигуратора, который является вызываемым для настройки логирование для этого
# процесса. Эти функции также передаются в очередь, которую они используют для
# связи.
#
# На практике вы можете настроить листенер, как хотите, но обратите
# внимание, что в этом простом примере листенер не применяет уровень или
# логику фильтрации к полученным записям. На практике, вероятно, потребуется
# использовать эту логику в рабочих процессах, чтобы избежать отправки событий,
# которые будут отфильтрованы между процессами.
#
# Размер повернутых файлов становится небольшим, что позволяет легко видеть
# результаты.
def listener_configurer():
    root = logging.getLogger()
    h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)
    f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')
    h.setFormatter(f)
    root.addHandler(h)

# Цикл верхнего уровня процесса прослушивателя: дождаться событий логирования
# (LogRecords) в очереди и обработать их. Выйти, когда получено None для
# LogRecord.
def listener_process(queue, configurer):
    configurer()
    while True:
        try:
            record = queue.get()
            if record is None:  # Мы посылаем это как страж, чтобы сказать слушателю, чтобы он вышел.
                break
            logger = logging.getLogger(record.name)
            logger.handle(record)  # Не применена логика уровня или фильтра - просто сделайте это!
        except Exception:
            import sys, traceback
            print('Whoops! Problem:', file=sys.stderr)
            traceback.print_exc(file=sys.stderr)

# Массивы используются для случайного выбора в этой демонстрации

LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,
          logging.ERROR, logging.CRITICAL]

LOGGERS = ['a.b.c', 'd.e.f']

MESSAGES = [
    'Random message #1',
    'Random message #2',
    'Random message #3',
]

# Настройка рабочего выполняется в начале запуска рабочего процесса. Обратите
# внимание, что на Windows вы не можете полагаться на семантику fork, таким
# образом, каждый процесс будет управлять кодом настройки логирования, когда он
# стартует.
def worker_configurer(queue):
    h = logging.handlers.QueueHandler(queue)  # Нужен только один обработчик
    root = logging.getLogger()
    root.addHandler(h)
    # отправить все сообщения, для демонстрации; другой уровень или логика фильтра не
    # применяются.
    root.setLevel(logging.DEBUG)

# Цикл верхнего уровня рабочего процесса, который просто регистрирует десять
# событий со случайными промежуточными задержками перед завершением. Печатные
# сообщения просто, чтобы вы знали, что он что-то делает!
def worker_process(queue, configurer):
    configurer(queue)
    name = multiprocessing.current_process().name
    print('Worker started: %s' % name)
    for i in range(10):
        time.sleep(random())
        logger = logging.getLogger(choice(LOGGERS))
        level = choice(LEVELS)
        message = choice(MESSAGES)
        logger.log(level, message)
    print('Worker finished: %s' % name)

# Вот где организуется демонстрация. Создаётся очередь, создаётся и запускается
# прослушиватель. Порождается десять работников и их запуск, далее ожидание,
# пока они закончат, а затем отправляется в очередь сообщение None для указания слушателю
# завершить работу.
def main():
    queue = multiprocessing.Queue(-1)
    listener = multiprocessing.Process(target=listener_process,
                                       args=(queue, listener_configurer))
    listener.start()
    workers = []
    for i in range(10):
        worker = multiprocessing.Process(target=worker_process,
                                         args=(queue, worker_configurer))
        workers.append(worker)
        worker.start()
    for w in workers:
        w.join()
    queue.put_nowait(None)
    listener.join()

if __name__ == '__main__':
    main()

Вариант приведенного выше сценария сохраняет журналирование в основном процессе в отдельном потоке:

import logging
import logging.config
import logging.handlers
from multiprocessing import Process, Queue
import random
import threading
import time

def logger_thread(q):
    while True:
        record = q.get()
        if record is None:
            break
        logger = logging.getLogger(record.name)
        logger.handle(record)


def worker_process(q):
    qh = logging.handlers.QueueHandler(q)
    root = logging.getLogger()
    root.setLevel(logging.DEBUG)
    root.addHandler(qh)
    levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
              logging.CRITICAL]
    loggers = ['foo', 'foo.bar', 'foo.bar.baz',
               'spam', 'spam.ham', 'spam.ham.eggs']
    for i in range(100):
        lvl = random.choice(levels)
        logger = logging.getLogger(random.choice(loggers))
        logger.log(lvl, 'Message no. %d', i)

if __name__ == '__main__':
    q = Queue()
    d = {
        'version': 1,
        'formatters': {
            'detailed': {
                'class': 'logging.Formatter',
                'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
            }
        },
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler',
                'level': 'INFO',
            },
            'file': {
                'class': 'logging.FileHandler',
                'filename': 'mplog.log',
                'mode': 'w',
                'formatter': 'detailed',
            },
            'foofile': {
                'class': 'logging.FileHandler',
                'filename': 'mplog-foo.log',
                'mode': 'w',
                'formatter': 'detailed',
            },
            'errors': {
                'class': 'logging.FileHandler',
                'filename': 'mplog-errors.log',
                'mode': 'w',
                'level': 'ERROR',
                'formatter': 'detailed',
            },
        },
        'loggers': {
            'foo': {
                'handlers': ['foofile']
            }
        },
        'root': {
            'level': 'DEBUG',
            'handlers': ['console', 'file', 'errors']
        },
    }
    workers = []
    for i in range(5):
        wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))
        workers.append(wp)
        wp.start()
    logging.config.dictConfig(d)
    lp = threading.Thread(target=logger_thread, args=(q,))
    lp.start()
    # В этот момент основной процесс мог бы сделать какую-то собственную полезную
    # работу, как только он будет сделан, он может ждать, когда воркеры завершатся...
    for wp in workers:
        wp.join()
    # И теперь сказать также завершиться логированию в потоке
    q.put(None)
    lp.join()

Этот вариант показывает, как применить конфигурацию для определенных логгеров — например, у логгера foo есть специальный обработчик, который хранит все события подсистемы foo в файле mplog-foo.log. Будет использоваться механизмом логирования в основном процессе (даже если журналируемые события генерируются в рабочих процессах) для направления сообщений в соответствующие места назначения.

Использование concurrent.futures.ProcessPoolExecutor¶

Если вы хотите использовать concurrent.futures.ProcessPoolExecutor для запуска ваших рабочих процессов, вам нужно создать очередь несколько иначе. Вместо

queue = multiprocessing.Queue(-1)

вы должны использовать

queue = multiprocessing.Manager().Queue(-1)  # также работает с приведенными выше примерами

и затем вы можете заменить создание рабочего из него:

workers = []
for i in range(10):
    worker = multiprocessing.Process(target=worker_process,
                                     args=(queue, worker_configurer))
    workers.append(worker)
    worker.start()
for w in workers:
    w.join()

к этому (не забудьте сначала импортировать concurrent.futures):

with concurrent.futures.ProcessPoolExecutor(max_workers=10) as executor:
    for i in range(10):
        executor.submit(worker_process, queue, worker_configurer)

Использование ротации файлов¶

Иногда вам нужно, чтобы файл журнала увеличился до определенного размера, затем открыть новый файл и журналировать в него. Возможно, вы захотите сохранить определенное количество этих файлов, и когда такое количество файлов будет создано, ротировать файлы так, чтобы количество файлов и размер файлов оставались фиксированными. Для этого шаблона использования пакет logging предоставляет RotatingFileHandler:

import glob
import logging
import logging.handlers

LOG_FILENAME = 'logging_rotatingfile_example.out'

# Настройка логгера с требуемым уровнем вывода
my_logger = logging.getLogger('MyLogger')
my_logger.setLevel(logging.DEBUG)

# Добавить обработчик сообщений в журнал
handler = logging.handlers.RotatingFileHandler(
              LOG_FILENAME, maxBytes=20, backupCount=5)

my_logger.addHandler(handler)

# Залогировать некоторые сообщения
for i in range(20):
    my_logger.debug('i = %d' % i)

# Посмотреть, какие файлы созданы
logfiles = glob.glob('%s*' % LOG_FILENAME)

for filename in logfiles:
    print(filename)

В результате должно получиться 6 отдельных файлов, каждый с частью истории журнала для приложения:

logging_rotatingfile_example.out
logging_rotatingfile_example.out.1
logging_rotatingfile_example.out.2
logging_rotatingfile_example.out.3
logging_rotatingfile_example.out.4
logging_rotatingfile_example.out.5

Самый последний файл всегда logging_rotatingfile_example.out, и каждый раз, когда он достигает предельного размера, он переименовывается с суффиксом .1. Каждый из существующих файлов резервных копий переименовывается для увеличения суффикса (.1 становится .2 и т. д.), а файл .6 удаляется.

Очевидно, что в этом примере длина журнала слишком мала. Вам скорее всего нужно установить maxBytes в соответствующее значение.

Использование альтернативных стилей форматирования¶

Когда журналирование было добавлено в стандартную библиотеку Python, единственным способом форматирования сообщений с переменным содержанием было использование метода %-форматирования. С тех пор Python получил два новых подхода к форматированию: string.Template (добавлено в Python 2.4) и str.format() (добавлено в Python 2.6).

Логирование (начиная с версии 3.2) обеспечивает улучшенную поддержку двух дополнительных стилей форматирования. Класс Formatter был расширен и теперь принимает дополнительный необязательный ключевой параметр с именем style. По умолчанию это '%', но другие возможные значения — '{' и '$', которые соответствуют двум другим стилям форматирования. Обратная совместимость поддерживается по умолчанию (как и следовало ожидать), но, явно указав параметр стиля, вы получаете возможность указать строки формата, которые работают с str.format() или string.Template. Вот пример консольного сеанса, чтобы показать возможности:

>>> import logging
>>> root = logging.getLogger()
>>> root.setLevel(logging.DEBUG)
>>> handler = logging.StreamHandler()
>>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}',
...                        style='{')
>>> handler.setFormatter(bf)
>>> root.addHandler(handler)
>>> logger = logging.getLogger('foo.bar')
>>> logger.debug('This is a DEBUG message')
2010-10-28 15:11:55,341 foo.bar DEBUG    This is a DEBUG message
>>> logger.critical('This is a CRITICAL message')
2010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message
>>> df = logging.Formatter('$asctime $name ${levelname} $message',
...                        style='$')
>>> handler.setFormatter(df)
>>> logger.debug('This is a DEBUG message')
2010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message
>>> logger.critical('This is a CRITICAL message')
2010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message
>>>

Обратите внимание, что форматирование сообщений журнала для окончательного вывода в журналы полностью не зависит от того, как построено отдельное сообщение журнала. Всё ещё можно использовать %-форматирование, как показано здесь:

>>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')
2010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message
>>>

Вызовы журналирования (logger.debug(), logger.info() и т. д.) принимают только позиционные параметры для самого фактического сообщения журнала, с ключевыми параметрами, используемыми только для определения вариантов того, как обрабатывать фактический вызов журнала (например, ключевой параметр exc_info, чтобы указать, что должна логироваться информация трассировки или ключевой параметр extra, чтобы указать дополнительную контекстную информацию, которая должна быть добавлена в журнал). Таким образом, вы не можете напрямую выполнять вызовы журналирования с использованием синтаксиса str.format() или string.Template, потому что внутри пакета logging используется %-форматирование для объединения строки формата и переменных аргументов. Это не изменится при сохранении обратной совместимости, поскольку все вызовы журналирования, которые присутствуют в существующем коде, будут использовать строки %-формата.

Однако есть способ, которым вы можете использовать форматирование {}- и $- для создания ваших индивидуальных сообщений журнала. Напомним, что для сообщения вы можете использовать произвольный объект в качестве строки формата сообщения, и что пакет logger вызовет str() для этого объекта, чтобы получить фактическую форматную строку. Рассмотрим следующие два класса:

class BraceMessage:
    def __init__(self, fmt, /, *args, **kwargs):
        self.fmt = fmt
        self.args = args
        self.kwargs = kwargs

    def __str__(self):
        return self.fmt.format(*self.args, **self.kwargs)

class DollarMessage:
    def __init__(self, fmt, /, **kwargs):
        self.fmt = fmt
        self.kwargs = kwargs

    def __str__(self):
        from string import Template
        return Template(self.fmt).substitute(**self.kwargs)

Любой из них может использоваться вместо строки формата, чтобы разрешить использование {}- или $ -форматирования для создания фактической части «сообщения», которая появляется в форматированных выводах журнала вместо «% (message)s» или «{message}» или «$message». Немного громоздко использовать имена классов всякий раз, когда вы хотите что-то логировать, но вполне приемлемо, если вы используете псевдоним, такой как __ (двойное подчеркивание, — не путать с _, одинарное подчеркивание, используемое как синоним/псевдоним для gettext.gettext() или его собратья).

Вышеупомянутые классы не включены в Python, хотя их достаточно легко скопировать и вставить в свой собственный код. Их можно использовать следующим образом (при условии, что они объявлены в модуле wherever):

>>> from wherever import BraceMessage as __
>>> print(__('Message with {0} {name}', 2, name='placeholders'))
Message with 2 placeholders
>>> class Point: pass
...
>>> p = Point()
>>> p.x = 0.5
>>> p.y = 0.5
>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})',
...       point=p))
Message with coordinates: (0.50, 0.50)
>>> from wherever import DollarMessage as __
>>> print(__('Message with $num $what', num=2, what='placeholders'))
Message with 2 placeholders
>>>

Хотя в приведенных выше примерах используется print(), чтобы показать, как работает форматирование, вы, конечно, можете использовать logger.debug() или аналогичный для фактического логирования с использованием этого подхода.

Следует отметить, что при таком подходе вы не платите значительным снижением производительности: фактическое форматирование происходит не тогда, когда вы выполняете вызов логгера, а когда (и если) зарегистрированное сообщение фактически собирается быть выведено в журнал обработчиком. Итак, единственная немного необычная вещь, которая может вас сбить с толку — это то, что круглые скобки охватывают строку формата и аргументы, а не только строку формата. Это потому, что обозначение __ — это просто синтаксический сахар для вызова конструктора одного из классов XXXMessage.

При желании можно использовать LoggerAdapter для достижения эффекта, аналогичного описанному выше, как в следующем примере:

import logging

class Message:
    def __init__(self, fmt, args):
        self.fmt = fmt
        self.args = args

    def __str__(self):
        return self.fmt.format(*self.args)

class StyleAdapter(logging.LoggerAdapter):
    def __init__(self, logger, extra=None):
        super(StyleAdapter, self).__init__(logger, extra or {})

    def log(self, level, msg, /, *args, **kwargs):
        if self.isEnabledFor(level):
            msg, kwargs = self.process(msg, kwargs)
            self.logger._log(level, Message(msg, args), (), **kwargs)

logger = StyleAdapter(logging.getLogger(__name__))

def main():
    logger.debug('Hello, {}', 'world!')

if __name__ == '__main__':
    logging.basicConfig(level=logging.DEBUG)
    main()

Приведенный выше сценарий должен записывать сообщение Hello, world! при запуске с Python 3.2 или новее.

Настройка `LogRecord`¶

Каждое логируемое событие представлено экземпляром LogRecord. Когда событие логируется и не отфильтровывается на уровне логгера, создаётся LogRecord, заполняется информацией о событии и затем передаётся обработчикам этого логгера (и его предков, вплоть до логгера включительно, где дальнейшее распространение вверх иерархия отключена). До Python 3.2 было только два места, где это производилось:

Logger.makeRecord(), который вызывается в обычном процессе логировании события. Это вызвало LogRecord непосредственно для создания экземпляра.
makeLogRecord(), который вызывается со словарём, содержащим атрибуты, которые нужно добавить в LogRecord. Обычно вызывается, когда подходящий словарь был получен по сети (например, в пикл форме через SocketHandler или в JSON форме через HTTPHandler).

Обычно это означало, что если вам нужно сделать что-то особенное с LogRecord, вы должны были сделать одно из следующих действий:

Создать свой подкласс Logger, который переопределяет Logger.makeRecord(), и установить его с помощью setLoggerClass() перед тем, как будут созданы экземпляры любых логгеров.
Добавить Filter к логгеру или обработчику, который выполняет необходимые специальные манипуляции, необходимые вам при вызове его метода filter().

Первый подход будет немного громоздким в сценарии, когда (скажем) несколько разных библиотек хотят делать разные вещи. Каждый попытается установить свой собственный подкласс Logger, и тот, который сделал это последним, тот выиграет.

Второй подход работает достаточно хорошо во многих случаях, но не позволяет, например, используйте специализированный подкласс LogRecord. Разработчики библиотек могут установить подходящий фильтр для своих логгеров, но им придётся помнить об этом каждый раз, когда они добавляют новый логгер (что они делали бы просто путём добавления новых пакетов или модулей и выполнения:

logger = logging.getLogger(__name__)

на уровне модуля). Вероятно, это слишком много забот, о которых нужно думать. Разработчики также могут добавить фильтр к NullHandler, прикрепленному к их логгеру верхнего уровня, но он не будет вызываться, если разработчик приложения прикрепит обработчик к логгеру библиотеки нижнего уровня, поэтому вывод этого обработчика не будет отражать намерения разработчика библиотеки.

В Python 3.2 и более поздних версиях создание LogRecord выполняется с помощью фабрики, которую вы можете указать. Фабрика — это просто вызов, который можно установить с помощью setLogRecordFactory(), а запросить с помощью getLogRecordFactory(). Фабрика вызывается с той же сигнатурой, что и конструктор LogRecord, поскольку LogRecord является настройкой по умолчанию для фабрики.

Такой подход позволяет настраиваемой фабрике контролировать все аспекты создания LogRecord. Например, вы можете вернуть подкласс или просто добавить некоторые дополнительные атрибуты к однажды созданной записи, используя шаблон, подобный этому:

old_factory = logging.getLogRecordFactory()

def record_factory(*args, **kwargs):
    record = old_factory(*args, **kwargs)
    record.custom_attribute = 0xdecafbad
    return record

logging.setLogRecordFactory(record_factory)

Этот шаблон позволяет различным библиотекам связывать фабрики вместе, и пока они не перепишут атрибуты друг друга или непреднамеренно перезапишут атрибуты, предоставленные в стандартной комплектации, сюрпризов быть не должно. Однако следует иметь в виду, что каждое звено в цепочке увеличивает накладные расходы времени выполнения для всех операций логирования, и этот метод следует использовать только тогда, когда использование Filter не даёт желаемого результата.

Создание подкласса QueueHandler — пример ZeroMQ¶

Вы можете использовать подкласс QueueHandler для отправки сообщений в другие типы очередей, например, в сокет «публикации» ZeroMQ. В приведённом ниже примере сокет создаётся отдельно и передаётся обработчику (как его «очередь»):

import zmq   # используя pyzmq, Python биндинг для ZeroMQ
import json  # для портабельной сериализации записей

ctx = zmq.Context()
sock = zmq.Socket(ctx, zmq.PUB)  # или zmq.PUSH, или другое подходящее значение
sock.bind('tcp://*:5556')        # или везде, где

class ZeroMQSocketHandler(QueueHandler):
    def enqueue(self, record):
        self.queue.send_json(record.__dict__)


handler = ZeroMQSocketHandler(sock)

Конечно, есть и другие способы организовать это, например, передать данные, необходимые обработчику для создания сокета:

class ZeroMQSocketHandler(QueueHandler):
    def __init__(self, uri, socktype=zmq.PUB, ctx=None):
        self.ctx = ctx or zmq.Context()
        socket = zmq.Socket(self.ctx, socktype)
        socket.bind(uri)
        super().__init__(socket)

    def enqueue(self, record):
        self.queue.send_json(record.__dict__)

    def close(self):
        self.queue.close()

Создание подкласса QueueListener — пример ZeroMQ¶

Вы также можете создать подкласс QueueListener для получения сообщений из других типов очередей, например из сокета «подписки» ZeroMQ. Пример:

class ZeroMQSocketListener(QueueListener):
    def __init__(self, uri, /, *handlers, **kwargs):
        self.ctx = kwargs.get('ctx') or zmq.Context()
        socket = zmq.Socket(self.ctx, zmq.SUB)
        socket.setsockopt_string(zmq.SUBSCRIBE, '')  # подписаться на всё
        socket.connect(uri)
        super().__init__(socket, *handlers, **kwargs)

    def dequeue(self):
        msg = self.queue.recv_json()
        return logging.makeLogRecord(msg)

См.также

Модуль logging: Справочник по API для модуля logging.
Модуль logging.config: API конфигурации для модуля logging.
Модуль logging.handlers: Полезные обработчики, включенные в модуль logging.

Базовое руководство по логированию

Более продвинутый учебник по логированию

Пример конфигурации на основе словаря¶

Ниже приведен пример словаря конфигурации журналирования — он взят из документация по проекту Django. Этот словарь передаётся в dictConfig(), чтобы конфигурация вступила в силу:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'verbose': {
            'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'
        },
        'simple': {
            'format': '%(levelname)s %(message)s'
        },
    },
    'filters': {
        'special': {
            '()': 'project.logging.SpecialFilter',
            'foo': 'bar',
        }
    },
    'handlers': {
        'null': {
            'level':'DEBUG',
            'class':'django.utils.log.NullHandler',
        },
        'console':{
            'level':'DEBUG',
            'class':'logging.StreamHandler',
            'formatter': 'simple'
        },
        'mail_admins': {
            'level': 'ERROR',
            'class': 'django.utils.log.AdminEmailHandler',
            'filters': ['special']
        }
    },
    'loggers': {
        'django': {
            'handlers':['null'],
            'propagate': True,
            'level':'INFO',
        },
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': False,
        },
        'myproject.custom': {
            'handlers': ['console', 'mail_admins'],
            'level': 'INFO',
            'filters': ['special']
        }
    }
}

Дополнительную информацию об этой конфигурации можно найти в соответствующем разделе документации Django.

Использование ротатора и именователя для настройки обработки ротации журналов¶

Пример того, как вы можете определить именователь и ротатор, приведён в следующем фрагменте, который показывает сжатие файла журнала на основе zlib:

def namer(name):
    return name + ".gz"

def rotator(source, dest):
    with open(source, "rb") as sf:
        data = sf.read()
        compressed = zlib.compress(data, 9)
        with open(dest, "wb") as df:
            df.write(compressed)
    os.remove(source)

rh = logging.handlers.RotatingFileHandler(...)
rh.rotator = rotator
rh.namer = namer

Это не «настоящие» файлы .gz, поскольку они представляют собой чистые сжатые данные без «контейнера», который вы можете найти в настоящем gzip файле. Этот фрагмент предназначен только для иллюстрации.

Более сложный пример многопроцессорной обработки¶

В следующем рабочем примере показано, как можно использовать журналирование с многопроцессорной обработкой с использованием файлов конфигурации. Конфигурации довольно просты, но служат для иллюстрации того, как более сложные могут быть реализованы в реальном сценарии многопроцессорной обработки.

В этом примере основной процесс порождает процесс слушателя и некоторые рабочие процессы. Каждый из основного процесса, слушателя и рабочих содержит три отдельные конфигурации (все рабочие имеют одну и ту же конфигурацию). Мы можем видеть журналирование в основном процессе, то, как рабочие логируются в QueueHandler, и как прослушиватель реализует QueueListener и более сложную конфигурацию логирования, а также организует отправку событий, полученных обработчикам через очередь, указанным в конфигурации. Обратите внимание, что эти конфигурации являются чисто иллюстративными, но вы сможете адаптировать этот пример к своему собственному сценарию.

Далее пример сценария (строки документации и комментарии, надеюсь, объяснят, как он работает):

import logging
import logging.config
import logging.handlers
from multiprocessing import Process, Queue, Event, current_process
import os
import random
import time

class MyHandler:
    """
    Простой обработчик событий логирования. Он запускается в процессе прослушивания
    и отправляет события на логгеры на основе имени в полученной записи, которые
    затем отправляются логирование системой обработчикам, настроенным для этих
    логгеров.
    """

    def handle(self, record):
        if record.name == "root":
            logger = logging.getLogger()
        else:
            logger = logging.getLogger(record.name)

        if logger.isEnabledFor(record.levelno):
            # Имя процесса преобразуется только для того, чтобы показать, что прослушиватель
            # выполняет логирование к файлам и консоли
            record.processName = '%s (for %s)' % (current_process().name, record.processName)
            logger.handle(record)

def listener_process(q, stop_event, config):
    """
    Это может быть сделано в основном процессе, но только что сделано в отдельном
    процессе для иллюстративных целей.

    Инициализирует логирование в соответствии с заданной конфигурацией, запускает
    прослушиватель и ожидает, когда основной процесс сигнализирует о завершении
    через событие. Прослушиватель затем останавливается, и процесс завершается.
    """
    logging.config.dictConfig(config)
    listener = logging.handlers.QueueListener(q, MyHandler())
    listener.start()
    if os.name == 'posix':
        # В POSIX настройка логера будет сконфигурирована в родительском процессе, но должна
        # быть отключена после вызова dictConfig. В Windows, поскольку fork не
        # используется, настройка логера не существует в дочернем элементе, поэтому
        # она будет создана, и появится сообщение --- отсюда и предложение «if posix».
        logger = logging.getLogger('setup')
        logger.critical('Should not appear, because of disabled logger ...')
    stop_event.wait()
    listener.stop()

def worker_process(config):
    """
    Некоторые из них рождаются с целью иллюстрации. На практике они могут быть
    разнородной группой процессов, а не идентичными друг другу.

    Пример инициализирует логирование в соответствии с заданной конфигурацией и
    регистрирует сто сообщений со случайными уровнями для случайного выбора логгеров.

    Добавляется небольшой сон, чтобы другие процессы могли работать. Это не является
    строго необходимым, но смешивает выходные данные различных процессов немного
    больше, чем если бы они остались в стороне.
    """
    logging.config.dictConfig(config)
    levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
              logging.CRITICAL]
    loggers = ['foo', 'foo.bar', 'foo.bar.baz',
               'spam', 'spam.ham', 'spam.ham.eggs']
    if os.name == 'posix':
        # В POSIX настройка логера будет сконфигурирована в родительском процессе, но должна
        # быть отключена после вызова dictConfig. В Windows, поскольку fork не
        # используется, настройка логера не существует в дочернем элементе, поэтому
        # она будет создана, и появится сообщение --- отсюда и предложение «if posix».
        logger = logging.getLogger('setup')
        logger.critical('Should not appear, because of disabled logger ...')
    for i in range(100):
        lvl = random.choice(levels)
        logger = logging.getLogger(random.choice(loggers))
        logger.log(lvl, 'Message no. %d', i)
        time.sleep(0.01)

def main():
    q = Queue()
    # Основной процесс получает простую конфигурацию, которая распечатается в консоли.
    config_initial = {
        'version': 1,
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler',
                'level': 'INFO'
            }
        },
        'root': {
            'handlers': ['console'],
            'level': 'DEBUG'
        }
    }
    # Конфигурация рабочего процесса --- это просто QueueHandler, подключенный к
    # корневому логгеру, который позволяет отправлять все сообщения в очередь.
    # Мы отключаем существующие регистраторы, чтобы отключить регистратор
    # «настройки», используемый в родительском процессе. Это необходимо в POSIX,
    # потому что логгер будет в дочернем элементе после fork().
    config_worker = {
        'version': 1,
        'disable_existing_loggers': True,
        'handlers': {
            'queue': {
                'class': 'logging.handlers.QueueHandler',
                'queue': q
            }
        },
        'root': {
            'handlers': ['queue'],
            'level': 'DEBUG'
        }
    }
    # Конфигурация процесса прослушивателя показывает, что доступна полная гибкость
    # конфигурации логирования для отправки событий обработчикам, как вы хотите.
    # Мы отключаем существующие регистраторы, чтобы отключить регистратор
    # «настройки», используемый в родительском процессе. Это необходимо в POSIX,
    # потому что логгер будет в дочернем элементе после fork().
    config_listener = {
        'version': 1,
        'disable_existing_loggers': True,
        'formatters': {
            'detailed': {
                'class': 'logging.Formatter',
                'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
            },
            'simple': {
                'class': 'logging.Formatter',
                'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
            }
        },
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler',
                'formatter': 'simple',
                'level': 'INFO'
            },
            'file': {
                'class': 'logging.FileHandler',
                'filename': 'mplog.log',
                'mode': 'w',
                'formatter': 'detailed'
            },
            'foofile': {
                'class': 'logging.FileHandler',
                'filename': 'mplog-foo.log',
                'mode': 'w',
                'formatter': 'detailed'
            },
            'errors': {
                'class': 'logging.FileHandler',
                'filename': 'mplog-errors.log',
                'mode': 'w',
                'formatter': 'detailed',
                'level': 'ERROR'
            }
        },
        'loggers': {
            'foo': {
                'handlers': ['foofile']
            }
        },
        'root': {
            'handlers': ['console', 'file', 'errors'],
            'level': 'DEBUG'
        }
    }
    # Записать некоторые начальные события, чтобы показать, что логирование в
    # родительской системе работает нормально.
    logging.config.dictConfig(config_initial)
    logger = logging.getLogger('setup')
    logger.info('About to create workers ...')
    workers = []
    for i in range(5):
        wp = Process(target=worker_process, name='worker %d' % (i + 1),
                     args=(config_worker,))
        workers.append(wp)
        wp.start()
        logger.info('Started worker: %s', wp.name)
    logger.info('About to create listener ...')
    stop_event = Event()
    lp = Process(target=listener_process, name='listener',
                 args=(q, stop_event, config_listener))
    lp.start()
    logger.info('Started listener')
    # Теперь ожидаем, пока воркеры закончат свою работу.
    for wp in workers:
        wp.join()
    # Воркеры всё сделали, слушая теперь могут остановиться. Логирование в
    # родительском элементе по-прежнему работает нормально.
    logger.info('Telling listener to stop ...')
    stop_event.set()
    lp.join()
    logger.info('All done.')

if __name__ == '__main__':
    main()

Вставка BOM в сообщения, отправленные в SysLogHandler¶

RFC 5424 требует, чтобы Юникод сообщение отправлялось демону системного журнала в виде набора байтов, которые имеют следующую структуру: необязательный компонент чистого ASCII, за которым следует метка порядка байтов (BOM) UTF-8, за которой следует Юникод, закодированный с использованием UTF-8. (См. соответствующий раздел спецификации.)

В Python 3.1 был добавлен код в SysLogHandler для вставки спецификации в сообщение, но, к сожалению, он был реализован неправильно: спецификация появлялась в начале сообщения и, следовательно, не позволяла любому компоненту чистого ASCII появляться перед ним.

Поскольку это деструктивное поведение, неправильный код BOM вставки удаляется из Python 3.2.4 и более поздних версий. Однако он не заменяется, и если вы хотите создавать сообщения, совместимые с RFC 5424, которые включают BOM, необязательную последовательность чистого ASCII перед ней и произвольный Юникод после неё, закодированные с использованием UTF-8. Тогда вам необходимо сделать следующее :

Присоединить экземпляр Formatter к вашему экземпляру SysLogHandler со строкой формата, например:
```
'ASCII section\ufeffUnicode section'
```
Кодовая точка Юникод U+FEFF при кодировании с использованием UTF-8 будет закодирована как спецификация UTF-8 — байтовая строка b'\xef\xbb\xbf'.
Заменить раздел ASCII любыми заполнителями, которые вам нравятся, но убедитесь, что данные, которые появляются там после замены, всегда являются ASCII (таким образом, они останутся неизменными после кодировки UTF-8).
Заменить раздел Юникод любыми заполнителями, которые вам нравятся; если данные, которые появляются там после замены, содержат символы вне диапазона ASCII, это нормально — они будут закодированы с использованием UTF-8.

Отформатированное сообщение будет закодировано с использованием кодировки UTF-8 SysLogHandler. Если вы будете следовать приведенным выше правилам, вы сможете создавать сообщения, совместимые с RFC 5424. Если вы этого не сделаете, журналирование может промолчать, но ваши сообщения не будут соответствовать RFC 5424, и ваш демон syslog может возмутиться.

Реализация структурированного журналирования¶

Хотя большинство сообщений журнала предназначены для чтения людьми и, следовательно, не поддаются машинному синтаксическому анализу, могут возникнуть обстоятельства, когда вы захотите вывести сообщения в структурированном формате, который может быть проанализирован программой (без необходимости использования сложных регулярных выражений для синтаксического анализа сообщения журнала). Этого легко добиться с помощью пакета logging. Есть несколько способов, которыми это может быть достигнуто, но ниже приводится простой подход, который использует JSON для сериализации события с возможностью машинного анализа:

import json
import logging

class StructuredMessage:
    def __init__(self, message, /, **kwargs):
        self.message = message
        self.kwargs = kwargs

    def __str__(self):
        return '%s >>> %s' % (self.message, json.dumps(self.kwargs))

_ = StructuredMessage   # необязательно, чтобы улучшить читаемость

logging.basicConfig(level=logging.INFO, format='%(message)s')
logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))

Если приведенный выше сценарий запустить, он распечатает:

message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}

Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.

Если вам нужна более специализированная обработка, вы можете использовать собственный кодировщик JSON, как в следующем подробном примере:

from __future__ import unicode_literals

import json
import logging

# Следующий бит должен гарантировать, что скрипт работает без изменений на 2.x и 3.x
try:
    unicode
except NameError:
    unicode = str

class Encoder(json.JSONEncoder):
    def default(self, o):
        if isinstance(o, set):
            return tuple(o)
        elif isinstance(o, unicode):
            return o.encode('unicode_escape').decode('ascii')
        return super(Encoder, self).default(o)

class StructuredMessage:
    def __init__(self, message, /, **kwargs):
        self.message = message
        self.kwargs = kwargs

    def __str__(self):
        s = Encoder().encode(self.kwargs)
        return '%s >>> %s' % (self.message, s)

_ = StructuredMessage   # необязательно, чтобы улучшить читаемость

def main():
    logging.basicConfig(level=logging.INFO, format='%(message)s')
    logging.info(_('message 1', set_value={1, 2, 3}, snowman='\u2603'))

if __name__ == '__main__':
    main()

Когда приведённый выше сценарий запускается, он напечатает:

message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}

Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.

Настройка обработчиков с помощью `dictConfig()`¶

Бывают случаи, когда вы хотите настроить обработчики журналов определённым образом, и если вы используете dictConfig(), вы можете сделать это без создания подклассов. В качестве примера рассмотрим, вариант установки владельца файла журнала. В POSIX это легко сделать с помощью shutil.chown(), но обработчики файлов в stdlib не предлагают встроенной поддержки. Вы можете настроить создание обработчика, используя простую функцию, например:

def owned_file_handler(filename, mode='a', encoding=None, owner=None):
    if owner:
        if not os.path.exists(filename):
            open(filename, 'a').close()
        shutil.chown(filename, *owner)
    return logging.FileHandler(filename, mode, encoding)

Затем вы можете указать в конфигурации логирования, переданной в dictConfig(), чтобы обработчик логирования создавался путём вызова этой функции:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'default': {
            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
        },
    },
    'handlers': {
        'file':{
            # Приведенные ниже значения выводятся из этого словаря и используемый для создания
            # обработчика, установки уровня обработчика и его формататора.
            '()': owned_file_handler,
            'level':'DEBUG',
            'formatter': 'default',
            # Приведенные ниже значения передаются создателю обработчика, вызываемому в
            # качестве ключевых аргументов.
            'owner': ['pulse', 'pulse'],
            'filename': 'chowntest.log',
            'mode': 'w',
            'encoding': 'utf-8',
        },
    },
    'root': {
        'handlers': ['file'],
        'level': 'DEBUG',
    },
}

В этом примере я устанавливаю владельца, используя пользователя и группу pulse, просто в целях иллюстрации. Собираем всё в рабочий скрипт chowntest.py:

import logging, logging.config, os, shutil

def owned_file_handler(filename, mode='a', encoding=None, owner=None):
    if owner:
        if not os.path.exists(filename):
            open(filename, 'a').close()
        shutil.chown(filename, *owner)
    return logging.FileHandler(filename, mode, encoding)

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'default': {
            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
        },
    },
    'handlers': {
        'file':{
            # Приведенные ниже значения выводятся из этого словаря и используемый для создания
            # обработчика, установки уровня обработчика и его формататора.
            '()': owned_file_handler,
            'level':'DEBUG',
            'formatter': 'default',
            # Приведенные ниже значения передаются создателю обработчика, вызываемому в
            # качестве ключевых аргументов.
            'owner': ['pulse', 'pulse'],
            'filename': 'chowntest.log',
            'mode': 'w',
            'encoding': 'utf-8',
        },
    },
    'root': {
        'handlers': ['file'],
        'level': 'DEBUG',
    },
}

logging.config.dictConfig(LOGGING)
logger = logging.getLogger('mylogger')
logger.debug('A debug message')

Чтобы запустить его, вам, вероятно, нужно будет запустить от пользователя root:

$ sudo python3.3 chowntest.py
$ cat chowntest.log
2013-11-05 09:34:51,128 DEBUG mylogger A debug message
$ ls -l chowntest.log
-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log

Обратите внимание, что в этом примере используется Python 3.3, потому что именно там появляется shutil.chown(). Этот подход должен работать с любой версией Python, поддерживающей dictConfig(), а именно с Python 2.7, 3.2 или новее. В версиях до 3.3 вам нужно будет реализовать фактическую смену владельца, например, os.chown().

На практике функция создания обработчика может находиться в служебном модуле где-то в вашем проекте. Вместо строчки в конфигурации:

'()': owned_file_handler,

вы можете использовать, например:

'()': 'ext://project.util.owned_file_handler',

где project.util можно заменить фактическим именем пакета, в котором находится функция. В приведенном выше рабочем сценарии должно работать использование 'ext://__main__.owned_file_handler'. Здесь фактический вызываемый объект разрешается dictConfig() из спецификации ext://.

Мы надеемся, что этот пример также указывает путь к тому, как вы могли бы реализовать другие типы изменения файлов, например, установка определенных битов разрешений POSIX , используя os.chmod().

Конечно, этот подход также можно распространить на другие типы обработчиков, кроме FileHandler, например, на один из ротатор обработчиков файлов или на другой тип обработчика.

Использование определенных стилей форматирования во всём приложении¶

В Python 3.2 Formatter получил ключевой параметр style, который, хотя по умолчанию был % для обратной совместимости, позволил спецификации { или $ поддерживать подходы к форматированию, поддерживаемые str.format() и string.Template. Обратите внимание, что это регулирует форматирование сообщений журнала для окончательного вывода в журналы и полностью ортогонально тому, как создаётся отдельное сообщение журнала.

Вызовы логирования (debug(), info() и т. д.) принимают только позиционные параметры для самого фактического сообщения логировании, с ключевыми параметрами, используемыми только для определения опций для того, как обрабатывать вызов логировании (например, ключевой параметр exc_info, чтобы указать, что нужно логировать информацию трассировки, или ключевой параметр extra для указания дополнительной контекстной информации, которая должна быть добавлена в журнал). Таким образом, вы не можете напрямую выполнять вызовы журналирования с использованием синтаксиса str.format() или string.Template, потому что внутри пакета журналирования используется %-форматирование для объединения строки формата и переменных аргументов. Это не изменится при сохранении обратной совместимости, поскольку все вызовы журналирования, которые присутствуют в существующем коде, будут использовать %-формат строки.

Были предложения связать стили формата с определенными логгерами, но этот подход также сталкивается с проблемами обратной совместимости, поскольку любой существующий код может использовать заданное имя логгера и использовать %-форматирование.

Чтобы журналирование работало совместно между любыми сторонними библиотеками и вашим кодом, решения о форматировании должны приниматься на уровне отдельного вызова журнала. Это открывает несколько способов использования альтернативных стилей форматирования.

Использование фабрик LogRecord¶

В Python 3.2, наряду с упомянутыми выше изменениями Formatter, пакет logging получил возможность разрешать пользователям устанавливать свои собственные подклассы LogRecord, используя функцию setLogRecordFactory(). Вы можете использовать это, чтобы установить свой собственный подкласс LogRecord, который делает всё правильно, переопределяя метод getMessage(). Реализация этого метода в базовом классе — это то место, где происходит форматирование msg % args, и где вы можете заменить своё альтернативное форматирование; однако следует соблюдать осторожность, чтобы поддерживать все стили форматирования и разрешить %-форматирование по умолчанию, чтобы обеспечить совместимость с другим кодом. Также следует позаботиться о вызове str(self.msg), как и в базовой реализации.

Обратитесь к справочной документации setLogRecordFactory() и LogRecord для получения дополнительной информации.

Использование настраиваемых объектов сообщений¶

Есть ещё один, возможно, более простой способ использования форматирования {}- и $- для создания индивидуальных сообщений журнала. Вы можете вспомнить (из Использование произвольных объектов в качестве сообщений), что при логировании можно использовать произвольный объект в качестве строки формата сообщения, и что пакет logging вызовет str() для этого объекта, чтобы получить фактическую форматную строку. Рассмотрим следующие два класса:

class BraceMessage:
    def __init__(self, fmt, /, *args, **kwargs):
        self.fmt = fmt
        self.args = args
        self.kwargs = kwargs

    def __str__(self):
        return self.fmt.format(*self.args, **self.kwargs)

class DollarMessage:
    def __init__(self, fmt, /, **kwargs):
        self.fmt = fmt
        self.kwargs = kwargs

    def __str__(self):
        from string import Template
        return Template(self.fmt).substitute(**self.kwargs)

Любой из них может использоваться вместо форматной строки, чтобы разрешить использование {}- или $- форматирования для построения фактической части «сообщения», которая появляется в форматированных выводах журнала вместо «% (message)s» или «{сообщение}» или «$ сообщение». Если вам кажется немного громоздко использовать имена классов всякий раз, когда вы хотите что-то логировать, вы можете сделать его более приемлемым, если вы используете псевдоним, такой как M или _ для сообщения (или, возможно, __, если вы используете _ для локализации. ).

Примеры такого подхода приведены ниже. В первом форматирование с str.format():

>>> __ = BraceMessage
>>> print(__('Message with {0} {1}', 2, 'placeholders'))
Message with 2 placeholders
>>> class Point: pass
...
>>> p = Point()
>>> p.x = 0.5
>>> p.y = 0.5
>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))
Message with coordinates: (0.50, 0.50)

Во-втором, форматирование с помощью string.Template:

>>> __ = DollarMessage
>>> print(__('Message with $num $what', num=2, what='placeholders'))
Message with 2 placeholders
>>>

Следует отметить, что при таком подходе вы не платите значительным снижением производительности: фактическое форматирование происходит не тогда, когда вы выполняете вызов логгера, а когда (и если) логируемое сообщение фактически собирается быть выведено в журнал обработчиком. Итак, единственная немного необычная вещь, которая может вас сбить с толку — это то, что круглые скобки охватывают форматную строку и аргументы, а не только строку формата. Это потому, что нотация __ — это просто синтаксический сахар для вызова конструктора одного из классов XXXMessage, показанных выше.

Настройка фильтров с помощью `dictConfig()`¶

Вы можете настроить фильтры с помощью dictConfig(), хотя на первый взгляд может быть неочевидно, как это сделать (отсюда и этот рецепт). Поскольку Filter — единственный класс фильтра, включенный в стандартную библиотеку, и маловероятно, что он удовлетворяет многим требованиям (он присутствует только в качестве базового класса), вам обычно потребуется определить собственный подкласс Filter с переопределенным методом filter(). Для этого укажите ключ () в словаре конфигурации для фильтра, указав вызываемый объект, который будет использоваться для создания фильтра (наиболее очевидным является класс, но вы можете предоставить любой вызываемый объект, который возвращает экземпляр Filter). Полный пример:

import logging
import logging.config
import sys

class MyFilter(logging.Filter):
    def __init__(self, param=None):
        self.param = param

    def filter(self, record):
        if self.param is None:
            allow = True
        else:
            allow = self.param not in record.msg
        if allow:
            record.msg = 'changed: ' + record.msg
        return allow

LOGGING = {
    'version': 1,
    'filters': {
        'myfilter': {
            '()': MyFilter,
            'param': 'noshow',
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'filters': ['myfilter']
        }
    },
    'root': {
        'level': 'DEBUG',
        'handlers': ['console']
    },
}

if __name__ == '__main__':
    logging.config.dictConfig(LOGGING)
    logging.debug('hello')
    logging.debug('hello - noshow')

В этом примере показано, как передать данные конфигурации вызываемому объекту, который создает экземпляр, в форме ключевых параметров. При запуске будет напечатан приведенный выше сценарий:

changed: hello

что показывает, что фильтр работает, как настроено.

Следует отметить пару дополнительных моментов:

Если вы не можете ссылаться на вызываемый объект непосредственно в конфигурации (например, если он находится в другом модуле, и вы не можете импортировать его напрямую, где находится словарь конфигурации), вы можете использовать форму ext://..., как описано в Доступ к внешним объектам. Например, вы могли использовать текст 'ext://__main__.MyFilter' вместо MyFilter в приведённом выше примере.
Как и в случае с фильтрами, этот метод также можно использовать для настройки пользовательских обработчиков и средств форматирования. См. Пользовательские объекты для получения дополнительной информации о том, как logging поддерживает использование определенных пользователем объектов в своей конфигурации, и см. другой рецепт Настройка обработчиков с помощью dictConfig() из поваренной книги выше.

Настраиваемое форматирование исключений¶

Могут быть случаи, когда вы хотите выполнить настраиваемое форматирование исключения — в качестве аргумента допустим, что вам нужна ровно одна строка для каждого зарегистрированного события, даже если присутствует информация об исключении. Вы можете сделать это с помощью специального класса средства форматирования, как показано в следующем примере:

import logging

class OneLineExceptionFormatter(logging.Formatter):
    def formatException(self, exc_info):
        """
        Отформатировать исключение, чтобы оно печаталось на одной строке.
        """
        result = super(OneLineExceptionFormatter, self).formatException(exc_info)
        return repr(result)  # или форматировать в одну строку

    def format(self, record):
        s = super(OneLineExceptionFormatter, self).format(record)
        if record.exc_text:
            s = s.replace('\n', '') + '|'
        return s

def configure_logging():
    fh = logging.FileHandler('output.txt', 'w')
    f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',
                                  '%d/%m/%Y %H:%M:%S')
    fh.setFormatter(f)
    root = logging.getLogger()
    root.setLevel(logging.DEBUG)
    root.addHandler(fh)

def main():
    configure_logging()
    logging.info('Sample message')
    try:
        x = 1 / 0
    except ZeroDivisionError as e:
        logging.exception('ZeroDivisionError: %s', e)

if __name__ == '__main__':
    main()

При запуске получается файл ровно с двумя строками:

28/01/2015 07:21:23|INFO|Sample message|
28/01/2015 07:21:23|ERROR|ZeroDivisionError: integer division or modulo by zero|'Traceback (most recent call last):\n  File "logtest7.py", line 30, in main\n    x = 1 / 0\nZeroDivisionError: integer division or modulo by zero'|

Хотя приведённая выше процедура является упрощенной, она указывает способ форматирования информации об исключении по своему усмотрению. Модуль traceback может быть полезен для более специализированных нужд.

Озвучивание журналируемых сообщений¶

Могут возникнуть ситуации, когда желательно, чтобы сообщения журнала воспроизводились в звуковом, а не в видимом формате. Это легко сделать, если в вашей системе доступна функция преобразования текста в речь (TTS), даже если у неё нет привязки к Python. В большинстве систем TTS есть программа командной строки, которую вы можете запустить, и её можно вызвать из обработчика с помощью subprocess. Здесь предполагается, что программы командной строки TTS не будут ожидать взаимодействия с пользователями или для выполнения которых потребуется много времени, и что частота регистрируемых сообщений не будет настолько высокой, чтобы загружать пользователя сообщениями, и что допустимы сообщения, передаваемые по одному, а не одновременно. В приведенном ниже примере реализации ожидается, что одно сообщение будет озвучено, прежде чем будет обработано следующее, и это может привести к тому, что другие обработчики будут продолжать ждать. Вот краткий пример, показывающий подход, который предполагает, что установлен пакет espeak TTS:

import logging
import subprocess
import sys

class TTSHandler(logging.Handler):
    def emit(self, record):
        msg = self.format(record)
        # Говорить медленно женским английским голосом
        cmd = ['espeak', '-s150', '-ven+f3', msg]
        p = subprocess.Popen(cmd, stdout=subprocess.PIPE,
                             stderr=subprocess.STDOUT)
        # дождаться окончания программы
        p.communicate()

def configure_logging():
    h = TTSHandler()
    root = logging.getLogger()
    root.addHandler(h)
    # средство форматирования по умолчанию просто возвращает сообщение
    root.setLevel(logging.DEBUG)

def main():
    logging.info('Hello')
    logging.debug('Goodbye')

if __name__ == '__main__':
    configure_logging()
    sys.exit(main())

При запуске этот скрипт должен сказать «Hello», а затем «Goodbye» женским голосом.

Вышеупомянутый подход, конечно, может быть адаптирован к другим системам TTS и даже к другим системам в целом, которые могут обрабатывать сообщения с помощью внешних программ, запускаемых из командной строки.

Буферизация сообщений журнала и их условный вывод¶

Могут возникнуть ситуации, когда вы хотите логировать сообщения во временной области и выводить их только при возникновении определенных условий. Например, вы можете захотеть начать логировать отладочные события в функции, и если функция завершится без ошибок, вы не хотите загромождать журнал собранной отладочной информацией, но если есть ошибка, вам нужна вся отладочная выводимая информация, а также ошибка.

Вот пример, который показывает, как вы можете сделать это с помощью декоратора для ваших функций, где вам нужно, чтобы журналирование велось таким образом. Он использует logging.handlers.MemoryHandler, который позволяет буферизовать зарегистрированные события до тех пор, пока не произойдёт какое- либо условие, после чего буферизованные события будут flushed — переданы другому обработчику (обработчику target) для обработки. По умолчанию MemoryHandler сбрасывается при заполнении его буфера или при появлении события, уровень которого больше или равен заданному порогу. Вы можете использовать этот рецепт с более специализированным подклассом MemoryHandler, если хотите настраиваемое поведение очистки.

В примере сценария есть простая функция foo, которая просто циклически проходит все уровни логирования, записывая в sys.stderr, чтобы указать, на каком уровне он собирается логировать, а затем фактически регистрирует сообщение на этом уровне. Вы можете передать параметр foo, который, если он истинен, будет логироваться на уровнях ERROR и CRITICAL — в противном случае он будет логироваться только на уровнях DEBUG, INFO и WARNING.

Сценарий просто украсит foo декоратором, который выполнит необходимое условное логирование. Декоратор принимает логгер в качестве параметра и присоединяет обработчик памяти на время вызова декорированной функции. Декоратор может быть дополнительно параметризован с помощью целевого обработчика уровня, на котором должна происходить очистка, и ёмкости буфера (количества буферизованных записей). По умолчанию это StreamHandler, который записывает в sys.stderr, logging.ERROR и 100 соответственно.

Сценарий:

import logging
from logging.handlers import MemoryHandler
import sys

logger = logging.getLogger(__name__)
logger.addHandler(logging.NullHandler())

def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):
    if target_handler is None:
        target_handler = logging.StreamHandler()
    if flush_level is None:
        flush_level = logging.ERROR
    if capacity is None:
        capacity = 100
    handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)

    def decorator(fn):
        def wrapper(*args, **kwargs):
            logger.addHandler(handler)
            try:
                return fn(*args, **kwargs)
            except Exception:
                logger.exception('call failed')
                raise
            finally:
                super(MemoryHandler, handler).flush()
                logger.removeHandler(handler)
        return wrapper

    return decorator

def write_line(s):
    sys.stderr.write('%s\n' % s)

def foo(fail=False):
    write_line('about to log at DEBUG ...')
    logger.debug('Actually logged at DEBUG')
    write_line('about to log at INFO ...')
    logger.info('Actually logged at INFO')
    write_line('about to log at WARNING ...')
    logger.warning('Actually logged at WARNING')
    if fail:
        write_line('about to log at ERROR ...')
        logger.error('Actually logged at ERROR')
        write_line('about to log at CRITICAL ...')
        logger.critical('Actually logged at CRITICAL')
    return fail

decorated_foo = log_if_errors(logger)(foo)

if __name__ == '__main__':
    logger.setLevel(logging.DEBUG)
    write_line('Calling undecorated foo with False')
    assert not foo(False)
    write_line('Calling undecorated foo with True')
    assert foo(True)
    write_line('Calling decorated foo with False')
    assert not decorated_foo(False)
    write_line('Calling decorated foo with True')
    assert decorated_foo(True)

При запуске этого сценария должен наблюдаться следующий результат:

Calling undecorated foo with False
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
Calling undecorated foo with True
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
about to log at ERROR ...
about to log at CRITICAL ...
Calling decorated foo with False
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
Calling decorated foo with True
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
about to log at ERROR ...
Actually logged at DEBUG
Actually logged at INFO
Actually logged at WARNING
Actually logged at ERROR
about to log at CRITICAL ...
Actually logged at CRITICAL

Как видите, фактический вывод журнала происходит только тогда, когда логируется событие с серьезностью ERROR или выше, но в этом случае также логируются любые предыдущие события с более низким уровнем серьезности.

Вы, конечно, можете использовать обычные средства декорирования:

@log_if_errors(logger)
def foo(fail=False):
    ...

Форматирование времени с использованием UTC (GMT) через конфигурацию¶

Иногда ван нужно отформатировать время используя UTC, что можно сделать с помощью такого класса, как UTCFormatter, показанного ниже:

import logging
import time

class UTCFormatter(logging.Formatter):
    converter = time.gmtime

и затем вы можете использовать UTCFormatter в своём коде вместо Formatter. Если вы хотите сделать это через конфигурацию, вы можете использовать API dictConfig() с подходом, проиллюстрированным следующим подробным примером:

import logging
import logging.config
import time

class UTCFormatter(logging.Formatter):
    converter = time.gmtime

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'utc': {
            '()': UTCFormatter,
            'format': '%(asctime)s %(message)s',
        },
        'local': {
            'format': '%(asctime)s %(message)s',
        }
    },
    'handlers': {
        'console1': {
            'class': 'logging.StreamHandler',
            'formatter': 'utc',
        },
        'console2': {
            'class': 'logging.StreamHandler',
            'formatter': 'local',
        },
    },
    'root': {
        'handlers': ['console1', 'console2'],
   }
}

if __name__ == '__main__':
    logging.config.dictConfig(LOGGING)
    logging.warning('The local time is %s', time.asctime())

Если скрипт запустить, он должен напечатать что-то вроде:

2015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 2015
2015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 2015

показывает, как время форматируется как по местному времени, так и по всемирному координированному времени, по одному для каждого обработчика.

Использование диспетчера контекста для выборочного логирования¶

Бывают случаи, когда было бы полезно временно изменить конфигурацию ведения журнала и вернуть её обратно после выполнения каких-либо действий. Для этого наиболее очевидным способом сохранения и восстановления контекста ведения журнала является менеджер (диспетчер) контекста. Вот простой пример такого менеджера контекста, который позволяет при желании изменить уровень логирования и добавить обработчик логирования исключительно в рамках менеджер контекста:

import logging
import sys

class LoggingContext:
    def __init__(self, logger, level=None, handler=None, close=True):
        self.logger = logger
        self.level = level
        self.handler = handler
        self.close = close

    def __enter__(self):
        if self.level is not None:
            self.old_level = self.logger.level
            self.logger.setLevel(self.level)
        if self.handler:
            self.logger.addHandler(self.handler)

    def __exit__(self, et, ev, tb):
        if self.level is not None:
            self.logger.setLevel(self.old_level)
        if self.handler:
            self.logger.removeHandler(self.handler)
        if self.handler and self.close:
            self.handler.close()
        # неявный возвращает None => не проглатывать исключения

Если вы укажете значение уровня, уровень логгера будет установлен на это значение в области действия блока with, охватываемого менеджером контекста. Если вы указываете обработчик, он добавляется в логгер при входе в блок и удаляется при выходе из блока. Вы также можете попросить менеджера закрыть обработчик для вас при выходе из блока — вы можете сделать это, если вам больше не нужен обработчик.

Чтобы проиллюстрировать, как это работает, мы можем добавить к приведенному выше следующий блок кода:

if __name__ == '__main__':
    logger = logging.getLogger('foo')
    logger.addHandler(logging.StreamHandler())
    logger.setLevel(logging.INFO)
    logger.info('1. This should appear just once on stderr.')
    logger.debug('2. This should not appear.')
    with LoggingContext(logger, level=logging.DEBUG):
        logger.debug('3. This should appear once on stderr.')
    logger.debug('4. This should not appear.')
    h = logging.StreamHandler(sys.stdout)
    with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):
        logger.debug('5. This should appear twice - once on stderr and once on stdout.')
    logger.info('6. This should appear just once on stderr.')
    logger.debug('7. This should not appear.')

Изначально мы устанавливаем уровень логгера в INFO, поэтому появляется сообщение №1, а сообщение №2 — нет. Затем мы временно меняем уровень на DEBUG в следующем блоке with, и поэтому появляется сообщение №3. После выхода из блока уровень логгера восстанавливается до INFO, и поэтому сообщение №4 не появляется. В следующем блоке with мы снова устанавливаем уровень на DEBUG, но также добавляем обработчик записи в sys.stdout. Таким образом, сообщение №5 появляется на консоли дважды (один раз через stderr и один раз через stdout). После завершения оператора with статус остается прежним, поэтому появляется сообщение №6 (например, сообщение №1), тогда как сообщение №7 — нет (как и сообщение №2).

Если запустить получившийся скрипт, результат будет следующим:

$ python logctx.py
This should appear just once on stderr.
This should appear once on stderr.
This should appear twice - once on stderr and once on stdout.
This should appear twice - once on stderr and once on stdout.
This should appear just once on stderr.

Если мы запустим его снова, но перенаправим stderr в /dev/null, мы увидим следующее, единственное сообщение, написанное в stdout:

$ python logctx.py 2>/dev/null
5. This should appear twice - once on stderr and once on stdout.

Ещё раз, подключив stdout к /dev/null, мы получим:

$ python logctx.py >/dev/null
This should appear just once on stderr.
This should appear once on stderr.
This should appear twice - once on stderr and once on stdout.
This should appear just once on stderr.

В этом случае сообщение № 5, напечатанное на stdout, не появляется, как ожидалось.

Конечно, рассмотренный здесь подход может быть обобщён, например, для временного присоединения фильтров журналирования. Обратите внимание, что приведенный выше код работает как в Python 2, так и в Python 3.

Стартовый шаблон CLI приложения¶

Далее пример, разъясняющий, как можно сделать:

Использовать уровень логирования на основе аргументов командной строки
Отправка нескольким подкомандам в отдельные файлы, все журналы ведутся на одном уровне и единообразно
Используйте простую минимальную конфигурацию

Предположим, у нас есть приложение командной строки, задача которого останавливать, запускать или перезапускать некоторые службы. Это может быть организовано в целях иллюстрации в виде файла app.py, который является основным сценарием для приложения, с отдельными командами, реализованными в start.py, stop.py и restart.py. Предположим далее, что мы хотим контролировать подробность приложения с помощью аргумента командной строки, по умолчанию logging.INFO. Вот один из реализаций app.py:

import argparse
import importlib
import logging
import os
import sys

def main(args=None):
    scriptname = os.path.basename(__file__)
    parser = argparse.ArgumentParser(scriptname)
    levels = ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')
    parser.add_argument('--log-level', default='INFO', choices=levels)
    subparsers = parser.add_subparsers(dest='command',
                                       help='Available commands:')
    start_cmd = subparsers.add_parser('start', help='Start a service')
    start_cmd.add_argument('name', metavar='NAME',
                           help='Name of service to start')
    stop_cmd = subparsers.add_parser('stop',
                                     help='Stop one or more services')
    stop_cmd.add_argument('names', metavar='NAME', nargs='+',
                          help='Name of service to stop')
    restart_cmd = subparsers.add_parser('restart',
                                        help='Restart one or more services')
    restart_cmd.add_argument('names', metavar='NAME', nargs='+',
                             help='Name of service to restart')
    options = parser.parse_args()
    # команды кода в dispatch могут находиться в этом файле. Только для иллюстрации мы
    # реализуем каждую команду в отдельном модуле.
    try:
        mod = importlib.import_module(options.command)
        cmd = getattr(mod, 'command')
    except (ImportError, AttributeError):
        print('Unable to find the code for command \'%s\'' % options.command)
        return 1
    # Здесь можно получить вид и загрузить конфигурацию из файла или словаря
    logging.basicConfig(level=options.log_level,
                        format='%(levelname)s %(name)s %(message)s')
    cmd(options)

if __name__ == '__main__':
    sys.exit(main())

А команды start, stop и restart могут быть реализованы в отдельных модулях, например, для запуска:

# start.py
import logging

logger = logging.getLogger(__name__)

def command(options):
    logger.debug('About to start %s', options.name)
    # на самом деле выполнить обработку команды здесь ...
    logger.info('Started the \'%s\' service.', options.name)

и, следовательно, для остановки:

# stop.py
import logging

logger = logging.getLogger(__name__)

def command(options):
    n = len(options.names)
    if n == 1:
        plural = ''
        services = '\'%s\'' % options.names[0]
    else:
        plural = 's'
        services = ', '.join('\'%s\'' % name for name in options.names)
        i = services.rfind(', ')
        services = services[:i] + ' and ' + services[i + 2:]
    logger.debug('About to stop %s', services)
    # на самом деле выполнение обработки команд производится здесь ...
    logger.info('Stopped the %s service%s.', services, plural)

и аналогично для перезапуска:

# restart.py
import logging

logger = logging.getLogger(__name__)

def command(options):
    n = len(options.names)
    if n == 1:
        plural = ''
        services = '\'%s\'' % options.names[0]
    else:
        plural = 's'
        services = ', '.join('\'%s\'' % name for name in options.names)
        i = services.rfind(', ')
        services = services[:i] + ' and ' + services[i + 2:]
    logger.debug('About to restart %s', services)
    # на самом деле выполнение обработки команд производится здесь ...
    logger.info('Restarted the %s service%s.', services, plural)

Если мы запустим это приложение с уровнем журнала по умолчанию, мы получим такой вывод:

$ python app.py start foo
INFO start Started the 'foo' service.

$ python app.py stop foo bar
INFO stop Stopped the 'foo' and 'bar' services.

$ python app.py restart foo bar baz
INFO restart Restarted the 'foo', 'bar' and 'baz' services.

Первое слово — это уровень логирования, а второе слово — это имя модуля или пакета места, где было зарегистрировано событие.

Если мы изменим уровень логирования, то мы сможем изменить информацию, отправляемую в журнал. Например, если нам нужна дополнительная информация:

$ python app.py --log-level DEBUG start foo
DEBUG start About to start foo
INFO start Started the 'foo' service.

$ python app.py --log-level DEBUG stop foo bar
DEBUG stop About to stop 'foo' and 'bar'
INFO stop Stopped the 'foo' and 'bar' services.

$ python app.py --log-level DEBUG restart foo bar baz
DEBUG restart About to restart 'foo', 'bar' and 'baz'
INFO restart Restarted the 'foo', 'bar' and 'baz' services.

И если мы хотим меньше:

$ python app.py --log-level WARNING start foo
$ python app.py --log-level WARNING stop foo bar
$ python app.py --log-level WARNING restart foo bar baz

В этом случае команды ничего не выводят на консоль, поскольку они ничего не логгируют на уровне WARNING или выше.

Графический интерфейс Qt для логирования¶

Время от времени появляется вопрос о том, как логировать в приложении с графическим интерфейсом пользователя. Фреймворк Qt — это популярный кроссплатформенный фреймворк пользовательского интерфейса с привязками Python с использованием библиотек PySide2 или PyQt5.

В следующем примере показано, как логировать в Qt GUI. Он вводит простой класс QtHandler, который принимает вызываемый объект, который должен быть слотом в основном потоке, выполняющий обновления графического интерфейса. Рабочий поток также создаётся, чтобы показать, как вы можете войти в графический интерфейс как из самого пользовательского интерфейса (с помощью кнопки для ручного логирования), так и из рабочего потока, выполняющего работу в фоновом режиме (здесь просто логируются сообщения на случайных уровнях со случайным короткие задержки между ними).

Рабочий поток реализован с использованием класса Qt QThread, а не модуля threading, поскольку в некоторых случаях необходимо использовать QThread, который предлагает лучшую интеграцию с другими компонентами Qt.

Код должен работать с последними выпусками PySide2 или PyQt5. Вы должны уметь адаптировать подход к более ранним версиям Qt. Пожалуйста, обратитесь к комментариям во фрагменте кода для получения более подробной информации.

import datetime
import logging
import random
import sys
import time

# Разобраться с незначительными различиями между PySide2 и PyQt5
try:
    from PySide2 import QtCore, QtGui, QtWidgets
    Signal = QtCore.Signal
    Slot = QtCore.Slot
except ImportError:
    from PyQt5 import QtCore, QtGui, QtWidgets
    Signal = QtCore.pyqtSignal
    Slot = QtCore.pyqtSlot


logger = logging.getLogger(__name__)


#
# Для правильной инициализации сигналы должны содержаться в объекте QObject или
# подкласса.
#
class Signaller(QtCore.QObject):
    signal = Signal(str, logging.LogRecord)

#
# Вывод в графический интерфейс Qt должен выполняться только в основном потоке.
# Таким образом, этот обработчик предназначен для выполнения функции слота,
# которая настроена на выполнение в основном потоке. В этом примере функция
# принимает аргумент строку, которая представляет собой форматированное сообщение
# журнала, и запись журнала, которая его сгенерировала. Отформатированный строка -
# это просто удобство, вы можете отформатировать строку для вывода любым
# способом, который вам нравится в самой функции слота.
#
# Необходимо указать функцию слота для выполнения любых необходимых обновлений
# GUI. Обработчик не знает и не заботится о элементах пользовательского
# интерфейса.
#
class QtHandler(logging.Handler):
    def __init__(self, slotfunc, *args, **kwargs):
        super(QtHandler, self).__init__(*args, **kwargs)
        self.signaller = Signaller()
        self.signaller.signal.connect(slotfunc)

    def emit(self, record):
        s = self.format(record)
        self.signaller.signal.emit(s, record)

#
# Пример использует QThreads, что означает, что потоки на уровне Python
# имеются чем-то вроде «Фикция № 1». Функция ниже получает имя Qt текущего потока.
#
def ctname():
    return QtCore.QThread.currentThread().objectName()


#
# Используется для генерации случайных уровней для логирования.
#
LEVELS = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
          logging.CRITICAL)

#
# Рабочий класс представляет работу, выполняемую в потоке, отдельном
# основному потоку. Способ запуска потока для выполнения работы заключается в
# нажатии кнопки, которая подключается к слоту в воркере.
#
# Поскольку значение threadName по умолчанию в LogRecord используется мало, мы
# добавляем qThreadName, которое содержит имя QThread, вычисленное выше, и
# передаем это значение в "дополнительный" словарь, который используется для
# обновления LogRecord с именем QThread.
#
# В этом примере воркер просто выводит сообщения последовательно, перемежаясь
# случайными задержками порядка нескольких секунд.
#
class Worker(QtCore.QObject):
    @Slot()
    def start(self):
        extra = {'qThreadName': ctname() }
        logger.debug('Started work', extra=extra)
        i = 1
        # Пусть поток работает до прерывания. Это обеспечивает достаточно чистое
        # завершение потока.
        while not QtCore.QThread.currentThread().isInterruptionRequested():
            delay = 0.5 + random.random() * 2
            time.sleep(delay)
            level = random.choice(LEVELS)
            logger.log(level, 'Message after delay of %3.1f: %d', delay, i, extra=extra)
            i += 1

#
# Реализовать простой пользовательский интерфейс для этого примера поваренной книги. Содержание:
#
# * Окно редактирования текста только для чтения, содержащее форматированные сообщения журнала
# * Кнопка для начала работы и логирования в отдельном потоке
# * Кнопка для журналирования чего-то из основного потока
# * Кнопка для очистки окна журнала
#
class Window(QtWidgets.QWidget):

    COLORS = {
        logging.DEBUG: 'black',
        logging.INFO: 'blue',
        logging.WARNING: 'orange',
        logging.ERROR: 'red',
        logging.CRITICAL: 'purple',
    }

    def __init__(self, app):
        super(Window, self).__init__()
        self.app = app
        self.textedit = te = QtWidgets.QPlainTextEdit(self)
        # Установить шрифт monospace для платформы
        f = QtGui.QFont('nosuchfont')
        f.setStyleHint(f.Monospace)
        te.setFont(f)
        te.setReadOnly(True)
        PB = QtWidgets.QPushButton
        self.work_button = PB('Start background work', self)
        self.log_button = PB('Log a message at a random level', self)
        self.clear_button = PB('Clear log window', self)
        self.handler = h = QtHandler(self.update_status)
        # Не забудьте использовать имя qThreadName, а не threadName в строке формата.
        fs = '%(asctime)s %(qThreadName)-12s %(levelname)-8s %(message)s'
        formatter = logging.Formatter(fs)
        h.setFormatter(formatter)
        logger.addHandler(h)
        # Настройка для завершения QThread при выходе
        app.aboutToQuit.connect(self.force_quit)

        # Показать все виджеты
        layout = QtWidgets.QVBoxLayout(self)
        layout.addWidget(te)
        layout.addWidget(self.work_button)
        layout.addWidget(self.log_button)
        layout.addWidget(self.clear_button)
        self.setFixedSize(900, 400)

        # Подключить нерабочие слоты и сигналы
        self.log_button.clicked.connect(self.manual_update)
        self.clear_button.clicked.connect(self.clear_display)

        # Запустить новый рабочий поток и подключить слоты для воркера
        self.start_thread()
        self.work_button.clicked.connect(self.worker.start)
        # Once started, the button should be disabled
        self.work_button.clicked.connect(lambda : self.work_button.setEnabled(False))

    def start_thread(self):
        self.worker = Worker()
        self.worker_thread = QtCore.QThread()
        self.worker.setObjectName('Worker')
        self.worker_thread.setObjectName('WorkerThread')  # для qThreadName
        self.worker.moveToThread(self.worker_thread)
        # Это приведет к запуску событийного цикла в рабочем потоке
        self.worker_thread.start()

    def kill_thread(self):
        # Просто сказать воркеру остановиться, затем скажи, чтобы вышел и ждал, пока
        # это произойдёт
        self.worker_thread.requestInterruption()
        if self.worker_thread.isRunning():
            self.worker_thread.quit()
            self.worker_thread.wait()
        else:
            print('worker has already exited.')

    def force_quit(self):
        # Для использования при закрытии окна
        if self.worker_thread.isRunning():
            self.kill_thread()

    # Приведенные ниже функции обновляют UI и запускаются в
    # основном потоке, поскольку здесь устанавливаются слоты

    @Slot(str, logging.LogRecord)
    def update_status(self, status, record):
        color = self.COLORS.get(record.levelno, 'black')
        s = '<pre><font color="%s">%s</font></pre>' % (color, status)
        self.textedit.appendHtml(s)

    @Slot()
    def manual_update(self):
        # Функция использует переданное форматированное сообщение, но также использует
        # информацию из записи для форматирования сообщения соответствующим цветом в
        # соответствии с его серьезностью (уровнем).
        level = random.choice(LEVELS)
        extra = {'qThreadName': ctname() }
        logger.log(level, 'Manually logged!', extra=extra)

    @Slot()
    def clear_display(self):
        self.textedit.clear()


def main():
    QtCore.QThread.currentThread().setObjectName('MainThread')
    logging.getLogger().setLevel(logging.DEBUG)
    app = QtWidgets.QApplication(sys.argv)
    example = Window(app)
    example.show()
    sys.exit(app.exec_())

if __name__=='__main__':
    main()