logging-cookbook.md

1> **Источник:** https://python-all.ru/3.4/howto/logging-cookbook.html2>3> «Документация Python на русском» – неофициальный перевод официальной документации Python: версии от 2.6 до 3.16, полнотекстовый поиск, английский оригинал рядом с переводом. Эта Markdown-версия страницы предназначена для работы с LLM: вставьте её в ChatGPT, Claude или Cursor.45---67# Сборник рецептов по логированию89| Автор: | Vinay Sajip \<vinay\_sajip at red-dove dot com\> |10| --- | --- |1112На этой странице представлен ряд рецептов, связанных с логированием, которые оказались полезными на практике.1314## Использование логирования в нескольких модулях1516Многократные вызовы `logging.getLogger('someLogger')` возвращают ссылку на один и тот же объект логгера. Это верно не только в пределах одного модуля, но и между модулями, пока они находятся в одном процессе интерпретатора Python. Это верно для ссылок на один и тот же объект; кроме того, код приложения может определить и настроить родительский логгер в одном модуле и создать (но не настраивать) дочерний логгер в отдельном модуле, и все вызовы логгера к дочернему будут передаваться родительскому. Вот главный модуль:1718```python19import logging20import auxiliary_module2122# создать логгер с именем 'spam_application'23logger = logging.getLogger('spam_application')24logger.setLevel(logging.DEBUG)25# создать файловый обработчик, записывающий даже отладочные сообщения26fh = logging.FileHandler('spam.log')27fh.setLevel(logging.DEBUG)28# создать консольный обработчик с более высоким уровнем логирования29ch = logging.StreamHandler()30ch.setLevel(logging.ERROR)31# создать форматтер и добавить его к обработчикам32formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')33fh.setFormatter(formatter)34ch.setFormatter(formatter)35# добавить обработчики к логгеру36logger.addHandler(fh)37logger.addHandler(ch)3839logger.info('creating an instance of auxiliary_module.Auxiliary')40a = auxiliary_module.Auxiliary()41logger.info('created an instance of auxiliary_module.Auxiliary')42logger.info('calling auxiliary_module.Auxiliary.do_something')43a.do_something()44logger.info('finished auxiliary_module.Auxiliary.do_something')45logger.info('calling auxiliary_module.some_function()')46auxiliary_module.some_function()47logger.info('done with auxiliary_module.some_function()')48```4950А вот вспомогательный модуль:5152```python53import logging5455# создать логгер56module_logger = logging.getLogger('spam_application.auxiliary')5758class Auxiliary:59    def __init__(self):60        self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')61        self.logger.info('creating an instance of Auxiliary')62    def do_something(self):63        self.logger.info('doing something')64        a = 1 + 165        self.logger.info('done doing something')6667def some_function():68    module_logger.info('received a call to "some_function"')69```7071Вывод выглядит так:7273```python742005-03-23 23:47:11,663 - spam_application - INFO -75   creating an instance of auxiliary_module.Auxiliary762005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -77   creating an instance of Auxiliary782005-03-23 23:47:11,665 - spam_application - INFO -79   created an instance of auxiliary_module.Auxiliary802005-03-23 23:47:11,668 - spam_application - INFO -81   calling auxiliary_module.Auxiliary.do_something822005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -83   doing something842005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -85   done doing something862005-03-23 23:47:11,670 - spam_application - INFO -87   finished auxiliary_module.Auxiliary.do_something882005-03-23 23:47:11,671 - spam_application - INFO -89   calling auxiliary_module.some_function()902005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -91   received a call to 'some_function'922005-03-23 23:47:11,673 - spam_application - INFO -93   done with auxiliary_module.some_function()94```9596## Несколько обработчиков и форматировщиков9798Логгеры – это обычные объекты Python. Метод [`addHandler()`](https://python-all.ru/3.4/library/logging.html#logging.Logger.addHandler) не имеет минимального или максимального ограничения на количество добавляемых обработчиков. Иногда приложению бывает полезно записывать все сообщения всех уровней в текстовый файл, одновременно выводя ошибки и выше на консоль. Чтобы настроить это, просто сконфигурируйте соответствующие обработчики. Вызовы логирования в коде приложения останутся без изменений. Вот небольшая модификация предыдущего простого примера конфигурации на основе модуля:99100```python101import logging102103logger = logging.getLogger('simple_example')104logger.setLevel(logging.DEBUG)105# создать файловый обработчик, записывающий даже отладочные сообщения106fh = logging.FileHandler('spam.log')107fh.setLevel(logging.DEBUG)108# создать консольный обработчик с более высоким уровнем логирования109ch = logging.StreamHandler()110ch.setLevel(logging.ERROR)111# создать форматтер и добавить его к обработчикам112formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')113ch.setFormatter(formatter)114fh.setFormatter(formatter)115# добавить обработчики в логгер116logger.addHandler(ch)117logger.addHandler(fh)118119# код 'приложения'120logger.debug('debug message')121logger.info('info message')122logger.warn('warn message')123logger.error('error message')124logger.critical('critical message')125```126127Обратите внимание, что «прикладной» код не заботится о нескольких обработчиках. Единственное, что изменилось – добавление и настройка нового обработчика с именем *fh*.128129Возможность создавать новые обработчики с фильтрами более высокого или низкого уровня серьезности может быть очень полезна при написании и тестировании приложения. Вместо использования множества операторов `print` для отладки используйте `logger.debug`: в отличие от операторов print, которые вам придется удалить или закомментировать позже, операторы logger.debug могут оставаться в исходном коде и оставаться неактивными до тех пор, пока они снова не понадобятся. В этом случае единственное, что нужно сделать, – изменить уровень серьезности логгера и/или обработчика на debug.130131## Журналирование в несколько мест назначения132133Допустим, вы хотите вести журнал в консоль и файл с разными форматами сообщений и в разных ситуациях. Предположим, вы хотите записывать сообщения уровня DEBUG и выше в файл, а сообщения уровня INFO и выше – в консоль. Также предположим, что файл должен содержать временные метки, а консольные сообщения – нет. Вот как это можно сделать:134135```python136import logging137138# настроить логирование в файл – подробнее см. предыдущий раздел139logging.basicConfig(level=logging.DEBUG,140                    format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',141                    datefmt='%m-%d %H:%M',142                    filename='/temp/myapp.log',143                    filemode='w')144# Определяет обработчик, который записывает сообщения уровня INFO и выше в sys.stderr.145console = logging.StreamHandler()146console.setLevel(logging.INFO)147# Задает формат, упрощенный для вывода в консоль.148formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')149# Указывает обработчику использовать этот формат.150console.setFormatter(formatter)151# Добавляет обработчик в корневой логгер.152logging.getLogger('').addHandler(console)153154# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...155logging.info('Jackdaws love my big sphinx of quartz.')156157# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:158# приложение:159160logger1 = logging.getLogger('myapp.area1')161logger2 = logging.getLogger('myapp.area2')162163logger1.debug('Quick zephyrs blow, vexing daft Jim.')164logger1.info('How quickly daft jumping zebras vex.')165logger2.warning('Jail zesty vixen who grabbed pay from quack.')166logger2.error('The five boxing wizards jump quickly.')167```168169При запуске на консоли вы увидите170171```python172root        : INFO     Jackdaws love my big sphinx of quartz.173myapp.area1 : INFO     How quickly daft jumping zebras vex.174myapp.area2 : WARNING  Jail zesty vixen who grabbed pay from quack.175myapp.area2 : ERROR    The five boxing wizards jump quickly.176```177178а в файле увидите примерно такое179180```python18110-22 22:19 root         INFO     Jackdaws love my big sphinx of quartz.18210-22 22:19 myapp.area1  DEBUG    Quick zephyrs blow, vexing daft Jim.18310-22 22:19 myapp.area1  INFO     How quickly daft jumping zebras vex.18410-22 22:19 myapp.area2  WARNING  Jail zesty vixen who grabbed pay from quack.18510-22 22:19 myapp.area2  ERROR    The five boxing wizards jump quickly.186```187188Как видите, сообщение DEBUG отображается только в файле. Остальные сообщения отправляются в оба места назначения.189190В этом примере используются консольный и файловый обработчики, но вы можете использовать любое количество и любое сочетание обработчиков по своему выбору.191192## Пример сервера конфигурации193194Вот пример модуля, использующего сервер конфигурации журналирования:195196```python197import logging198import logging.config199import time200import os201202# Прочитать начальный конфигурационный файл.203logging.config.fileConfig('logging.conf')204205# Создать и запустить слушатель на порту 9999.206t = logging.config.listen(9999)207t.start()208209logger = logging.getLogger('simpleExample')210211try:212    # Прокрутить вызовы логирования, чтобы увидеть разницу.213    # Создавать новые конфигурации до нажатия Ctrl+C.214    while True:215        logger.debug('debug message')216        logger.info('info message')217        logger.warn('warn message')218        logger.error('error message')219        logger.critical('critical message')220        time.sleep(5)221except KeyboardInterrupt:222    # очистка223    logging.config.stopListening()224    t.join()225```226227А вот скрипт, который принимает имя файла и отправляет этот файл на сервер, предварив его двоично-закодированной длиной, в качестве новой конфигурации журналирования:228229```python230#!/usr/bin/env python231import socket, sys, struct232233with open(sys.argv[1], 'rb') as f:234    data_to_send = f.read()235236HOST = 'localhost'237PORT = 9999238s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)239print('connecting...')240s.connect((HOST, PORT))241print('sending config...')242s.send(struct.pack('>L', len(data_to_send)))243s.send(data_to_send)244s.close()245print('complete')246```247248## Работа с блокирующими обработчиками249250Иногда требуется, чтобы обработчики логирования выполняли свою работу, не блокируя поток, из которого ведется логирование. Это часто встречается в веб-приложениях, хотя, конечно, бывает и в других сценариях.251252Часто виновником медленной работы является [`SMTPHandler`](https://python-all.ru/3.4/library/logging.handlers.html#logging.handlers.SMTPHandler): отправка писем может занимать много времени по ряду причин, не зависящих от разработчика (например, плохая производительность почтовой или сетевой инфраструктуры). Но почти любой сетевой обработчик может блокироваться: даже операция [`SocketHandler`](https://python-all.ru/3.4/library/logging.handlers.html#logging.handlers.SocketHandler) может выполнять DNS-запрос внутри, который слишком медленный (и этот запрос может находиться глубоко в коде библиотеки сокетов, ниже уровня Python, и вне вашего контроля).253254Одно из решений – использовать двухчастный подход. На первом этапе прикрепите только [`QueueHandler`](https://python-all.ru/3.4/library/logging.handlers.html#logging.handlers.QueueHandler) к тем логгерам, к которым обращаются из критичных по производительности потоков. Они просто пишут в свою очередь, которая может быть настроена на достаточно большую емкость или инициализирована без верхнего ограничения размера. Запись в очередь обычно принимается быстро, хотя вам, вероятно, потребуется перехватывать исключение [`queue.Full`](https://python-all.ru/3.4/library/queue.html#queue.Full) в качестве меры предосторожности в коде. Если вы разработчик библиотеки, и в вашем коде есть критичные по производительности потоки, обязательно задокументируйте это (вместе с рекомендацией прикреплять только `QueueHandlers` к вашим логгерам) на благо других разработчиков, которые будут использовать ваш код.255256Вторая часть решения – [`QueueListener`](https://python-all.ru/3.4/library/logging.handlers.html#logging.handlers.QueueListener), который был разработан как аналог [`QueueHandler`](https://python-all.ru/3.4/library/logging.handlers.html#logging.handlers.QueueHandler). [`QueueListener`](https://python-all.ru/3.4/library/logging.handlers.html#logging.handlers.QueueListener) очень прост: ему передаются очередь и несколько обработчиков, и он запускает внутренний поток, который слушает свою очередь на предмет LogRecords, отправленных от `QueueHandlers` (или любого другого источника `LogRecords`, если на то пошло). `LogRecords` извлекаются из очереди и передаются обработчикам для обработки.257258Преимущество отдельного класса [`QueueListener`](https://python-all.ru/3.4/library/logging.handlers.html#logging.handlers.QueueListener) в том, что можно использовать один и тот же экземпляр для обслуживания нескольких `QueueHandlers`. Это более эффективно по ресурсам, чем, скажем, создание многопоточных версий существующих классов обработчиков, которые потребляют по одному потоку на обработчик без особой пользы.259260Ниже приведён пример использования этих двух классов (импорты опущены):261262```python263que = queue.Queue(-1) # Без ограничения размера.264queue_handler = QueueHandler(que)265handler = logging.StreamHandler()266listener = QueueListener(que, handler)267root = logging.getLogger()268root.addHandler(queue_handler)269formatter = logging.Formatter('%(threadName)s: %(message)s')270handler.setFormatter(formatter)271listener.start()272# Вывод лога будет отображать поток, создавший событие (главный поток), а не внутренний поток,273# отслеживающий внутреннюю очередь.274# Именно это и должно происходить.275# то, что должно произойти.276root.warning('Look out!')277listener.stop()278```279280который при запуске выведет:281282```python283MainThread: Look out!284```285286## Отправка и получение событий логирования по сети287288Допустим, вы хотите отправлять события логирования по сети и обрабатывать их на принимающей стороне. Простой способ сделать это – прикрепить экземпляр [`SocketHandler`](https://python-all.ru/3.4/library/logging.handlers.html#logging.handlers.SocketHandler) к корневому логгеру на отправляющей стороне:289290```python291import logging, logging.handlers292293rootLogger = logging.getLogger('')294rootLogger.setLevel(logging.DEBUG)295socketHandler = logging.handlers.SocketHandler('localhost',296                    logging.handlers.DEFAULT_TCP_LOGGING_PORT)297# Не нужно использовать форматтер, так как сокет-обработчик отправляет событие в виде неформатированного пикла.298# неформатированный pickle299rootLogger.addHandler(socketHandler)300301# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...302logging.info('Jackdaws love my big sphinx of quartz.')303304# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:305# приложение:306307logger1 = logging.getLogger('myapp.area1')308logger2 = logging.getLogger('myapp.area2')309310logger1.debug('Quick zephyrs blow, vexing daft Jim.')311logger1.info('How quickly daft jumping zebras vex.')312logger2.warning('Jail zesty vixen who grabbed pay from quack.')313logger2.error('The five boxing wizards jump quickly.')314```315316На принимающей стороне можно настроить приемник с помощью модуля [`socketserver`](https://python-all.ru/3.4/library/socketserver.html#module-socketserver). Вот базовый рабочий пример:317318```python319import pickle320import logging321import logging.handlers322import socketserver323import struct324325class LogRecordStreamHandler(socketserver.StreamRequestHandler):326    """Обработчик для потокового запроса логирования.327328    Это по сути записывает запись, используя ту политику логирования, которая настроена локально.329    настроено локально.330    """331332    def handle(self):333        """334        Обрабатывает несколько запросов – каждый ожидается в формате: 4-байтовая длина, затем запись журнала в формате пикл.335        Записывает запись в соответствии с политикой, настроенной локально.336        согласно локально настроенной политике.337        """338        while True:339            chunk = self.connection.recv(4)340            if len(chunk) < 4:341                break342            slen = struct.unpack('>L', chunk)[0]343            chunk = self.connection.recv(slen)344            while len(chunk) < slen:345                chunk = chunk + self.connection.recv(slen - len(chunk))346            obj = self.unPickle(chunk)347            record = logging.makeLogRecord(obj)348            self.handleLogRecord(record)349350    def unPickle(self, data):351        return pickle.loads(data)352353    def handleLogRecord(self, record):354        # Если указано имя, используется именованный логгер, а не тот, что355        # подразумевается записью.356        if self.server.logname is not None:357            name = self.server.logname358        else:359            name = record.name360        logger = logging.getLogger(name)361        # Примечание: КАЖДАЯ запись попадает в журнал. Это связано с тем, что Logger.handle362        # обычно вызывается ПОСЛЕ фильтрации на уровне регистратора. Если требуется363        # выполнять фильтрацию, делайте это на стороне клиента, чтобы не тратить364        # циклы процессора и сетевую пропускную способность!365        logger.handle(record)366367class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):368    """369    Простой приёмник журнала на основе TCP-сокетов, подходящий для тестирования.370    """371372    allow_reuse_address = True373374    def __init__(self, host='localhost',375                 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,376                 handler=LogRecordStreamHandler):377        socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)378        self.abort = 0379        self.timeout = 1380        self.logname = None381382    def serve_until_stopped(self):383        import select384        abort = 0385        while not abort:386            rd, wr, ex = select.select([self.socket.fileno()],387                                       [], [],388                                       self.timeout)389            if rd:390                self.handle_request()391            abort = self.abort392393def main():394    logging.basicConfig(395        format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')396    tcpserver = LogRecordSocketReceiver()397    print('About to start TCP server...')398    tcpserver.serve_until_stopped()399400if __name__ == '__main__':401    main()402```403404Сначала запустите сервер, затем клиент. На стороне клиента в консоль ничего не выводится; на стороне сервера вы должны увидеть что-то вроде:405406```python407About to start TCP server...408   59 root            INFO     Jackdaws love my big sphinx of quartz.409   59 myapp.area1     DEBUG    Quick zephyrs blow, vexing daft Jim.410   69 myapp.area1     INFO     How quickly daft jumping zebras vex.411   69 myapp.area2     WARNING  Jail zesty vixen who grabbed pay from quack.412   69 myapp.area2     ERROR    The five boxing wizards jump quickly.413```414415Обратите внимание, что в некоторых сценариях существуют проблемы безопасности с pickle. Если они вас затрагивают, вы можете использовать альтернативную схему сериализации, переопределив метод `makePickle()` и реализовав свою альтернативу там, а также адаптировав приведенный выше скрипт для использования вашей альтернативной сериализации.416417## Добавление контекстной информации в вывод журнала418419Иногда требуется, чтобы вывод логирования содержал контекстную информацию в дополнение к параметрам, переданным в вызов логирования. Например, в сетевом приложении может быть желательно регистрировать специфичную для клиента информацию в журнале (например, имя пользователя удаленного клиента или IP-адрес). Хотя вы можете использовать параметр *extra* для этого, не всегда удобно передавать информацию таким образом. Хотя может возникнуть соблазн создавать экземпляры `Logger` для каждого соединения, это не очень хорошая идея, потому что эти экземпляры не собираются сборщиком мусора. Хотя на практике это не проблема, когда количество экземпляров `Logger` зависит от уровня детализации, которую вы хотите использовать при логировании приложения, это может быть трудно управляемым, если количество экземпляров `Logger` становится фактически неограниченным.420421### Использование LoggerAdapter для добавления контекстной информации422423Простой способ передавать контекстную информацию для вывода вместе с информацией о событии логирования – использовать класс `LoggerAdapter`. Этот класс разработан так, чтобы выглядеть как `Logger`, так что вы можете вызывать `debug()`, `info()`, `warning()`, `error()`, `exception()`, `critical()` и `log()`. Эти методы имеют те же сигнатуры, что и их аналоги в `Logger`, поэтому вы можете использовать экземпляры обоих типов взаимозаменяемо.424425Когда вы создаете экземпляр `LoggerAdapter`, вы передаете ему экземпляр `Logger` и объект, подобный словарю, который содержит вашу контекстную информацию. Когда вы вызываете один из методов логирования на экземпляре `LoggerAdapter`, он делегирует вызов базовому экземпляру `Logger`, переданному его конструктору, и обеспечивает передачу контекстной информации в делегированном вызове. Вот фрагмент из кода `LoggerAdapter`:426427```python428def debug(self, msg, *args, **kwargs):429    """430    Передаёт вызов отладки нижележащему регистратору после добавления431    контекстной информации из данного экземпляра адаптера.432    """433    msg, kwargs = self.process(msg, kwargs)434    self.logger.debug(msg, *args, **kwargs)435```436437Метод `process()` класса `LoggerAdapter` – это то место, где контекстная информация добавляется к выводу логирования. Ему передаются сообщение и именованные аргументы вызова логирования, и он возвращает (потенциально) измененные версии этих данных для использования в вызове базового логгера. Реализация по умолчанию этого метода оставляет сообщение без изменений, но вставляет ключ 'extra' в именованные аргументы, значением которого является объект, подобный словарю, переданный конструктору. Конечно, если вы передали аргумент 'extra' в вызове адаптера, он будет молча перезаписан.438439Преимущество использования 'extra' в том, что значения из dict-подобного объекта сливаются в \_\_dict\_\_ экземпляра `LogRecord`, что позволяет использовать настраиваемые строки с экземплярами `Formatter`, которые знают о ключах dict-подобного объекта. Если вам нужен другой метод, например, если вы хотите добавить контекстную информацию в начало или конец строки сообщения, вам просто нужно создать подкласс `LoggerAdapter` и переопределить `process()` для выполнения нужных действий. Вот простой пример:440441```python442class CustomAdapter(logging.LoggerAdapter):443    """444    Данный пример адаптера ожидает, что переданный объект, подобный словарю, содержит445    ключ 'connid', значение которого в квадратных скобках добавляется к началу сообщения журнала.446    """447    def process(self, msg, kwargs):448        return '[%s] %s' % (self.extra['connid'], msg), kwargs449```450451который можно использовать так:452453```python454logger = logging.getLogger(__name__)455adapter = CustomAdapter(logger, {'connid': some_conn_id})456```457458Тогда любые события, которые вы регистрируете через адаптер, будут иметь значение `some_conn_id`, добавленное в начало сообщений журнала.459460#### Использование объектов, отличных от словарей, для передачи контекстной информации461462Вам не нужно передавать фактический словарь в `LoggerAdapter` – вы можете передать экземпляр класса, который реализует `__getitem__` и `__iter__`, так чтобы он выглядел как словарь для логирования. Это может быть полезно, если вы хотите генерировать значения динамически (тогда как значения в словаре были бы постоянными).463464### Использование фильтров для добавления контекстной информации465466Вы также можете добавить контекстную информацию в вывод журнала с помощью пользовательского `Filter`. Экземпляры `Filter` могут изменять переданные им `LogRecords`, включая добавление дополнительных атрибутов, которые затем можно выводить с помощью подходящей строки формата или, при необходимости, пользовательского `Formatter`.467468Например, в веб-приложении обрабатываемый запрос (или, по крайней мере, его интересные части) может храниться в переменной threadlocal ([`threading.local`](https://python-all.ru/3.4/library/threading.html#threading.local)), а затем извлекаться из `Filter` для добавления, скажем, информации из запроса – например, удаленного IP-адреса и имени пользователя – в `LogRecord`, используя имена атрибутов 'ip' и 'user', как в примере с `LoggerAdapter` выше. В этом случае можно использовать ту же строку формата для получения аналогичного вывода, показанного выше. Вот пример скрипта:469470```python471import logging472from random import choice473474class ContextFilter(logging.Filter):475    """476    Это фильтр, который внедряет контекстную информацию в журнал.477478    Вместо использования реальной контекстной информации в данном примере используются случайные479    данные.480    """481482    USERS = ['jim', 'fred', 'sheila']483    IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']484485    def filter(self, record):486487        record.ip = choice(ContextFilter.IPS)488        record.user = choice(ContextFilter.USERS)489        return True490491if __name__ == '__main__':492   levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)493   logging.basicConfig(level=logging.DEBUG,494                       format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')495   a1 = logging.getLogger('a.b.c')496   a2 = logging.getLogger('d.e.f')497498   f = ContextFilter()499   a1.addFilter(f)500   a2.addFilter(f)501   a1.debug('A debug message')502   a1.info('An info message with %s', 'some parameters')503   for x in range(10):504       lvl = choice(levels)505       lvlname = logging.getLevelName(lvl)506       a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')507```508509который при запуске выдаёт примерно следующее:510511```python5122010-09-06 22:38:15,292 a.b.c DEBUG    IP: 123.231.231.123 User: fred     A debug message5132010-09-06 22:38:15,300 a.b.c INFO     IP: 192.168.0.1     User: sheila   An info message with some parameters5142010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters5152010-09-06 22:38:15,300 d.e.f ERROR    IP: 127.0.0.1       User: jim      A message at ERROR level with 2 parameters5162010-09-06 22:38:15,300 d.e.f DEBUG    IP: 127.0.0.1       User: sheila   A message at DEBUG level with 2 parameters5172010-09-06 22:38:15,300 d.e.f ERROR    IP: 123.231.231.123 User: fred     A message at ERROR level with 2 parameters5182010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1     User: jim      A message at CRITICAL level with 2 parameters5192010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters5202010-09-06 22:38:15,300 d.e.f DEBUG    IP: 192.168.0.1     User: jim      A message at DEBUG level with 2 parameters5212010-09-06 22:38:15,301 d.e.f ERROR    IP: 127.0.0.1       User: sheila   A message at ERROR level with 2 parameters5222010-09-06 22:38:15,301 d.e.f DEBUG    IP: 123.231.231.123 User: fred     A message at DEBUG level with 2 parameters5232010-09-06 22:38:15,301 d.e.f INFO     IP: 123.231.231.123 User: fred     A message at INFO level with 2 parameters524```525526## Ведение журнала в один файл из нескольких процессов527528Хотя логирование потокобезопасно и запись в один файл из нескольких потоков в одном процессе *поддерживается*, запись в один файл из *нескольких процессов* *не* поддерживается, потому что в Python нет стандартного способа сериализовать доступ к одному файлу из нескольких процессов. Если вам нужно вести журнал в один файл из нескольких процессов, один из способов – заставить все процессы записывать в `SocketHandler`, а отдельный процесс будет реализовывать сокет-сервер, который читает из сокета и пишет в файл. (Если хотите, можно выделить один поток в одном из существующих процессов для выполнения этой функции.) [*В этом разделе*](https://python-all.ru/3.4/howto/logging-cookbook.html#network-logging) этот подход документирован более подробно и включает рабочий приемник сокетов, который можно использовать как отправную точку для адаптации в ваших собственных приложениях.529530Если вы используете последнюю версию Python, которая включает модуль [`multiprocessing`](https://python-all.ru/3.4/library/multiprocessing.html#module-multiprocessing), вы можете написать свой собственный обработчик, который использует класс [`Lock`](https://python-all.ru/3.4/library/multiprocessing.html#multiprocessing.Lock) из этого модуля для сериализации доступа к файлу из ваших процессов. Существующие `FileHandler` и его подклассы в настоящее время не используют [`multiprocessing`](https://python-all.ru/3.4/library/multiprocessing.html#module-multiprocessing), хотя в будущем они могут это сделать. Обратите внимание, что в настоящее время модуль [`multiprocessing`](https://python-all.ru/3.4/library/multiprocessing.html#module-multiprocessing) не предоставляет работающей функциональности блокировок на всех платформах (см. [https://bugs.python.org/issue3770](https://python-all.ru/3.4/howto/logging-cookbook.html)).531532В качестве альтернативы вы можете использовать `Queue` и [`QueueHandler`](https://python-all.ru/3.4/library/logging.handlers.html#logging.handlers.QueueHandler) для отправки всех событий логирования одному из процессов вашего многопроцессного приложения. Следующий пример скрипта демонстрирует, как это можно сделать; в примере отдельный процесс-слушатель прослушивает события, отправленные другими процессами, и регистрирует их в соответствии со своей собственной конфигурацией логирования. Хотя пример демонстрирует только один способ (например, вы можете захотеть использовать поток-слушатель вместо отдельного процесса-слушателя – реализация была бы аналогичной), он допускает полностью различные конфигурации логирования для слушателя и других процессов вашего приложения и может использоваться как основа для кода, удовлетворяющего вашим конкретным требованиям:533534```python535# Вам понадобятся эти импорты в вашем коде.536import logging537import logging.handlers538import multiprocessing539540# Следующие две строки импорта только для этой демонстрации.541from random import choice, random542import time543544#545# Поскольку нужно задать настройки логирования для слушателя и рабочих процессов, функции546# слушателя и рабочего процесса принимают параметр configurer – вызываемый объект для547# настройки логирования этого процесса. Эти функции также получают очередь, которую548# используют для взаимодействия.549#550# На практике слушателя можно настроить как угодно, но заметьте: в этом простом551# примере слушатель не применяет логику уровней или фильтров к полученным записям.552# На практике эту логику, вероятно, стоит вынести в рабочие процессы, чтобы не553# пересылать между процессами события, которые всё равно будут отфильтрованы.554#555# Размер файлов при ротации намеренно сделан небольшим, чтобы результат был хорошо виден.556def listener_configurer():557    root = logging.getLogger()558    h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)559    f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')560    h.setFormatter(f)561    root.addHandler(h)562563# Это главный цикл процесса-слушателя: ждём события логирования564# (LogRecords) в очереди и обрабатываем их; завершаем работу, когда получаем None вместо565# LogRecord.566def listener_process(queue, configurer):567    configurer()568    while True:569        try:570            record = queue.get()571            if record is None: # Отправляем это как сигнал завершения, чтобы слушатель остановился.572                break573            logger = logging.getLogger(record.name)574            logger.handle(record) # Никакой логики уровней и фильтров – просто делаем дело!575        except Exception:576            import sys, traceback577            print('Whoops! Problem:', file=sys.stderr)578            traceback.print_exc(file=sys.stderr)579580# Массивы для случайного выбора в этой демонстрации.581582LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,583          logging.ERROR, logging.CRITICAL]584585LOGGERS = ['a.b.c', 'd.e.f']586587MESSAGES = [588    'Random message #1',589    'Random message #2',590    'Random message #3',591]592593# Настройка рабочего процесса выполняется в начале его работы.594# Обратите внимание: в Windows нельзя полагаться на семантику fork, поэтому каждый процесс595# будет выполнять код настройки логирования при запуске.596def worker_configurer(queue):597    h = logging.handlers.QueueHandler(queue) # Нужен только один обработчик.598    root = logging.getLogger()599    root.addHandler(h)600    root.setLevel(logging.DEBUG) # Отправляем все сообщения для демонстрации; никакой другой логики уровней или фильтров.601602# Это главный цикл рабочего процесса, который просто логирует десять событий с603# случайные задержки перед завершением.604# Сообщения print нужны лишь для того, чтобы было видно, что программа работает.605def worker_process(queue, configurer):606    configurer(queue)607    name = multiprocessing.current_process().name608    print('Worker started: %s' % name)609    for i in range(10):610        time.sleep(random())611        logger = logging.getLogger(choice(LOGGERS))612        level = choice(LEVELS)613        message = choice(MESSAGES)614        logger.log(level, message)615    print('Worker finished: %s' % name)616617# Здесь организуется демонстрация. Создать очередь, создать и запустить618# слушатель, создать десять рабочих процессов и запустить их, дождаться их завершения,619# затем отправить None в очередь, чтобы сообщить слушателю о завершении.620def main():621    queue = multiprocessing.Queue(-1)622    listener = multiprocessing.Process(target=listener_process,623                                       args=(queue, listener_configurer))624    listener.start()625    workers = []626    for i in range(10):627        worker = multiprocessing.Process(target=worker_process,628                                       args=(queue, worker_configurer))629        workers.append(worker)630        worker.start()631    for w in workers:632        w.join()633    queue.put_nowait(None)634    listener.join()635636if __name__ == '__main__':637    main()638```639640Вариант приведённого выше сценария оставляет ведение журнала в главном процессе, в отдельном потоке:641642```python643import logging644import logging.config645import logging.handlers646from multiprocessing import Process, Queue647import random648import threading649import time650651def logger_thread(q):652    while True:653        record = q.get()654        if record is None:655            break656        logger = logging.getLogger(record.name)657        logger.handle(record)658659def worker_process(q):660    qh = logging.handlers.QueueHandler(q)661    root = logging.getLogger()662    root.setLevel(logging.DEBUG)663    root.addHandler(qh)664    levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,665              logging.CRITICAL]666    loggers = ['foo', 'foo.bar', 'foo.bar.baz',667               'spam', 'spam.ham', 'spam.ham.eggs']668    for i in range(100):669        lvl = random.choice(levels)670        logger = logging.getLogger(random.choice(loggers))671        logger.log(lvl, 'Message no. %d', i)672673if __name__ == '__main__':674    q = Queue()675    d = {676        'version': 1,677        'formatters': {678            'detailed': {679                'class': 'logging.Formatter',680                'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'681            }682        },683        'handlers': {684            'console': {685                'class': 'logging.StreamHandler',686                'level': 'INFO',687            },688            'file': {689                'class': 'logging.FileHandler',690                'filename': 'mplog.log',691                'mode': 'w',692                'formatter': 'detailed',693            },694            'foofile': {695                'class': 'logging.FileHandler',696                'filename': 'mplog-foo.log',697                'mode': 'w',698                'formatter': 'detailed',699            },700            'errors': {701                'class': 'logging.FileHandler',702                'filename': 'mplog-errors.log',703                'mode': 'w',704                'level': 'ERROR',705                'formatter': 'detailed',706            },707        },708        'loggers': {709            'foo': {710                'handlers': ['foofile']711            }712        },713        'root': {714            'level': 'DEBUG',715            'handlers': ['console', 'file', 'errors']716        },717    }718    workers = []719    for i in range(5):720        wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))721        workers.append(wp)722        wp.start()723    logging.config.dictConfig(d)724    lp = threading.Thread(target=logger_thread, args=(q,))725    lp.start()726    # На этом этапе главный процесс может заняться своей полезной работой727    # Когда он с этим закончит, он может дождаться завершения рабочих процессов...728    for wp in workers:729        wp.join()730    # А теперь указать потоку журналирования завершиться731    q.put(None)732    lp.join()733```734735Этот вариант показывает, как можно, например, применить конфигурацию для конкретных логгеров – например, логгер `foo` имеет специальный обработчик, который сохраняет все события подсистемы `foo` в файл `mplog-foo.log`. Это будет использоваться механизмом логирования в главном процессе (даже если события логирования генерируются в рабочих процессах) для направления сообщений в соответствующие места назначения.736737## Использование ротации файлов738739Иногда требуется, чтобы файл журнала увеличивался до определенного размера, затем открывался новый файл и запись велась в него. Возможно, вы захотите сохранять определенное количество таких файлов, и когда будет создано это количество файлов, выполнять ротацию файлов, чтобы количество файлов и их размер оставались ограниченными. Для этого сценария использования в пакете logging предусмотрен `RotatingFileHandler`:740741```python742import glob743import logging744import logging.handlers745746LOG_FILENAME = 'logging_rotatingfile_example.out'747748# Настроить конкретный регистратор с нужным уровнем вывода749my_logger = logging.getLogger('MyLogger')750my_logger.setLevel(logging.DEBUG)751752# Добавить обработчик сообщений журнала в регистратор753handler = logging.handlers.RotatingFileHandler(754              LOG_FILENAME, maxBytes=20, backupCount=5)755756my_logger.addHandler(handler)757758# Записать несколько сообщений759for i in range(20):760    my_logger.debug('i = %d' % i)761762# Посмотреть, какие файлы созданы763logfiles = glob.glob('%s*' % LOG_FILENAME)764765for filename in logfiles:766    print(filename)767```768769В результате должно получиться 6 отдельных файлов, каждый из которых содержит часть истории журнала приложения:770771```python772logging_rotatingfile_example.out773logging_rotatingfile_example.out.1774logging_rotatingfile_example.out.2775logging_rotatingfile_example.out.3776logging_rotatingfile_example.out.4777logging_rotatingfile_example.out.5778```779780Самый текущий файл всегда называется `logging_rotatingfile_example.out`, и каждый раз, когда он достигает предельного размера, он переименовывается с суффиксом `.1`. Каждый из существующих резервных файлов переименовывается для увеличения суффикса (`.1` становится `.2` и т.д.), а файл `.6` удаляется.781782Разумеется, в этом примере размер файла журнала установлен слишком маленьким для наглядности. В реальности нужно установить *maxBytes* в подходящее значение.783784## Использование альтернативных стилей форматирования785786Когда логирование было добавлено в стандартную библиотеку Python, единственным способом форматирования сообщений с переменным содержимым был метод %-форматирования. С тех пор в Python появились два новых подхода к форматированию: [`string.Template`](https://python-all.ru/3.4/library/string.html#string.Template) (добавлено в Python 2.4) и [`str.format()`](https://python-all.ru/3.4/library/stdtypes.html#str.format) (добавлено в Python 2.6).787788Логирование (начиная с версии 3.2) обеспечивает улучшенную поддержку этих двух дополнительных стилей форматирования. Класс `Formatter` был расширен, чтобы принимать дополнительный необязательный именованный параметр с именем `style`. По умолчанию он равен `'%'`, но другими возможными значениями являются `'{'` и `'$'`, которые соответствуют двум другим стилям форматирования. Обратная совместимость поддерживается по умолчанию (как и ожидается), но при явном указании параметра style вы получаете возможность задавать строки формата, которые работают с [`str.format()`](https://python-all.ru/3.4/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.4/library/string.html#string.Template). Вот пример сеанса консоли, показывающий возможности:789790```pycon791>>> import logging792>>> root = logging.getLogger()793>>> root.setLevel(logging.DEBUG)794>>> handler = logging.StreamHandler()795>>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}',796...                        style='{')797>>> handler.setFormatter(bf)798>>> root.addHandler(handler)799>>> logger = logging.getLogger('foo.bar')800>>> logger.debug('This is a DEBUG message')8012010-10-28 15:11:55,341 foo.bar DEBUG    This is a DEBUG message802>>> logger.critical('This is a CRITICAL message')8032010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message804>>> df = logging.Formatter('$asctime $name ${levelname} $message',805...                        style='$')806>>> handler.setFormatter(df)807>>> logger.debug('This is a DEBUG message')8082010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message809>>> logger.critical('This is a CRITICAL message')8102010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message811>>>812```813814Обратите внимание: форматирование сообщений журнала для конечного вывода в файлы совершенно не зависит от того, как конструируется отдельное сообщение. Оно по-прежнему может использовать %-форматирование, как показано ниже:815816```python817>>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')8182010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message819>>>820```821822Вызовы логирования (`logger.debug()`, `logger.info()` и т.д.) принимают только позиционные параметры для самого сообщения логирования, а именованные параметры используются только для определения параметров обработки самого вызова логирования (например, именованный параметр `exc_info` для указания, что следует регистрировать трассировку стека, или именованный параметр `extra` для указания дополнительной контекстной информации, добавляемой в журнал). Поэтому вы не можете напрямую делать вызовы логирования, используя синтаксис [`str.format()`](https://python-all.ru/3.4/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.4/library/string.html#string.Template), потому что внутри пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Это невозможно изменить, сохраняя обратную совместимость, поскольку все существующие вызовы логирования в существующем коде будут использовать %-строки формата.823824Однако есть способ использовать форматирование {}- и $- для построения отдельных сообщений журнала. Напомним, что в качестве строки формата сообщения можно использовать произвольный объект, и пакет logging вызовет `str()` для этого объекта, чтобы получить фактическую строку формата. Рассмотрим следующие два класса:825826```python827class BraceMessage:828    def __init__(self, fmt, *args, **kwargs):829        self.fmt = fmt830        self.args = args831        self.kwargs = kwargs832833    def __str__(self):834        return self.fmt.format(*self.args, **self.kwargs)835836class DollarMessage:837    def __init__(self, fmt, **kwargs):838        self.fmt = fmt839        self.kwargs = kwargs840841    def __str__(self):842        from string import Template843        return Template(self.fmt).substitute(**self.kwargs)844```845846Любой из них можно использовать вместо строки формата, чтобы разрешить {}- или $-форматирование для построения фактической части «message», которая появляется в форматированном выводе журнала вместо «%(message)s» или «{message}» или «$message». Использовать имена классов всякий раз, когда нужно что-то записать, немного неудобно, но вполне приемлемо, если использовать псевдоним, например \_\_ (двойное подчеркивание – не путать с \_, одиночным подчеркиванием, используемым как синоним/псевдоним для [`gettext.gettext()`](https://python-all.ru/3.4/library/gettext.html#gettext.gettext) или его собратьев).847848Вышеуказанные классы не входят в состав Python, но их достаточно легко скопировать и вставить в свой код. Использовать их можно следующим образом (при условии, что они объявлены в модуле с именем `wherever`):849850```pycon851>>> from wherever import BraceMessage as __852>>> print(__('Message with {0} {name}', 2, name='placeholders'))853Message with 2 placeholders854>>> class Point: pass855...856>>> p = Point()857>>> p.x = 0.5858>>> p.y = 0.5859>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})',860...       point=p))861Message with coordinates: (0.50, 0.50)862>>> from wherever import DollarMessage as __863>>> print(__('Message with $num $what', num=2, what='placeholders'))864Message with 2 placeholders865>>>866```867868Хотя в приведённых выше примерах используется `print()` для демонстрации работы форматирования, в реальном логировании, конечно, применяется `logger.debug()` или аналогичный метод.869870Следует отметить, что этот подход не даёт значительного снижения производительности с этим подходом: фактическое форматирование происходит не тогда, когда вы делаете вызов регистрации, а когда (и если) регистрируемое сообщение действительно должно быть выведено в журнал с помощью обработчика. Поэтому единственное, что может сбить с толку, – это то, что скобки ставятся вокруг строки формата и аргументов, а не только вокруг строки формата. Это потому, что нотация \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов XXXMessage.871872При желании можно использовать `LoggerAdapter` для достижения похожего эффекта, как в следующем примере:873874```python875import logging876877class Message(object):878    def __init__(self, fmt, args):879        self.fmt = fmt880        self.args = args881882    def __str__(self):883        return self.fmt.format(*self.args)884885class StyleAdapter(logging.LoggerAdapter):886    def __init__(self, logger, extra=None):887        super(StyleAdapter, self).__init__(logger, extra or {})888889    def log(self, level, msg, *args, **kwargs):890        if self.isEnabledFor(level):891            msg, kwargs = self.process(msg, kwargs)892            self.logger._log(level, Message(msg, args), (), **kwargs)893894logger = StyleAdapter(logging.getLogger(__name__))895896def main():897    logger.debug('Hello, {}', 'world!')898899if __name__ == '__main__':900    logging.basicConfig(level=logging.DEBUG)901    main()902```903904При запуске на Python 3.2 или новее указанный скрипт должен записать в лог сообщение `Hello, world!`.905906## Настройка `LogRecord`907908Каждое событие логирования представлено экземпляром [`LogRecord`](https://python-all.ru/3.4/library/logging.html#logging.LogRecord). Когда событие логируется и не отфильтровывается по уровню регистратора, создаётся [`LogRecord`](https://python-all.ru/3.4/library/logging.html#logging.LogRecord), заполняется информацией о событии и передаётся обработчикам этого регистратора (и его предкам, вплоть до регистратора, у которого дальнейшее распространение вверх по иерархии отключено). До Python 3.2 создание выполнялось только в двух местах:909910- [`Logger.makeRecord()`](https://python-all.ru/3.4/library/logging.html#logging.Logger.makeRecord) – вызывается в обычном процессе записи события. Он напрямую обращался к [`LogRecord`](https://python-all.ru/3.4/library/logging.html#logging.LogRecord) для создания экземпляра.911- [`makeLogRecord()`](https://python-all.ru/3.4/library/logging.html#logging.makeLogRecord), which is called with a dictionary containing attributes to be added to the LogRecord. This is typically invoked when a suitable dictionary has been received over the network (e.g. in pickle form via a [`SocketHandler`](https://python-all.ru/3.4/library/logging.handlers.html#logging.handlers.SocketHandler), or in JSON form via an [`HTTPHandler`](https://python-all.ru/3.4/library/logging.handlers.html#logging.handlers.HTTPHandler)).912913Обычно это означало, что если требуется что-то особенное с [`LogRecord`](https://python-all.ru/3.4/library/logging.html#logging.LogRecord), приходилось делать одно из следующего.914915- Создать собственный подкласс [`Logger`](https://python-all.ru/3.4/library/logging.html#logging.Logger), переопределяющий [`Logger.makeRecord()`](https://python-all.ru/3.4/library/logging.html#logging.Logger.makeRecord), и установить его с помощью [`setLoggerClass()`](https://python-all.ru/3.4/library/logging.html#logging.setLoggerClass) до того, как будут созданы какие-либо нужные регистраторы.916- Добавить [`Filter`](https://python-all.ru/3.4/library/logging.html#logging.Filter) в регистратор или обработчик, который выполняет необходимые специальные манипуляции при вызове его метода [`filter()`](https://python-all.ru/3.4/library/logging.html#logging.Filter.filter).917918Первый подход был бы несколько громоздким, если, скажем, несколько разных библиотек хотели делать разные вещи. Каждая пыталась бы установить собственный подкласс [`Logger`](https://python-all.ru/3.4/library/logging.html#logging.Logger), и победила бы та, которая сделала это последней.919920Второй подход во многих случаях работает достаточно хорошо, но не позволяет, например, использовать специализированный подкласс [`LogRecord`](https://python-all.ru/3.4/library/logging.html#logging.LogRecord). Разработчики библиотек могут установить подходящий фильтр для своих регистраторов, но им придётся помнить об этом каждый раз, когда они создают новый регистратор (что они делают, просто добавляя новые пакеты или модули и выполняя921922```python923logger = logging.getLogger(__name__)924```925926на уровне модуля). Вероятно, это лишняя забота. Разработчики могли бы также добавить фильтр в [`NullHandler`](https://python-all.ru/3.4/library/logging.handlers.html#logging.NullHandler), прикреплённый к их корневому регистратору, но он не будет вызываться, если разработчик приложения присоединит обработчик к нижележащему библиотечному регистратору – тогда вывод этого обработчика не отразит намерений разработчика библиотеки.927928В Python 3.2 и новее создание [`LogRecord`](https://python-all.ru/3.4/library/logging.html#logging.LogRecord) осуществляется через фабрику, которую можно указать. Фабрика – это просто вызываемый объект, который можно установить с помощью [`setLogRecordFactory()`](https://python-all.ru/3.4/library/logging.html#logging.setLogRecordFactory) и запросить через [`getLogRecordFactory()`](https://python-all.ru/3.4/library/logging.html#logging.getLogRecordFactory). Фабрика вызывается с той же сигнатурой, что и конструктор [`LogRecord`](https://python-all.ru/3.4/library/logging.html#logging.LogRecord), поскольку [`LogRecord`](https://python-all.ru/3.4/library/logging.html#logging.LogRecord) является настройкой по умолчанию для фабрики.929930Этот подход позволяет пользовательской фабрике контролировать все аспекты создания LogRecord. Например, можно вернуть подкласс или просто добавить несколько дополнительных атрибутов к записи после ее создания, используя шаблон, подобный следующему:931932```python933old_factory = logging.getLogRecordFactory()934935def record_factory(*args, **kwargs):936    record = old_factory(*args, **kwargs)937    record.custom_attribute = 0xdecafbad938    return record939940logging.setLogRecordFactory(record_factory)941```942943Такой подход позволяет разным библиотекам объединять фабрики в цепочку, и пока они не перезаписывают атрибуты друг друга или случайно не переопределяют стандартные атрибуты, неожиданностей быть не должно. Однако следует помнить, что каждое звено в цепочке добавляет дополнительные накладные расходы во время выполнения всех операций логирования, и этот метод следует использовать только тогда, когда применение [`Filter`](https://python-all.ru/3.4/library/logging.html#logging.Filter) не даёт желаемого результата.944945## Создание подкласса QueueHandler – пример с ZeroMQ946947Можно использовать подкласс `QueueHandler` для отправки сообщений в очереди других типов, например, в сокет «публикации» ZeroMQ. В примере ниже сокет создаётся отдельно и передаётся обработчику (в качестве его «очереди»):948949```python950import zmq # с использованием pyzmq, привязки Python к ZeroMQ951import json # для переносимой сериализации записей952953ctx = zmq.Context()954sock = zmq.Socket(ctx, zmq.PUB) # или zmq.PUSH, или другое подходящее значение955sock.bind('tcp://*:5556') # или где угодно956957class ZeroMQSocketHandler(QueueHandler):958    def enqueue(self, record):959        data = json.dumps(record.__dict__)960        self.queue.send(data)961962handler = ZeroMQSocketHandler(sock)963```964965Конечно, есть и другие способы организации этого, например, передача данных, необходимых обработчику для создания сокета:966967```python968class ZeroMQSocketHandler(QueueHandler):969    def __init__(self, uri, socktype=zmq.PUB, ctx=None):970        self.ctx = ctx or zmq.Context()971        socket = zmq.Socket(self.ctx, socktype)972        socket.bind(uri)973        QueueHandler.__init__(self, socket)974975    def enqueue(self, record):976        data = json.dumps(record.__dict__)977        self.queue.send(data)978979    def close(self):980        self.queue.close()981```982983## Создание подкласса QueueListener – пример с ZeroMQ984985Также можно создать подкласс `QueueListener` для получения сообщений из очередей других типов, например, из сокета «подписки» ZeroMQ. Вот пример:986987```python988class ZeroMQSocketListener(QueueListener):989    def __init__(self, uri, *handlers, **kwargs):990        self.ctx = kwargs.get('ctx') or zmq.Context()991        socket = zmq.Socket(self.ctx, zmq.SUB)992        socket.setsockopt(zmq.SUBSCRIBE, '') # подписаться на всё993        socket.connect(uri)994995    def dequeue(self):996        msg = self.queue.recv()997        return logging.makeLogRecord(json.loads(msg))998```9991000> **См. также**1001>1002> **Модуль [`logging`](https://python-all.ru/3.4/library/logging.html#module-logging)**1003>1004> Справочник API для модуля logging.1005>1006> **Модуль [`logging.config`](https://python-all.ru/3.4/library/logging.config.html#module-logging.config)**1007>1008> API конфигурации для модуля logging.1009>1010> **Модуль [`logging.handlers`](https://python-all.ru/3.4/library/logging.handlers.html#module-logging.handlers)**1011>1012> Полезные обработчики, входящие в состав модуля logging.1013>1014> [*Базовое руководство по логированию*](https://python-all.ru/3.4/howto/logging.html#logging-basic-tutorial)1015>1016> [*Более продвинутое руководство по логированию*](https://python-all.ru/3.4/howto/logging.html#logging-advanced-tutorial)10171018## Пример конфигурации на основе словаря10191020Ниже приведён пример словаря конфигурации логирования – он взят из [документации проекта Django](https://python-all.ru/3.4/howto/logging-cookbook.html). Этот словарь передаётся в [`dictConfig()`](https://python-all.ru/3.4/library/logging.config.html#logging.config.dictConfig) для применения конфигурации:10211022```python1023LOGGING = {1024    'version': 1,1025    'disable_existing_loggers': True,1026    'formatters': {1027        'verbose': {1028            'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'1029        },1030        'simple': {1031            'format': '%(levelname)s %(message)s'1032        },1033    },1034    'filters': {1035        'special': {1036            '()': 'project.logging.SpecialFilter',1037            'foo': 'bar',1038        }1039    },1040    'handlers': {1041        'null': {1042            'level':'DEBUG',1043            'class':'django.utils.log.NullHandler',1044        },1045        'console':{1046            'level':'DEBUG',1047            'class':'logging.StreamHandler',1048            'formatter': 'simple'1049        },1050        'mail_admins': {1051            'level': 'ERROR',1052            'class': 'django.utils.log.AdminEmailHandler',1053            'filters': ['special']1054        }1055    },1056    'loggers': {1057        'django': {1058            'handlers':['null'],1059            'propagate': True,1060            'level':'INFO',1061        },1062        'django.request': {1063            'handlers': ['mail_admins'],1064            'level': 'ERROR',1065            'propagate': False,1066        },1067        'myproject.custom': {1068            'handlers': ['console', 'mail_admins'],1069            'level': 'INFO',1070            'filters': ['special']1071        }1072    }1073}1074```10751076Для получения дополнительной информации об этой конфигурации можно обратиться к [соответствующему разделу](https://python-all.ru/3.4/howto/logging-cookbook.html) документации Django.10771078## Использование ротатора и средства именования для настройки обработки ротации журналов10791080Пример того, как можно определить namer и rotator, приведен в следующем фрагменте кода, который демонстрирует сжатие журнала с использованием zlib:10811082```python1083def namer(name):1084    return name + ".gz"10851086def rotator(source, dest):1087    with open(source, "rb") as sf:1088        data = sf.read()1089        compressed = zlib.compress(data, 9)1090        with open(dest, "wb") as df:1091            df.write(compressed)1092    os.remove(source)10931094rh = logging.handlers.RotatingFileHandler(...)1095rh.rotator = rotator1096rh.namer = namer1097```10981099Это не «настоящие» .gz-файлы, поскольку они представляют собой просто сжатые данные без «контейнера», который присутствует в обычном gzip-файле. Данный фрагмент приведен только для иллюстрации.11001101## Более сложный пример с многопроцессностью11021103Следующий рабочий пример показывает, как можно использовать логирование с многопроцессностью с помощью файлов конфигурации. Конфигурации довольно просты, но служат иллюстрацией того, как можно реализовать более сложные в реальном сценарии многопроцессной обработки.11041105В примере главный процесс порождает процесс-слушатель и несколько рабочих процессов. Каждый из главного процесса, слушателя и рабочих имеет три отдельные конфигурации (все рабочие используют одну и ту же конфигурацию). Видно ведение журнала в главном процессе, как рабочие пишут в QueueHandler, а слушатель реализует QueueListener и более сложную конфигурацию ведения журнала, и организует отправку событий, полученных через очередь, обработчикам, указанным в конфигурации. Обратите внимание, что эти конфигурации чисто иллюстративные, но этот пример можно адаптировать под свой сценарий.11061107Вот скрипт – строки документации и комментарии, надеюсь, поясняют, как он работает:11081109```python1110import logging1111import logging.config1112import logging.handlers1113from multiprocessing import Process, Queue, Event, current_process1114import os1115import random1116import time11171118class MyHandler:1119    """1120    Простой обработчик для событий логирования. Он выполняется в процессе-слушателе и1121    распределяет события по логгерам на основе имени в полученной записи,1122    которые затем передаются системой логирования обработчикам,1123    настроенным для этих логгеров.1124    """1125    def handle(self, record):1126        logger = logging.getLogger(record.name)1127        # Имя процесса преобразуется только для того, чтобы показать, что это слушатель1128        # выполняет логирование в файлы и консоль.1129        record.processName = '%s (for %s)' % (current_process().name, record.processName)1130        logger.handle(record)11311132def listener_process(q, stop_event, config):1133    """1134    Это можно было бы сделать в главном процессе, но сделано в отдельном1135    процессе для наглядности.11361137    Это инициализирует логирование согласно указанной конфигурации1138    запускает слушатель и ожидает сигнала от главного процесса о завершении1139    через событие. Затем слушатель останавливается, и процесс завершается.1140    """1141    logging.config.dictConfig(config)1142    listener = logging.handlers.QueueListener(q, MyHandler())1143    listener.start()1144    if os.name == 'posix':1145        # В POSIX логгер setup уже был настроен в1146        # родительском процессе, но должен был быть отключён после вызова1147        # dictConfig.1148        # В Windows, поскольку fork не используется, логгер setup не будет1149        # существовать в дочернем процессе, поэтому он будет создан, и сообщение1150        # появится – отсюда и конструкция "if posix".1151        logger = logging.getLogger('setup')1152        logger.critical('Should not appear, because of disabled logger ...')1153    stop_event.wait()1154    listener.stop()11551156def worker_process(config):1157    """1158    Некоторое количество таких процессов порождается для иллюстрации. На1159    практике это могла бы быть разнородная группа процессов, а не1160    идентичные друг другу.11611162    Это инициализирует логирование согласно указанной конфигурации1163    и записывает сотню сообщений со случайными уровнями в случайно выбранные1164    логгеры.11651166    Добавлена небольшая задержка, чтобы дать другим процессам шанс выполниться. Это1167    не является строго необходимым, но позволяет немного перемешать вывод от разных1168    процессов больше, чем если бы её не было.1169    """1170    logging.config.dictConfig(config)1171    levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1172              logging.CRITICAL]1173    loggers = ['foo', 'foo.bar', 'foo.bar.baz',1174               'spam', 'spam.ham', 'spam.ham.eggs']1175    if os.name == 'posix':1176        # В POSIX логгер setup уже был настроен в1177        # родительском процессе, но должен был быть отключён после вызова1178        # dictConfig.1179        # В Windows, поскольку fork не используется, логгер setup не будет1180        # существовать в дочернем процессе, поэтому он будет создан, и сообщение1181        # появится – отсюда и конструкция "if posix".1182        logger = logging.getLogger('setup')1183        logger.critical('Should not appear, because of disabled logger ...')1184    for i in range(100):1185        lvl = random.choice(levels)1186        logger = logging.getLogger(random.choice(loggers))1187        logger.log(lvl, 'Message no. %d', i)1188        time.sleep(0.01)11891190def main():1191    q = Queue()1192    # Главный процесс получает простую конфигурацию, которая выводит информацию в консоль.1193    config_initial = {1194        'version': 1,1195        'formatters': {1196            'detailed': {1197                'class': 'logging.Formatter',1198                'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1199            }1200        },1201        'handlers': {1202            'console': {1203                'class': 'logging.StreamHandler',1204                'level': 'INFO',1205            },1206        },1207        'root': {1208            'level': 'DEBUG',1209            'handlers': ['console']1210        },1211    }1212    # Конфигурация рабочего процесса представляет собой QueueHandler, прикреплённый к1213    # корневому логгеру, что позволяет отправлять все сообщения в очередь.1214    # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1215    # родительском процессе. Это необходимо в POSIX, потому что логгер будет1216    # присутствовать в дочернем процессе после вызова fork().1217    config_worker = {1218        'version': 1,1219        'disable_existing_loggers': True,1220        'handlers': {1221            'queue': {1222                'class': 'logging.handlers.QueueHandler',1223                'queue': q,1224            },1225        },1226        'root': {1227            'level': 'DEBUG',1228            'handlers': ['queue']1229        },1230    }1231    # Конфигурация процесса-слушателя показывает, что вся гибкость1232    # конфигурации логирования доступна для отправки событий обработчикам так, как1233    # требуется.1234    # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1235    # родительском процессе. Это необходимо в POSIX, потому что логгер будет1236    # присутствовать в дочернем процессе после вызова fork().1237    config_listener = {1238        'version': 1,1239        'disable_existing_loggers': True,1240        'formatters': {1241            'detailed': {1242                'class': 'logging.Formatter',1243                'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1244            },1245            'simple': {1246                'class': 'logging.Formatter',1247                'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1248            }1249        },1250        'handlers': {1251            'console': {1252                'class': 'logging.StreamHandler',1253                'level': 'INFO',1254                'formatter': 'simple',1255            },1256            'file': {1257                'class': 'logging.FileHandler',1258                'filename': 'mplog.log',1259                'mode': 'w',1260                'formatter': 'detailed',1261            },1262            'foofile': {1263                'class': 'logging.FileHandler',1264                'filename': 'mplog-foo.log',1265                'mode': 'w',1266                'formatter': 'detailed',1267            },1268            'errors': {1269                'class': 'logging.FileHandler',1270                'filename': 'mplog-errors.log',1271                'mode': 'w',1272                'level': 'ERROR',1273                'formatter': 'detailed',1274            },1275        },1276        'loggers': {1277            'foo': {1278                'handlers': ['foofile']1279            }1280        },1281        'root': {1282            'level': 'DEBUG',1283            'handlers': ['console', 'file', 'errors']1284        },1285    }1286    # Записываем несколько начальных событий, просто чтобы показать, что логирование в родительском процессе работает1287    # нормально.1288    logging.config.dictConfig(config_initial)1289    logger = logging.getLogger('setup')1290    logger.info('About to create workers ...')1291    workers = []1292    for i in range(5):1293        wp = Process(target=worker_process, name='worker %d' % (i + 1),1294                     args=(config_worker,))1295        workers.append(wp)1296        wp.start()1297        logger.info('Started worker: %s', wp.name)1298    logger.info('About to create listener ...')1299    stop_event = Event()1300    lp = Process(target=listener_process, name='listener',1301                 args=(q, stop_event, config_listener))1302    lp.start()1303    logger.info('Started listener')1304    # Теперь ожидаем завершения работы рабочих процессов.1305    for wp in workers:1306        wp.join()1307    # Все рабочие процессы завершены, теперь можно остановить прослушивание.1308    # Логирование в родительском процессе всё ещё работает нормально.1309    logger.info('Telling listener to stop ...')1310    stop_event.set()1311    lp.join()1312    logger.info('All done.')13131314if __name__ == '__main__':1315    main()1316```13171318## Вставка BOM в сообщения, отправляемые в SysLogHandler13191320[RFC 5424](https://python-all.ru/3.4/howto/logging-cookbook.html) требует, чтобы Unicode-сообщение отправлялось демону syslog в виде набора байтов следующей структуры: необязательный компонент, состоящий только из ASCII, затем метка порядка байтов (BOM) UTF-8, затем Unicode, закодированный в UTF-8. (См. [соответствующий раздел спецификации](https://python-all.ru/3.4/howto/logging-cookbook.html).)13211322В Python 3.1 в [`SysLogHandler`](https://python-all.ru/3.4/library/logging.handlers.html#logging.handlers.SysLogHandler) был добавлен код для вставки метки BOM в сообщение, но, к сожалению, он был реализован неправильно: BOM появлялся в начале сообщения, не позволяя никакому чисто ASCII-компоненту находиться перед ним.13231324Поскольку такое поведение некорректно, код, неправильно вставляющий BOM, удаляется из Python 3.2.4 и более поздних версий. Однако он не заменяется, и если требуется создавать сообщения, совместимые с RFC 5424, которые содержат BOM, необязательную последовательность символов только из ASCII перед ним и произвольный Unicode после него, закодированные в UTF-8, то необходимо сделать следующее:132513261. Прикрепите экземпляр [`Formatter`](https://python-all.ru/3.4/library/logging.html#logging.Formatter) к своему экземпляру [`SysLogHandler`](https://python-all.ru/3.4/library/logging.handlers.html#logging.handlers.SysLogHandler) со строкой формата, например:13271328   ```python1329   'ASCII section\ufeffUnicode section'1330   ```13311332   Кодовая точка Unicode U+FEFF при кодировании UTF-8 будет закодирована как метка BOM UTF-8 – строка байтов `b'\xef\xbb\xbf'`.13332. ASCII-часть следует заменить на любые подходящие заполнители, но необходимо следить, чтобы данные, которые появляются там после подстановки, всегда были в ASCII (таким образом, они останутся без изменений после кодирования UTF-8).13343. Unicode-часть следует заменить на любые заполнители; если данные после подстановки содержат символы за пределами диапазона ASCII, это нормально – они будут закодированы в UTF-8.13351336Отформатированное сообщение *будет* закодировано `SysLogHandler` в кодировке UTF-8. Если соблюдать приведённые выше правила, можно создавать сообщения, совместимые с RFC 5424. В противном случае логирование может не жаловаться, но сообщения не будут соответствовать RFC 5424, и ваш демон syslog может начать жаловаться.13371338## Реализация структурированного ведения журнала13391340Хотя большинство сообщений лога предназначены для чтения человеком и поэтому нелегко разбираются машиной, могут возникнуть ситуации, когда нужно выводить сообщения в структурированном формате, *который* может быть проанализирован программой (без необходимости сложных регулярных выражений для разбора сообщения лога). Это легко достигается с помощью пакета logging. Есть несколько способов это сделать, но ниже приведён простой подход, использующий JSON для сериализации события в машиночитаемом виде:13411342```python1343import json1344import logging13451346class StructuredMessage(object):1347    def __init__(self, message, **kwargs):1348        self.message = message1349        self.kwargs = kwargs13501351    def __str__(self):1352        return '%s >>> %s' % (self.message, json.dumps(self.kwargs))13531354_ = StructuredMessage   # необязательно, для улучшения читаемости13551356logging.basicConfig(level=logging.INFO, format='%(message)s')1357logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))1358```13591360Если запустить приведённый выше скрипт, он выведет:13611362```python1363message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}1364```13651366Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.13671368Если требуется более специализированная обработка, можно использовать пользовательский кодировщик JSON, как в следующем полном примере:13691370```python1371from __future__ import unicode_literals13721373import json1374import logging13751376# Следующий фрагмент предназначен для того, чтобы скрипт работал без изменений в версиях 2.x и 3.x.1377try:1378    unicode1379except NameError:1380    unicode = str13811382class Encoder(json.JSONEncoder):1383    def default(self, o):1384        if isinstance(o, set):1385            return tuple(o)1386        elif isinstance(o, unicode):1387            return o.encode('unicode_escape').decode('ascii')1388        return super(Encoder, self).default(o)13891390class StructuredMessage(object):1391    def __init__(self, message, **kwargs):1392        self.message = message1393        self.kwargs = kwargs13941395    def __str__(self):1396        s = Encoder().encode(self.kwargs)1397        return '%s >>> %s' % (self.message, s)13981399_ = StructuredMessage   # необязательно, для улучшения читаемости14001401def main():1402    logging.basicConfig(level=logging.INFO, format='%(message)s')1403    logging.info(_('message 1', set_value=set([1, 2, 3]), snowman='\u2603'))14041405if __name__ == '__main__':1406    main()1407```14081409При запуске приведённого выше скрипта он выведет:14101411```python1412message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}1413```14141415Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.14161417## Настройка обработчиков с помощью [`dictConfig()`](https://python-all.ru/3.4/library/logging.config.html#logging.config.dictConfig)14181419Иногда требуется настроить обработчики логирования особым образом, и при использовании [`dictConfig()`](https://python-all.ru/3.4/library/logging.config.html#logging.config.dictConfig) это можно сделать без создания подклассов. Например, можно задать владельца файла журнала. В POSIX это легко делается с помощью [`shutil.chown()`](https://python-all.ru/3.4/library/shutil.html#shutil.chown), но файловые обработчики в стандартной библиотеке не имеют встроенной поддержки. Создание обработчика можно настроить с помощью обычной функции, например:14201421```python1422def owned_file_handler(filename, mode='a', encoding=None, owner=None):1423    if owner:1424        if not os.path.exists(filename):1425            open(filename, 'a').close()1426        shutil.chown(filename, *owner)1427    return logging.FileHandler(filename, mode, encoding)1428```14291430Затем в конфигурации логирования, передаваемой в [`dictConfig()`](https://python-all.ru/3.4/library/logging.config.html#logging.config.dictConfig), можно указать, что обработчик должен быть создан вызовом этой функции:14311432```python1433LOGGING = {1434    'version': 1,1435    'disable_existing_loggers': False,1436    'formatters': {1437        'default': {1438            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'1439        },1440    },1441    'handlers': {1442        'file':{1443            # Значения ниже извлекаются из этого словаря и1444            # используются для создания обработчика, установки его уровня и1445            # его форматтера.1446            '()': owned_file_handler,1447            'level':'DEBUG',1448            'formatter': 'default',1449            # Значения ниже передаются вызываемому объекту-создателю обработчика1450            # в качестве именованных аргументов.1451            'owner': ['pulse', 'pulse'],1452            'filename': 'chowntest.log',1453            'mode': 'w',1454            'encoding': 'utf-8',1455        },1456    },1457    'root': {1458        'handlers': ['file'],1459        'level': 'DEBUG',1460    },1461}1462```14631464В этом примере я устанавливаю владельца через пользователя и группу `pulse` – только для иллюстрации. Собирая всё вместе в рабочий скрипт `chowntest.py`:14651466```python1467import logging, logging.config, os, shutil14681469def owned_file_handler(filename, mode='a', encoding=None, owner=None):1470    if owner:1471        if not os.path.exists(filename):1472            open(filename, 'a').close()1473        shutil.chown(filename, *owner)1474    return logging.FileHandler(filename, mode, encoding)14751476LOGGING = {1477    'version': 1,1478    'disable_existing_loggers': False,1479    'formatters': {1480        'default': {1481            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'1482        },1483    },1484    'handlers': {1485        'file':{1486            # Значения ниже извлекаются из этого словаря и1487            # используются для создания обработчика, установки его уровня и1488            # его форматтера.1489            '()': owned_file_handler,1490            'level':'DEBUG',1491            'formatter': 'default',1492            # Значения ниже передаются вызываемому объекту-создателю обработчика1493            # в качестве именованных аргументов.1494            'owner': ['pulse', 'pulse'],1495            'filename': 'chowntest.log',1496            'mode': 'w',1497            'encoding': 'utf-8',1498        },1499    },1500    'root': {1501        'handlers': ['file'],1502        'level': 'DEBUG',1503    },1504}15051506logging.config.dictConfig(LOGGING)1507logger = logging.getLogger('mylogger')1508logger.debug('A debug message')1509```15101511Чтобы запустить это, возможно, потребуется выполнить от имени `root`:15121513```python1514$ sudo python3.3 chowntest.py1515$ cat chowntest.log15162013-11-05 09:34:51,128 DEBUG mylogger A debug message1517$ ls -l chowntest.log1518-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log1519```15201521Обратите внимание, что в этом примере используется Python 3.3, так как именно в нём появилась функция [`shutil.chown()`](https://python-all.ru/3.4/library/shutil.html#shutil.chown). Этот подход должен работать с любой версией Python, которая поддерживает [`dictConfig()`](https://python-all.ru/3.4/library/logging.config.html#logging.config.dictConfig) – а именно Python 2.7, 3.2 и выше. В версиях до 3.3 вам потребуется реализовать смену владельца, например, с помощью [`os.chown()`](https://python-all.ru/3.4/library/os.html#os.chown).15221523На практике функция создания обработчика может находиться в служебном модуле где-нибудь в вашем проекте. Вместо строки в конфигурации:15241525```python1526'()': owned_file_handler,1527```15281529можно использовать, например:15301531```python1532'()': 'ext://project.util.owned_file_handler',1533```15341535где `project.util` можно заменить на фактическое имя пакета, в котором находится функция. В приведённом выше рабочем скрипте должно сработать использование `'ext://__main__.owned_file_handler'`. Здесь фактическая вызываемая сущность разрешается функцией [`dictConfig()`](https://python-all.ru/3.4/library/logging.config.html#logging.config.dictConfig) из спецификации `ext://`.15361537Надеемся, этот пример также показывает, как можно реализовать другие типы изменений файлов (например, установку определённых битов разрешений POSIX) тем же способом, с помощью [`os.chmod()`](https://python-all.ru/3.4/library/os.html#os.chmod).15381539Конечно, этот подход можно расширить и на другие типы обработчиков, отличные от [`FileHandler`](https://python-all.ru/3.4/library/logging.handlers.html#logging.FileHandler) – например, на один из ротационных файловых обработчиков или на совершенно другой тип обработчика.15401541## Использование определённых стилей форматирования во всём приложении15421543В Python 3.2 у [`Formatter`](https://python-all.ru/3.4/library/logging.html#logging.Formatter) появился именованный параметр `style`, который по умолчанию равен `%` для обратной совместимости, но позволяет указать `{` или `$` для поддержки подходов форматирования, используемых в [`str.format()`](https://python-all.ru/3.4/library/stdtypes.html#str.format) и [`string.Template`](https://python-all.ru/3.4/library/string.html#string.Template). Обратите внимание, что это управляет форматированием сообщений журнала для финального вывода в журнал и совершенно независимо от того, как конструируется отдельное сообщение для записи.15441545Вызовы журналирования ([`debug()`](https://python-all.ru/3.4/library/logging.html#logging.Logger.debug), [`info()`](https://python-all.ru/3.4/library/logging.html#logging.Logger.info) и т.д.) принимают только позиционные параметры для самого сообщения журнала; именованные параметры используются только для определения параметров обработки вызова (например, именованный параметр `exc_info` указывает, что нужно записывать информацию о трассировке, или `extra` для добавления дополнительной контекстной информации в журнал). Поэтому нельзя напрямую использовать синтаксис [`str.format()`](https://python-all.ru/3.4/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.4/library/string.html#string.Template) в вызовах журналирования, потому что внутри пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Изменить это, сохранив обратную совместимость, невозможно, так как все существующие вызовы в коде используют %-формат.15461547Высказывались предложения связывать стили форматирования с конкретными регистраторами, но этот подход также сталкивается с проблемами обратной совместимости, поскольку любой существующий код может использовать данное имя регистратора и %-форматирование.15481549Чтобы логирование работало совместимо между любыми сторонними библиотеками и вашим кодом, решения о форматировании необходимо принимать на уровне отдельного вызова логирования. Это открывает несколько способов, которыми можно реализовать альтернативные стили форматирования.15501551### Использование фабрик LogRecord15521553В Python 3.2, вместе с изменениями [`Formatter`](https://python-all.ru/3.4/library/logging.html#logging.Formatter), упомянутыми выше, пакет logging получил возможность позволять пользователям задавать собственные подклассы [`LogRecord`](https://python-all.ru/3.4/library/logging.html#logging.LogRecord) с помощью функции [`setLogRecordFactory()`](https://python-all.ru/3.4/library/logging.html#logging.setLogRecordFactory). Это можно использовать для установки собственного подкласса [`LogRecord`](https://python-all.ru/3.4/library/logging.html#logging.LogRecord), который делает правильные вещи, переопределяя метод [`getMessage()`](https://python-all.ru/3.4/library/logging.html#logging.LogRecord.getMessage). В реализации базового класса этого метода происходит форматирование `msg % args`, и здесь можно подставить своё альтернативное форматирование; однако нужно быть осторожным, чтобы поддерживать все стили форматирования и оставить %-форматирование по умолчанию, чтобы обеспечить совместимость с другим кодом. Также следует не забыть вызвать `str(self.msg)`, как это делает базовая реализация.15541555Обратитесь к справочной документации по [`setLogRecordFactory()`](https://python-all.ru/3.4/library/logging.html#logging.setLogRecordFactory) и [`LogRecord`](https://python-all.ru/3.4/library/logging.html#logging.LogRecord) для получения дополнительной информации.15561557### Использование пользовательских объектов сообщений15581559Существует ещё один, возможно, более простой способ использовать {}- и $-форматирование для построения отдельных сообщений журнала. Возможно, вы помните (из раздела [*Использование произвольных объектов в качестве сообщений*](https://python-all.ru/3.4/howto/logging.html#arbitrary-object-messages)), что при журналировании можно использовать произвольный объект в качестве строки формата сообщения, и пакет logging вызовет [`str()`](https://python-all.ru/3.4/library/stdtypes.html#str) для этого объекта, чтобы получить фактическую строку формата. Рассмотрим следующие два класса:15601561```python1562class BraceMessage(object):1563    def __init__(self, fmt, *args, **kwargs):1564        self.fmt = fmt1565        self.args = args1566        self.kwargs = kwargs15671568    def __str__(self):1569        return self.fmt.format(*self.args, **self.kwargs)15701571class DollarMessage(object):1572    def __init__(self, fmt, **kwargs):1573        self.fmt = fmt1574        self.kwargs = kwargs15751576    def __str__(self):1577        from string import Template1578        return Template(self.fmt).substitute(**self.kwargs)1579```15801581Любой из них можно использовать вместо строки формата, чтобы с помощью {}- или $-форматирования строить фактическую часть «message», которая появляется в отформатированном выводе журнала вместо «%(message)s», «{message}» или «$message». Если использовать имена классов каждый раз, когда нужно что-то записать, кажется громоздким, можно сделать это более удобным, используя псевдоним, например `M` или `_` для сообщения (или, возможно, `__`, если вы используете `_` для локализации).15821583Примеры этого подхода приведены ниже. Сначала форматирование с помощью [`str.format()`](https://python-all.ru/3.4/library/stdtypes.html#str.format):15841585```python1586>>> __ = BraceMessage1587>>> print(__('Message with {0} {1}', 2, 'placeholders'))1588Message with 2 placeholders1589>>> class Point: pass1590...1591>>> p = Point()1592>>> p.x = 0.51593>>> p.y = 0.51594>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))1595Message with coordinates: (0.50, 0.50)1596```15971598Затем форматирование с помощью [`string.Template`](https://python-all.ru/3.4/library/string.html#string.Template):15991600```python1601>>> __ = DollarMessage1602>>> print(__('Message with $num $what', num=2, what='placeholders'))1603Message with 2 placeholders1604>>>1605```16061607Стоит отметить, что при таком подходе нет значительного снижения производительности: фактическое форматирование происходит не в момент вызова журналирования, а когда (и если) сообщение должно быть выведено в журнал обработчиком. Единственная необычная деталь, которая может сбить с толку, – скобки окружают строку формата и аргументы, а не только строку формата. Это связано с тем, что нотация \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов `XXXMessage`, показанных выше.16081609## Настройка фильтров с помощью [`dictConfig()`](https://python-all.ru/3.4/library/logging.config.html#logging.config.dictConfig)16101611Фильтры *можно* настраивать с помощью [`dictConfig()`](https://python-all.ru/3.4/library/logging.config.html#logging.config.dictConfig), хотя с первого взгляда может быть неочевидно, как это сделать (поэтому и приведён этот рецепт). Поскольку [`Filter`](https://python-all.ru/3.4/library/logging.html#logging.Filter) – единственный класс фильтра, входящий в стандартную библиотеку, и вряд ли он удовлетворит все потребности (он существует только как базовый класс), обычно потребуется определить собственный подкласс [`Filter`](https://python-all.ru/3.4/library/logging.html#logging.Filter) с переопределённым методом [`filter()`](https://python-all.ru/3.4/library/logging.html#logging.Filter.filter). Для этого укажите ключ `()` в словаре конфигурации для фильтра, задав вызываемый объект, который будет использоваться для создания фильтра (класс – самый очевидный вариант, но можно указать любой вызываемый объект, возвращающий экземпляр [`Filter`](https://python-all.ru/3.4/library/logging.html#logging.Filter)). Вот полный пример:16121613```python1614import logging1615import logging.config1616import sys16171618class MyFilter(logging.Filter):1619    def __init__(self, param=None):1620        self.param = param16211622    def filter(self, record):1623        if self.param is None:1624            allow = True1625        else:1626            allow = self.param not in record.msg1627        if allow:1628            record.msg = 'changed: ' + record.msg1629        return allow16301631LOGGING = {1632    'version': 1,1633    'filters': {1634        'myfilter': {1635            '()': MyFilter,1636            'param': 'noshow',1637        }1638    },1639    'handlers': {1640        'console': {1641            'class': 'logging.StreamHandler',1642            'filters': ['myfilter']1643        }1644    },1645    'root': {1646        'level': 'DEBUG',1647        'handlers': ['console']1648    },1649}16501651if __name__ == '__main__':1652    logging.config.dictConfig(LOGGING)1653    logging.debug('hello')1654    logging.debug('hello - noshow')1655```16561657Этот пример показывает, как можно передавать конфигурационные данные вызываемому объекту, который создает экземпляр, в виде именованных параметров. При запуске приведенный выше скрипт выведет:16581659```python1660changed: hello1661```16621663что показывает, что фильтр работает в соответствии с настройками.16641665Несколько дополнительных моментов, на которые стоит обратить внимание:16661667- Если нет возможности сослаться на вызываемый объект непосредственно в конфигурации (например, он находится в другом модуле и его нельзя импортировать напрямую в месте, где находится словарь конфигурации), можно использовать форму `ext://...`, как описано в разделе [*Доступ к внешним объектам*](https://python-all.ru/3.4/library/logging.config.html#logging-config-dict-externalobj). Например, в приведённом выше примере можно было использовать текст `'ext://__main__.MyFilter'` вместо `MyFilter`.1668- Помимо фильтров, этот метод также можно использовать для настройки пользовательских обработчиков и форматтеров. Смотрите раздел [*Пользовательские объекты*](https://python-all.ru/3.4/library/logging.config.html#logging-config-dict-userdef) для получения дополнительной информации о том, как logging поддерживает использование пользовательских объектов в своей конфигурации, а также см. другой рецепт из этой книги рецептов [*Настройка обработчиков с помощью dictConfig()*](https://python-all.ru/3.4/howto/logging-cookbook.html#custom-handlers) выше.16691670## Настраиваемое форматирование исключений16711672Могут возникнуть ситуации, когда вы захотите настроить форматирование исключений – для примера, предположим, вы хотите ровно одну строку на каждое событие лога, даже если присутствует информация об исключении. Вы можете сделать это с помощью пользовательского класса форматтера, как показано в следующем примере:16731674```python1675import logging16761677class OneLineExceptionFormatter(logging.Formatter):1678    def formatException(self, exc_info):1679        """1680        Форматировать исключение так, чтобы оно выводилось одной строкой.1681        """1682        result = super(OneLineExceptionFormatter, self).formatException(exc_info)1683        return repr(result) # или форматировать одной строкой по своему усмотрению16841685    def format(self, record):1686        s = super(OneLineExceptionFormatter, self).format(record)1687        if record.exc_text:1688            s = s.replace('\n', '') + '|'1689        return s16901691def configure_logging():1692    fh = logging.FileHandler('output.txt', 'w')1693    f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',1694                                  '%d/%m/%Y %H:%M:%S')1695    fh.setFormatter(f)1696    root = logging.getLogger()1697    root.setLevel(logging.DEBUG)1698    root.addHandler(fh)16991700def main():1701    configure_logging()1702    logging.info('Sample message')1703    try:1704        x = 1 / 01705    except ZeroDivisionError as e:1706        logging.exception('ZeroDivisionError: %s', e)17071708if __name__ == '__main__':1709    main()1710```17111712При запуске это создает файл ровно с двумя строками:17131714```python171528/01/2015 07:21:23|INFO|Sample message|171628/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'|1717```17181719Хотя описанный выше подход упрощён, он показывает, как можно форматировать информацию об исключениях по своему усмотрению. Модуль [`traceback`](https://python-all.ru/3.4/library/traceback.html#module-traceback) может быть полезен для более специализированных нужд.17201721## Озвучивание сообщений лога17221723Могут возникнуть ситуации, когда сообщения журнала желательно воспроизводить в звуковом, а не в видимом формате. Это легко сделать, если в вашей системе доступна функция преобразования текста в речь (TTS), даже если у неё нет привязки к Python. У большинства TTS-систем есть программа командной строки, которую можно запустить, и её можно вызвать из обработчика с помощью [`подпроцесса`](https://python-all.ru/3.4/library/subprocess.html#module-subprocess). Предполагается, что программы командной строки TTS не ожидают взаимодействия с пользователем и не требуют много времени для выполнения, а частота сообщений журнала не настолько высока, чтобы заваливать пользователя сообщениями, и что приемлемо воспроизводить сообщения по одному, а не одновременно. Приведённый ниже пример реализации ожидает завершения озвучивания одного сообщения, прежде чем обработать следующее, что может задерживать другие обработчики. Вот краткий пример, демонстрирующий подход, в котором предполагается, что доступен TTS-пакет `espeak`:17241725```python1726import logging1727import subprocess1728import sys17291730class TTSHandler(logging.Handler):1731    def emit(self, record):1732        msg = self.format(record)1733        # Говорить медленно женским английским голосом.1734        cmd = ['espeak', '-s150', '-ven+f3', msg]1735        p = subprocess.Popen(cmd, stdout=subprocess.PIPE,1736                             stderr=subprocess.STDOUT)1737        # дождаться завершения программы1738        p.communicate()17391740def configure_logging():1741    h = TTSHandler()1742    root = logging.getLogger()1743    root.addHandler(h)1744    # стандартный форматтер просто возвращает сообщение1745    root.setLevel(logging.DEBUG)17461747def main():1748    logging.info('Hello')1749    logging.debug('Goodbye')17501751if __name__ == '__main__':1752    configure_logging()1753    sys.exit(main())1754```17551756При запуске этот скрипт должен сказать «Hello», а затем «Goodbye» женским голосом.17571758Описанный выше подход, конечно, можно адаптировать для других TTS-систем и даже для других систем, которые могут обрабатывать сообщения через внешние программы, запускаемые из командной строки.17591760## Буферизация сообщений лога и условный вывод17611762Могут возникнуть ситуации, когда вы хотите записывать сообщения во временную область и выводить их только при наступлении определенного условия. Например, вы можете начать запись отладочных событий в функции, и если функция завершится без ошибок, вы не захотите засорять лог собранной отладочной информацией, но если возникнет ошибка, вы захотите вывести всю отладочную информацию вместе с ошибкой.17631764Вот пример, показывающий, как это можно сделать с помощью декоратора для функций, в которых требуется такое поведение журналирования. В нём используется [`logging.handlers.MemoryHandler`](https://python-all.ru/3.4/library/logging.handlers.html#logging.handlers.MemoryHandler), который позволяет буферизовать события журнала до наступления некоторого условия, после чего буферизованные события `сбрасываются` (передаются другому обработчику – `целевому` – для обработки). По умолчанию `MemoryHandler` сбрасывает буфер, когда он заполняется или когда встречается событие с уровнем, равным или превышающим указанный порог. Этот рецепт можно использовать с более специализированным подклассом `MemoryHandler`, если требуется собственное поведение сброса.17651766The example script has a simple function, `foo`, which just cycles through all the logging levels, writing to `sys.stderr` to say what level it’s about to log at, and then actually logging a message that that level. You can pass a parameter to `foo` which, if true, will log at ERROR and CRITICAL levels - otherwise, it only logs at DEBUG, INFO and WARNING levels.17671768The script just arranges to decorate `foo` with a decorator which will do the conditional logging that’s required. The decorator takes a logger as a parameter and attaches a memory handler for the duration of the call to the decorated function. The decorator can be additionally parameterised using a target handler, a level at which flushing should occur, and a capacity for the buffer. These default to a [`StreamHandler`](https://python-all.ru/3.4/library/logging.handlers.html#logging.StreamHandler) which writes to `sys.stderr`, `logging.ERROR` and `100` respectively.17691770Вот скрипт:17711772```python1773import logging1774from logging.handlers import MemoryHandler1775import sys17761777logger = logging.getLogger(__name__)1778logger.addHandler(logging.NullHandler())17791780def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):1781    if target_handler is None:1782        target_handler = logging.StreamHandler()1783    if flush_level is None:1784        flush_level = logging.ERROR1785    if capacity is None:1786        capacity = 1001787    handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)17881789    def decorator(fn):1790        def wrapper(*args, **kwargs):1791            logger.addHandler(handler)1792            try:1793                return fn(*args, **kwargs)1794            except Exception:1795                logger.exception('call failed')1796                raise1797            finally:1798                super(MemoryHandler, handler).flush()1799                logger.removeHandler(handler)1800        return wrapper18011802    return decorator18031804def write_line(s):1805    sys.stderr.write('%s\n' % s)18061807def foo(fail=False):1808    write_line('about to log at DEBUG ...')1809    logger.debug('Actually logged at DEBUG')1810    write_line('about to log at INFO ...')1811    logger.info('Actually logged at INFO')1812    write_line('about to log at WARNING ...')1813    logger.warning('Actually logged at WARNING')1814    if fail:1815        write_line('about to log at ERROR ...')1816        logger.error('Actually logged at ERROR')1817        write_line('about to log at CRITICAL ...')1818        logger.critical('Actually logged at CRITICAL')1819    return fail18201821decorated_foo = log_if_errors(logger)(foo)18221823if __name__ == '__main__':1824    logger.setLevel(logging.DEBUG)1825    write_line('Calling undecorated foo with False')1826    assert not foo(False)1827    write_line('Calling undecorated foo with True')1828    assert foo(True)1829    write_line('Calling decorated foo with False')1830    assert not decorated_foo(False)1831    write_line('Calling decorated foo with True')1832    assert decorated_foo(True)1833```18341835При запуске этого скрипта отобразится следующий вывод:18361837```python1838Calling undecorated foo with False1839about to log at DEBUG ...1840about to log at INFO ...1841about to log at WARNING ...1842Calling undecorated foo with True1843about to log at DEBUG ...1844about to log at INFO ...1845about to log at WARNING ...1846about to log at ERROR ...1847about to log at CRITICAL ...1848Calling decorated foo with False1849about to log at DEBUG ...1850about to log at INFO ...1851about to log at WARNING ...1852Calling decorated foo with True1853about to log at DEBUG ...1854about to log at INFO ...1855about to log at WARNING ...1856about to log at ERROR ...1857Actually logged at DEBUG1858Actually logged at INFO1859Actually logged at WARNING1860Actually logged at ERROR1861about to log at CRITICAL ...1862Actually logged at CRITICAL1863```18641865Как видно, фактический вывод журнала происходит только при регистрации события, уровень которого ERROR или выше, но в этом случае также регистрируются все предыдущие события с более низкими уровнями.18661867Конечно, можно использовать обычные средства декорирования:18681869```python1870@log_if_errors(logger)1871def foo(fail=False):1872    ...1873```18741875## Форматирование времени с использованием UTC (GMT) через конфигурацию18761877Иногда требуется форматировать время по UTC, что можно сделать с помощью класса такого как *UTCFormatter*, показанного ниже:18781879```python1880import logging1881import time18821883class UTCFormatter(logging.Formatter):1884    converter = time.gmtime1885```18861887И после этого можно использовать `UTCFormatter` в своём коде вместо [`Formatter`](https://python-all.ru/3.4/library/logging.html#logging.Formatter). Если это нужно сделать через конфигурацию, можно воспользоваться API [`dictConfig()`](https://python-all.ru/3.4/library/logging.config.html#logging.config.dictConfig) с подходом, проиллюстрированным следующим полным примером:18881889```python1890import logging1891import logging.config1892import time18931894class UTCFormatter(logging.Formatter):1895    converter = time.gmtime18961897LOGGING = {1898    'version': 1,1899    'disable_existing_loggers': False,1900    'formatters': {1901        'utc': {1902            '()': UTCFormatter,1903            'format': '%(asctime)s %(message)s',1904        },1905        'local': {1906            'format': '%(asctime)s %(message)s',1907        }1908    },1909    'handlers': {1910        'console1': {1911            'class': 'logging.StreamHandler',1912            'formatter': 'utc',1913        },1914        'console2': {1915            'class': 'logging.StreamHandler',1916            'formatter': 'local',1917        },1918    },1919    'root': {1920        'handlers': ['console1', 'console2'],1921   }1922}19231924if __name__ == '__main__':1925    logging.config.dictConfig(LOGGING)1926    logging.warning('The local time is %s', time.asctime())1927```19281929При запуске этого скрипта он должен вывести примерно следующее:19301931```python19322015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 201519332015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 20151934```19351936показывая, как время форматируется как в местном времени, так и в UTC, по одному для каждого обработчика.1937