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

Автор:Vinay Sajip <vinay_sajip@red-dove.com>

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

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

Селекторные совещания к 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()

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

   0 Thread-1 Hi from myfunc
   3 MainThread Hello from main
 505 Thread-1 Hi from myfunc
 755 MainThread Hello from main
1007 Thread-1 Hi from myfunc
1507 MainThread Hello from main
1508 Thread-1 Hi from myfunc
2010 Thread-1 Hi from myfunc
2258 MainThread Hello from main
2512 Thread-1 Hi from myfunc
3009 MainThread Hello from main
3013 Thread-1 Hi from myfunc
3515 Thread-1 Hi from myfunc
3761 MainThread Hello from main
4017 Thread-1 Hi from myfunc
4513 MainThread Hello from main
4518 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: в отличие от инструкций печати, которые придется удалить или прокомментировать позже, логгер.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)  # no limit on size
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)
# не беспокойтесь о форматере, так как обработчик сокета отправляет событие как
# неформатированный pickle
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 в формате pickle. Регистрирует запись в
        соответствии с локальной политикой.
        """
        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...
   59 root            INFO     Jackdaws love my big sphinx of quartz.
   59 myapp.area1     DEBUG    Quick zephyrs blow, vexing daft Jim.
   69 myapp.area1     INFO     How quickly daft jumping zebras vex.
   69 myapp.area2     WARNING  Jail zesty vixen who grabbed pay from quack.
   69 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 - это место, где контекстная информация добавляется в выходные данные логирование. Это передало сообщение и аргументы ключевой требования логирование, и это пасует назад (потенциально) измененные версии их, чтобы использовать в требовании к основному логгер. Внедрение по умолчанию этого метод оставляет сообщение в покое, но вставляет „дополнительный“ ключ в аргументе ключевой, стоимость которого - подобный dict объект, переданный конструктору. Конечно, если вы передали „дополнительный“ аргумент ключевой в звонке на адаптер, он будет тихо переписан.

Преимущество использования „дополнительного“ состоит в том, что ценности в подобном dict объекте слиты в случай LogRecord __ dict __, позволив вам использовать настроенные строки с вашим 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, для передачи контекстной информации

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

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

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

Например, в веб-приложении обрабатывается запрос (или, по крайней мере, интересные его части) могут храниться в threadlocal (threading.local), к которым переменная, и затем получила доступ от Filter, чтобы добавить, скажем, информацию от запроса - говорят, удаленный IP-адрес и имя пользователя удаленного пользователя - к LogRecord, используя атрибут называют „IP“ и „пользователя“ как в примере 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

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

Хотя логирование безопасен от нити, и логирование к единственному файлу от нескольких нитей в единственном процессе поддержанный is, логирование к единственному файлу от multiple processes - поддержанный not, потому что нет никакого стандартного способа преобразовать в последовательную форму доступ к единственному файлу через несколько процессов в Python. Если вам нужно войти в один файл из нескольких процессов, один из способов сделать это, чтобы все процессы регистрации в SocketHandler, и иметь отдельный процесс, который реализует сервер сокет, который считывает из сокет и журналы в файл. (При необходимости для выполнения этой функции можно выделить один поток в одном из существующих процессов.) This section более подробно документирует этот подход и включает в себя рабочий приемник сокет, который может быть используемый в качестве отправной точки для адаптации в собственных приложениях.

Можно также написать собственный обработчик, который использует Lock класс из модуля multiprocessing для сериализации доступа к файлу из процессов. Существующие FileHandler и подклассы в настоящее время не используют multiprocessing, хотя они могут сделать это в будущем. Следует отметить, что в настоящее время модуль multiprocessing не обеспечивает функциональные возможности рабочей блокировки на всех платформах (см. https://bugs.python.org/issue3770).

Кроме того, можно использовать 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 Вы не можете полагаться на семантику вилки, таким
# образом, каждый процесс будет управлять конфигурацией логирование код, когда это
# начнется.
def worker_configurer(queue):
    h = logging.handlers.QueueHandler(queue)  # Just the one handler needed
    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)

Применение ротации файлов

Иногда вы хотите, чтобы файл журнала вырос до определенного размера, а затем открыть новый файл и войти в него. Возможно, потребуется сохранить определенное количество этих файлов, и когда будет создано много файлов, поверните их таким образом, чтобы количество файлов и размер файлов оставались ограниченными. Для этой модели использования пакет логирование предоставляет 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, поскольку внутри пакета логирование используется% -форматирование для объединения формата строка и аргументов переменной. Не было бы никакого изменения этого, сохраняя обратную совместимость, так как все требования логирование, которые находятся там в существующем код, будут использовать % - формат строки.

Однако существует возможность использования форматирования {} и $ для создания отдельных сообщений журнала. Напомним, что для сообщения можно использовать произвольный объект в качестве строки формата сообщения, и что пакет логирование вызовет 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)

Любой из них может быть используемый вместо последовательности формата, чтобы позволить {} - или $ - форматирующий быть используемый, чтобы построить фактическую часть «сообщения», которая появляется в отформатированной продукции регистрации вместо «% (сообщение) s» или «{сообщение}» или «$message». Это немного громоздко использовать имена класс, когда вы хотите что-то записать, но это довольно вкусно, если вы используете такие алиас, как __ (двойное подчеркивание — не путать с _, единственное подчеркивание используемый как synonym/алиас для 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 „publish“ сокет. В приведенном ниже примере сокет создается отдельно и передается обработчику (как его очередь):

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. Этот фрагмент предназначен только для иллюстрации.

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

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

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

Вот сценарий - докстринги и комментарии, надеюсь, объясняют, как он работает:

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, так как форк не
        # используется, установка, логгер не будет существовать в дочернем, таким образом,
        # это было бы создано и сообщение появится - следовательно «если 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, так как форк не
        # используется, установка, логгер не будет существовать в дочернем, таким образом,
        # это было бы создано и сообщение появится - следовательно «если 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, присоединенный
    # к корневому журналу, который позволяет отправлять все сообщения в очередь. Мы
    # отключаем существующие логгеры, чтобы отключить "setup" логгер используемый в
    # родительском процессе. Это необходимо для POSIX, потому что логгер будет
    # находиться в потомке после fork().
    config_worker = {
        'version': 1,
        'disable_existing_loggers': True,
        'handlers': {
            'queue': {
                'class': 'logging.handlers.QueueHandler',
                'queue': q
            }
        },
        'root': {
            'handlers': ['queue'],
            'level': 'DEBUG'
        }
    }
    # Конфигурация процесса прослушивателя показывает, что полная гибкость
    # конфигурации логирование доступна для отправки событий обработчикам при
    # необходимости. Мы отключаем существующие логгеры, чтобы отключить "setup" логгер
    # используемый в родительском процессе. Это необходимо для 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 требует, чтобы сообщение Unicode послали демону системного журнала как ряд байтов, у которых есть следующая структура: дополнительный компонент чистого ASCII, сопровождаемый Byte Order Mark (BOM) UTF-8, сопровождаемым Unicode кодированный, используя UTF-8. (См. соответствующий раздел спецификации.

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

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

  1. Приложите Formatter сущность к своему случаю SysLogHandler с форматом строка такой как:

    'ASCII section\ufeffUnicode section'
    

    Unicode кодовая точка U+FEFF, когда кодированный, используя UTF-8, будет кодированный как BOM UTF-8 – байт-строка b'\xef\xbb\xbf'.

  2. Замените раздел ASCII на любые нужные местозаполнители, но убедитесь, что данные, появляющиеся в нем после замены, всегда являются ASCII (таким образом, они останутся неизменными после кодировки UTF-8).

  3. Замените раздел юникод на любые заполнители; если данные, появляющиеся после замены, содержат символы за пределами диапазона ASCII, это нормально - это будет кодированный с использованием UTF-8.

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

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

Хотя большинство сообщений логирование предназначено для чтения людьми и таким образом не с готовностью машинно-распознаваем, могли бы быть обстоятельства, где вы хотите к выходным сигналам в структурированном формате который быть способный к тому, чтобы быть разобранным программой (не нуждаясь в сложных регулярных выражениях, чтобы разобрать сообщение регистрации). Это просто достичь, используя пакет логирование. Существует ряд способов, с помощью которых это может быть достигнуто, но ниже приведен простой подход, который использует 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   # optional, to improve readability

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   # optional, to improve readability

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, пакет логирование получил возможность предоставлять пользователям возможность устанавливать свои собственные подклассы LogRecord, используя функцию setLogRecordFactory(). Вы можете использовать это, чтобы задать свой собственный подкласс LogRecord, который делает правильно, переопределяя getMessage() метод. Основное внедрение класс этого метод состоит в том, где форматирование msg % args происходит, и где вы можете заменить своим альтернативным форматированием; однако следует соблюдать осторожность при поддержке всех стилей форматирования и разрешить% -форматирование по умолчанию, чтобы обеспечить совместимость с другими код. Следует также проявлять осторожность, чтобы вызвать str(self.msg), как это делает базовая реализация.

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

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

Существует другой, возможно, более простой способ использования форматирования {} и $ для создания отдельных сообщений журнала. Можно вспомнить (из Использование произвольных объектов в качестве сообщений), что при логирование можно использовать произвольный объект в качестве строки формата сообщения, и что пакет логирование вызовет 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». Если вы находите немного громоздким использовать имена класс, когда вы хотите записать что- то в журнал, вы можете сделать его более приятным, если вы используете для сообщения такие алиас, как 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()

Вы can настроить фильтры, используя 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 в вышеупомянутом примере.
  • А также для фильтров, эта техника может также быть используемый, чтобы настроить пользовательских обработчиков и средства форматирования. См. Определенные пользователями объекты для получения дополнительной информации о том, как поддержки логирование, используя определенные пользователями объекты в его конфигурации, и видят другой рецепт Настройка обработчиков с помощью dictConfig() поваренной книги выше.

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

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

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 может быть полезен для более специализированных нужд.

Призношение сообщений логирования

Могут быть ситуации, когда желательно иметь сообщения логирование, отображаемые в слышимом, а не видимом формате. Это легко сделать, если в системе доступны функции «текст-речь» (text-to-speech, 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, который при значении true будет регистрироваться на уровнях 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

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

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

@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. Если вы хотите сделать это через конфигурацию, вы можете использовать dictConfig() API с подходом, проиллюстрированным следующим полным примером:

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

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

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

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

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()
        # implicit return of None => don't swallow exceptions

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

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

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
1. This should appear just once on stderr.
3. This should appear once on stderr.
5. This should appear twice - once on stderr and once on stdout.
5. This should appear twice - once on stderr and once on stdout.
6. 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, мы get:

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

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

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

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

Вот пример, который показывает, как вы можете:

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

Предположим, у нас есть приложение командной строки, задание которого - остановить, запустить или перезапустить некоторые службы. Это может быть организовано для иллюстрации в виде файла 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()
    # команды код to 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 для ведения журнала

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

В следующем примере показано, как выполнить вход в графический интерфейс Qt. Это вводит простой QtHandler класс, который берет подлежащее выкупу, которое должно быть местом в главной нити, которая делает обновления графический интерфейса пользователя. Нить рабочего также создана, чтобы показать, как вы можете зарегистрировать к графический интерфейсу пользователя от обоих сам UI (через кнопку для регистрации руководства), а также работа выполнения нити рабочего на заднем плане (здесь, просто сообщения логирование наугад уровни со случайными короткими промежуточными задержками).

Нить рабочего осуществлена, используя QThread класс QT, а не модуль 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):
        # For use when the window is closed
        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()