logging-cookbook.md

1> **Источник:** https://python-all.ru/3.8/howto/logging-cookbook.html2>3> «Документация Python на русском» – неофициальный перевод официальной документации Python: версии от 2.6 до 3.16, полнотекстовый поиск, английский оригинал рядом с переводом. Эта Markdown-версия страницы предназначена для работы с LLM: вставьте её в ChatGPT, Claude или Cursor.45---67# Сборник рецептов по логированию89**Автор**1011Vinay Sajip \<vinay\_sajip at red-dove dot com\>1213На этой странице представлен ряд рецептов, связанных с логированием, которые оказались полезными на практике.1415## Использование логирования в нескольких модулях1617Многократные вызовы `logging.getLogger('someLogger')` возвращают ссылку на один и тот же объект логгера. Это верно не только в пределах одного модуля, но и для разных модулей, если они выполняются в одном процессе интерпретатора Python. Кроме того, код приложения может определить и настроить родительский логгер в одном модуле, а затем создать (но не настраивать) дочерний логгер в другом модуле – все вызовы логгера у дочернего будут передаваться родительскому. Вот главный модуль:1819```python20import logging21import auxiliary_module2223# создать логгер с именем 'spam_application'24logger = logging.getLogger('spam_application')25logger.setLevel(logging.DEBUG)26# создать файловый обработчик, записывающий даже отладочные сообщения27fh = logging.FileHandler('spam.log')28fh.setLevel(logging.DEBUG)29# создать консольный обработчик с более высоким уровнем логирования30ch = logging.StreamHandler()31ch.setLevel(logging.ERROR)32# создать форматтер и добавить его к обработчикам33formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')34fh.setFormatter(formatter)35ch.setFormatter(formatter)36# добавить обработчики к логгеру37logger.addHandler(fh)38logger.addHandler(ch)3940logger.info('creating an instance of auxiliary_module.Auxiliary')41a = auxiliary_module.Auxiliary()42logger.info('created an instance of auxiliary_module.Auxiliary')43logger.info('calling auxiliary_module.Auxiliary.do_something')44a.do_something()45logger.info('finished auxiliary_module.Auxiliary.do_something')46logger.info('calling auxiliary_module.some_function()')47auxiliary_module.some_function()48logger.info('done with auxiliary_module.some_function()')49```5051А вот вспомогательный модуль:5253```python54import logging5556# создать логгер57module_logger = logging.getLogger('spam_application.auxiliary')5859class Auxiliary:60    def __init__(self):61        self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')62        self.logger.info('creating an instance of Auxiliary')6364    def do_something(self):65        self.logger.info('doing something')66        a = 1 + 167        self.logger.info('done doing something')6869def some_function():70    module_logger.info('received a call to "some_function"')71```7273Вывод выглядит так:7475```text762005-03-23 23:47:11,663 - spam_application - INFO -77   creating an instance of auxiliary_module.Auxiliary782005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -79   creating an instance of Auxiliary802005-03-23 23:47:11,665 - spam_application - INFO -81   created an instance of auxiliary_module.Auxiliary822005-03-23 23:47:11,668 - spam_application - INFO -83   calling auxiliary_module.Auxiliary.do_something842005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -85   doing something862005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -87   done doing something882005-03-23 23:47:11,670 - spam_application - INFO -89   finished auxiliary_module.Auxiliary.do_something902005-03-23 23:47:11,671 - spam_application - INFO -91   calling auxiliary_module.some_function()922005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -93   received a call to 'some_function'942005-03-23 23:47:11,673 - spam_application - INFO -95   done with auxiliary_module.some_function()96```9798## Журналирование из нескольких потоков99100Журналирование из нескольких потоков не требует особых усилий. В следующем примере показано журналирование из главного (начального) потока и ещё одного потока:101102```python103import logging104import threading105import time106107def worker(arg):108    while not arg['stop']:109        logging.debug('Hi from myfunc')110        time.sleep(0.5)111112def main():113    logging.basicConfig(level=logging.DEBUG, format='%(relativeCreated)6d %(threadName)s %(message)s')114    info = {'stop': False}115    thread = threading.Thread(target=worker, args=(info,))116    thread.start()117    while True:118        try:119            logging.debug('Hello from main')120            time.sleep(0.75)121        except KeyboardInterrupt:122            info['stop'] = True123            break124    thread.join()125126if __name__ == '__main__':127    main()128```129130При запуске скрипт должен вывести что-то вроде следующего:131132```text133   0 Thread-1 Hi from myfunc134   3 MainThread Hello from main135 505 Thread-1 Hi from myfunc136 755 MainThread Hello from main1371007 Thread-1 Hi from myfunc1381507 MainThread Hello from main1391508 Thread-1 Hi from myfunc1402010 Thread-1 Hi from myfunc1412258 MainThread Hello from main1422512 Thread-1 Hi from myfunc1433009 MainThread Hello from main1443013 Thread-1 Hi from myfunc1453515 Thread-1 Hi from myfunc1463761 MainThread Hello from main1474017 Thread-1 Hi from myfunc1484513 MainThread Hello from main1494518 Thread-1 Hi from myfunc150```151152Как и следовало ожидать, вывод журнала перемежается. Разумеется, такой подход работает и для большего количества потоков, чем показано здесь.153154## Несколько обработчиков и форматировщиков155156Логгеры – это обычные объекты Python. У метода [`addHandler()`](https://python-all.ru/3.8/library/logging.html#logging.Logger.addHandler) нет минимального или максимального ограничения на количество добавляемых обработчиков. Иногда приложению полезно записывать все сообщения всех уровней в текстовый файл и одновременно выводить ошибки и сообщения выше в консоль. Чтобы это настроить, достаточно сконфигурировать нужные обработчики. Вызовы журналирования в коде приложения останутся без изменений. Вот небольшая модификация предыдущего простого примера конфигурации на основе модуля:157158```python159import logging160161logger = logging.getLogger('simple_example')162logger.setLevel(logging.DEBUG)163# создать файловый обработчик, записывающий даже отладочные сообщения164fh = logging.FileHandler('spam.log')165fh.setLevel(logging.DEBUG)166# создать консольный обработчик с более высоким уровнем логирования167ch = logging.StreamHandler()168ch.setLevel(logging.ERROR)169# создать форматтер и добавить его к обработчикам170formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')171ch.setFormatter(formatter)172fh.setFormatter(formatter)173# добавить обработчики в логгер174logger.addHandler(ch)175logger.addHandler(fh)176177# код 'приложения'178logger.debug('debug message')179logger.info('info message')180logger.warning('warn message')181logger.error('error message')182logger.critical('critical message')183```184185Обратите внимание, что «прикладной» код не заботится о нескольких обработчиках. Единственное, что изменилось – добавление и настройка нового обработчика с именем *fh*.186187Возможность создавать новые обработчики с фильтрами более высокого или низкого уровня очень полезна при написании и тестировании приложения. Вместо множества операторов `print` для отладки используйте `logger.debug`: в отличие от операторов print, которые позже придётся удалять или закомментировать, вызовы logger.debug могут оставаться в исходном коде и оставаться неактивными, пока они снова не понадобятся. В тот момент единственное, что нужно изменить – уровень журналирования логгера и/или обработчика на DEBUG.188189## Журналирование в несколько мест назначения190191Допустим, вы хотите вести журнал в консоль и файл с разными форматами сообщений и в разных ситуациях. Предположим, вы хотите записывать сообщения уровня DEBUG и выше в файл, а сообщения уровня INFO и выше – в консоль. Также предположим, что файл должен содержать временные метки, а консольные сообщения – нет. Вот как это можно сделать:192193```python194import logging195196# настроить логирование в файл – подробнее см. предыдущий раздел197logging.basicConfig(level=logging.DEBUG,198                    format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',199                    datefmt='%m-%d %H:%M',200                    filename='/temp/myapp.log',201                    filemode='w')202# Определяет обработчик, который записывает сообщения уровня INFO и выше в sys.stderr.203console = logging.StreamHandler()204console.setLevel(logging.INFO)205# Задает формат, упрощенный для вывода в консоль.206formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')207# Указывает обработчику использовать этот формат.208console.setFormatter(formatter)209# Добавляет обработчик в корневой логгер.210logging.getLogger('').addHandler(console)211212# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...213logging.info('Jackdaws love my big sphinx of quartz.')214215# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:216# приложение:217218logger1 = logging.getLogger('myapp.area1')219logger2 = logging.getLogger('myapp.area2')220221logger1.debug('Quick zephyrs blow, vexing daft Jim.')222logger1.info('How quickly daft jumping zebras vex.')223logger2.warning('Jail zesty vixen who grabbed pay from quack.')224logger2.error('The five boxing wizards jump quickly.')225```226227При запуске на консоли вы увидите228229```text230root        : INFO     Jackdaws love my big sphinx of quartz.231myapp.area1 : INFO     How quickly daft jumping zebras vex.232myapp.area2 : WARNING  Jail zesty vixen who grabbed pay from quack.233myapp.area2 : ERROR    The five boxing wizards jump quickly.234```235236а в файле увидите примерно такое237238```text23910-22 22:19 root         INFO     Jackdaws love my big sphinx of quartz.24010-22 22:19 myapp.area1  DEBUG    Quick zephyrs blow, vexing daft Jim.24110-22 22:19 myapp.area1  INFO     How quickly daft jumping zebras vex.24210-22 22:19 myapp.area2  WARNING  Jail zesty vixen who grabbed pay from quack.24310-22 22:19 myapp.area2  ERROR    The five boxing wizards jump quickly.244```245246Как видите, сообщение DEBUG отображается только в файле. Остальные сообщения отправляются в оба места назначения.247248В этом примере используются консольный и файловый обработчики, но вы можете использовать любое количество и любое сочетание обработчиков по своему выбору.249250## Пример сервера конфигурации251252Вот пример модуля, использующего сервер конфигурации журналирования:253254```python255import logging256import logging.config257import time258import os259260# Прочитать начальный конфигурационный файл.261logging.config.fileConfig('logging.conf')262263# Создать и запустить слушатель на порту 9999.264t = logging.config.listen(9999)265t.start()266267logger = logging.getLogger('simpleExample')268269try:270    # Прокрутить вызовы логирования, чтобы увидеть разницу.271    # Создавать новые конфигурации до нажатия Ctrl+C.272    while True:273        logger.debug('debug message')274        logger.info('info message')275        logger.warning('warn message')276        logger.error('error message')277        logger.critical('critical message')278        time.sleep(5)279except KeyboardInterrupt:280    # очистка281    logging.config.stopListening()282    t.join()283```284285А вот скрипт, который принимает имя файла и отправляет этот файл на сервер, предварив его двоично-закодированной длиной, в качестве новой конфигурации журналирования:286287```python288#!/usr/bin/env python289import socket, sys, struct290291with open(sys.argv[1], 'rb') as f:292    data_to_send = f.read()293294HOST = 'localhost'295PORT = 9999296s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)297print('connecting...')298s.connect((HOST, PORT))299print('sending config...')300s.send(struct.pack('>L', len(data_to_send)))301s.send(data_to_send)302s.close()303print('complete')304```305306## Работа с блокирующими обработчиками307308Иногда требуется, чтобы обработчики логирования выполняли свою работу, не блокируя поток, из которого ведется логирование. Это часто встречается в веб-приложениях, хотя, конечно, бывает и в других сценариях.309310Типичный виновник медленной работы – [`SMTPHandler`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.SMTPHandler): отправка электронной почты может занимать много времени по ряду причин, не зависящих от разработчика (например, из-за плохой работы почтовой или сетевой инфраструктуры). Но почти любой сетевой обработчик может блокировать: даже операция [`SocketHandler`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.SocketHandler) может выполнять DNS-запрос «под капотом», который оказывается слишком медленным (и этот запрос может быть глубоко в коде библиотеки сокетов, ниже уровня Python и вне вашего контроля).311312Одно из решений – использовать двухчастный подход. На первом этапе к логгерам, к которым обращаются из критичных по производительности потоков, следует подключать только [`QueueHandler`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.QueueHandler). Они просто пишут в свою очередь, которую можно настроить на достаточно большую ёмкость или инициализировать без верхнего ограничения размера. Запись в очередь обычно выполняется быстро, хотя в коде желательно перехватывать исключение [`queue.Full`](https://python-all.ru/3.8/library/queue.html#queue.Full) на всякий случай. Если вы – разработчик библиотеки, в коде которой есть критичные по производительности потоки, обязательно задокументируйте это (вместе с рекомендацией подключать к вашим логгерам только `QueueHandlers`) для пользы других разработчиков, которые будут использовать ваш код.313314Вторая часть решения – [`QueueListener`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.QueueListener), который был разработан как аналог [`QueueHandler`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.QueueHandler). [`QueueListener`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.QueueListener) устроен очень просто: ему передаётся очередь и несколько обработчиков, и он запускает внутренний поток, который слушает свою очередь на предмет LogRecords, отправленных из `QueueHandlers` (или любого другого источника `LogRecords`). `LogRecords` извлекаются из очереди и передаются обработчикам для обработки.315316Преимущество отдельного класса [`QueueListener`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.QueueListener) в том, что один его экземпляр может обслуживать несколько `QueueHandlers`. Это более экономит ресурсы, чем, скажем, многопоточные версии существующих классов обработчиков, которые расходовали бы по одному потоку на обработчик без особой пользы.317318Ниже приведён пример использования этих двух классов (импорты опущены):319320```python321que = queue.Queue(-1)  # Без ограничения размера.322queue_handler = QueueHandler(que)323handler = logging.StreamHandler()324listener = QueueListener(que, handler)325root = logging.getLogger()326root.addHandler(queue_handler)327formatter = logging.Formatter('%(threadName)s: %(message)s')328handler.setFormatter(formatter)329listener.start()330# Вывод лога будет отображать поток, создавший событие (главный поток), а не внутренний поток,331# отслеживающий внутреннюю очередь.332# Именно это и должно происходить.333# то, что должно произойти.334root.warning('Look out!')335listener.stop()336```337338который при запуске выведет:339340```text341MainThread: Look out!342```343344Изменено в версии 3.5: До Python 3.5 [`QueueListener`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.QueueListener) всегда передавал каждое полученное из очереди сообщение каждому обработчику, с которыми был инициализирован. (Это объяснялось тем, что предполагалось, что фильтрация по уровню полностью выполняется на стороне наполнения очереди.) Начиная с версии 3.5 это поведение можно изменить, передав именованный аргумент `respect_handler_level=True` конструктору слушателя. Когда это сделано, слушатель сравнивает уровень каждого сообщения с уровнем обработчика и передаёт сообщение обработчику, только если это уместно.345346## Отправка и получение событий логирования по сети347348Допустим, вы хотите отправлять события логирования по сети и обрабатывать их на принимающей стороне. Простой способ – подключить экземпляр [`SocketHandler`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.SocketHandler) к корневому логгеру на отправляющей стороне:349350```python351import logging, logging.handlers352353rootLogger = logging.getLogger('')354rootLogger.setLevel(logging.DEBUG)355socketHandler = logging.handlers.SocketHandler('localhost',356                    logging.handlers.DEFAULT_TCP_LOGGING_PORT)357# Не нужно использовать форматтер, так как сокет-обработчик отправляет событие в виде неформатированного пикла.358# неформатированный pickle359rootLogger.addHandler(socketHandler)360361# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...362logging.info('Jackdaws love my big sphinx of quartz.')363364# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:365# приложение:366367logger1 = logging.getLogger('myapp.area1')368logger2 = logging.getLogger('myapp.area2')369370logger1.debug('Quick zephyrs blow, vexing daft Jim.')371logger1.info('How quickly daft jumping zebras vex.')372logger2.warning('Jail zesty vixen who grabbed pay from quack.')373logger2.error('The five boxing wizards jump quickly.')374```375376На принимающей стороне можно настроить приёмник с помощью модуля [`socketserver`](https://python-all.ru/3.8/library/socketserver.html#module-socketserver). Вот простой работающий пример:377378```python379import pickle380import logging381import logging.handlers382import socketserver383import struct384385class LogRecordStreamHandler(socketserver.StreamRequestHandler):386    """Обработчик для потокового запроса логирования.387388    Это по сути записывает запись, используя ту политику логирования, которая настроена локально.389    настроено локально.390    """391392    def handle(self):393        """394        Обрабатывает несколько запросов – каждый ожидается в формате: 4-байтовая длина, затем запись журнала в формате пикл.395        Записывает запись в соответствии с политикой, настроенной локально.396        согласно локально настроенной политике.397        """398        while True:399            chunk = self.connection.recv(4)400            if len(chunk) < 4:401                break402            slen = struct.unpack('>L', chunk)[0]403            chunk = self.connection.recv(slen)404            while len(chunk) < slen:405                chunk = chunk + self.connection.recv(slen - len(chunk))406            obj = self.unPickle(chunk)407            record = logging.makeLogRecord(obj)408            self.handleLogRecord(record)409410    def unPickle(self, data):411        return pickle.loads(data)412413    def handleLogRecord(self, record):414        # Если указано имя, используется именованный логгер, а не тот, что415        # подразумевается записью.416        if self.server.logname is not None:417            name = self.server.logname418        else:419            name = record.name420        logger = logging.getLogger(name)421        # Примечание: КАЖДАЯ запись попадает в журнал. Это связано с тем, что Logger.handle422        # обычно вызывается ПОСЛЕ фильтрации на уровне регистратора. Если требуется423        # выполнять фильтрацию, делайте это на стороне клиента, чтобы не тратить424        # циклы процессора и сетевую пропускную способность!425        logger.handle(record)426427class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):428    """429    Простой приёмник журнала на основе TCP-сокетов, подходящий для тестирования.430    """431432    allow_reuse_address = True433434    def __init__(self, host='localhost',435                 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,436                 handler=LogRecordStreamHandler):437        socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)438        self.abort = 0439        self.timeout = 1440        self.logname = None441442    def serve_until_stopped(self):443        import select444        abort = 0445        while not abort:446            rd, wr, ex = select.select([self.socket.fileno()],447                                       [], [],448                                       self.timeout)449            if rd:450                self.handle_request()451            abort = self.abort452453def main():454    logging.basicConfig(455        format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')456    tcpserver = LogRecordSocketReceiver()457    print('About to start TCP server...')458    tcpserver.serve_until_stopped()459460if __name__ == '__main__':461    main()462```463464Сначала запустите сервер, затем клиент. На стороне клиента в консоль ничего не выводится; на стороне сервера вы должны увидеть что-то вроде:465466```text467About to start TCP server...468   59 root            INFO     Jackdaws love my big sphinx of quartz.469   59 myapp.area1     DEBUG    Quick zephyrs blow, vexing daft Jim.470   69 myapp.area1     INFO     How quickly daft jumping zebras vex.471   69 myapp.area2     WARNING  Jail zesty vixen who grabbed pay from quack.472   69 myapp.area2     ERROR    The five boxing wizards jump quickly.473```474475Обратите внимание, что в некоторых сценариях существуют проблемы безопасности с pickle. Если они вас затрагивают, вы можете использовать альтернативную схему сериализации, переопределив метод `makePickle()` и реализовав свою альтернативу там, а также адаптировав вышеприведённый скрипт для использования вашей альтернативной сериализации.476477## Добавление контекстной информации в вывод журнала478479Иногда требуется, чтобы вывод журнала содержал контекстную информацию в дополнение к параметрам, переданным в вызове логирования. Например, в сетевом приложении может быть желательно записывать в журнал информацию, специфичную для клиента (например, имя пользователя удалённого клиента или IP-адрес). Хотя для этого можно использовать параметр *extra*, не всегда удобно передавать информацию таким образом. Может возникнуть соблазн создавать экземпляры `Logger` для каждого соединения, но это плохая идея, поскольку такие экземпляры не собираются сборщиком мусора. Хотя на практике это не проблема, когда количество экземпляров `Logger` зависит от уровня детализации, используемого при логировании приложения, управление ими может стать сложным, если количество экземпляров `Logger` станет фактически неограниченным.480481### Использование LoggerAdapter для добавления контекстной информации482483Простой способ передавать контекстную информацию для вывода вместе с информацией о событиях логирования – использовать класс `LoggerAdapter`. Этот класс спроектирован так, чтобы выглядеть как `Logger`, что позволяет вызывать `debug()`, `info()`, `warning()`, `error()`, `exception()`, `critical()` и `log()`. Эти методы имеют те же сигнатуры, что и их аналоги в `Logger`, поэтому экземпляры обоих типов можно использовать взаимозаменяемо.484485При создании экземпляра `LoggerAdapter` вы передаёте ему экземпляр `Logger` и объект, подобный словарю, содержащий вашу контекстную информацию. Когда вы вызываете один из методов логирования на экземпляре `LoggerAdapter`, он делегирует вызов базовому экземпляру `Logger`, переданному в конструктор, и организует передачу контекстной информации в этом делегированном вызове. Вот фрагмент кода `LoggerAdapter`:486487```python488def debug(self, msg, /, *args, **kwargs):489    """490    Передаёт вызов отладки нижележащему регистратору после добавления491    контекстной информации из данного экземпляра адаптера.492    """493    msg, kwargs = self.process(msg, kwargs)494    self.logger.debug(msg, *args, **kwargs)495```496497Метод `process()` класса `LoggerAdapter` – это то место, где контекстная информация добавляется в вывод журнала. Ему передаются сообщение и именованные аргументы вызова логирования, а он возвращает (потенциально) изменённые версии для использования в вызове базового регистратора. В реализации по умолчанию этот метод оставляет сообщение без изменений, но вставляет ключ 'extra' в именованные аргументы, значением которого является объект, подобный словарю, переданный конструктору. Конечно, если вы передали именованный аргумент 'extra' в вызове адаптера, он будет молча перезаписан.498499Преимущество использования 'extra' в том, что значения из объекта, подобного словарю, сливаются в \_\_dict\_\_ экземпляра `LogRecord`, что позволяет использовать настроенные строки с экземплярами `Formatter`, которые знают о ключах этого объекта. Если вам нужен другой метод, например, добавить контекстную информацию в начало или конец строки сообщения, достаточно создать подкласс `LoggerAdapter` и переопределить `process()` для нужного поведения. Вот простой пример:500501```python502class CustomAdapter(logging.LoggerAdapter):503    """504    Данный пример адаптера ожидает, что переданный объект, подобный словарю, содержит505    ключ 'connid', значение которого в квадратных скобках добавляется к началу сообщения журнала.506    """507    def process(self, msg, kwargs):508        return '[%s] %s' % (self.extra['connid'], msg), kwargs509```510511который можно использовать так:512513```python514logger = logging.getLogger(__name__)515adapter = CustomAdapter(logger, {'connid': some_conn_id})516```517518Тогда все события, регистрируемые через адаптер, будут содержать значение `some_conn_id`, добавленное в начало сообщений журнала.519520#### Использование объектов, отличных от словарей, для передачи контекстной информации521522Необязательно передавать в `LoggerAdapter` именно словарь – можно передать экземпляр класса, реализующего `__getitem__` и `__iter__`, чтобы он выглядел как словарь для системы логирования. Это полезно, если нужно генерировать значения динамически (тогда как значения в словаре были бы постоянными).523524### Использование фильтров для добавления контекстной информации525526Вы также можете добавлять контекстную информацию в вывод журнала с помощью определённого пользователем `Filter`. Экземплярам `Filter` разрешено изменять `LogRecords`, переданный им, включая добавление дополнительных атрибутов, которые затем можно выводить с помощью подходящей форматной строки или, если необходимо, пользовательского `Formatter`.527528Например, в веб-приложении обрабатываемый запрос (или, по крайней мере, его интересные части) можно сохранить в потоковой локальной переменной ([`threading.local`](https://python-all.ru/3.8/library/threading.html#threading.local)), а затем из `Filter` получить к ней доступ, чтобы добавить, скажем, информацию из запроса – например, удалённый IP-адрес и имя пользователя – в `LogRecord`, используя имена атрибутов 'ip' и 'user', как в примере с `LoggerAdapter` выше. В этом случае можно использовать ту же форматную строку для получения вывода, аналогичного показанному выше. Вот пример скрипта:529530```python531import logging532from random import choice533534class ContextFilter(logging.Filter):535    """536    Это фильтр, который внедряет контекстную информацию в журнал.537538    Вместо использования реальной контекстной информации в данном примере используются случайные539    данные.540    """541542    USERS = ['jim', 'fred', 'sheila']543    IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']544545    def filter(self, record):546547        record.ip = choice(ContextFilter.IPS)548        record.user = choice(ContextFilter.USERS)549        return True550551if __name__ == '__main__':552    levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)553    logging.basicConfig(level=logging.DEBUG,554                        format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')555    a1 = logging.getLogger('a.b.c')556    a2 = logging.getLogger('d.e.f')557558    f = ContextFilter()559    a1.addFilter(f)560    a2.addFilter(f)561    a1.debug('A debug message')562    a1.info('An info message with %s', 'some parameters')563    for x in range(10):564        lvl = choice(levels)565        lvlname = logging.getLevelName(lvl)566        a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')567```568569который при запуске выдаёт примерно следующее:570571```text5722010-09-06 22:38:15,292 a.b.c DEBUG    IP: 123.231.231.123 User: fred     A debug message5732010-09-06 22:38:15,300 a.b.c INFO     IP: 192.168.0.1     User: sheila   An info message with some parameters5742010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters5752010-09-06 22:38:15,300 d.e.f ERROR    IP: 127.0.0.1       User: jim      A message at ERROR level with 2 parameters5762010-09-06 22:38:15,300 d.e.f DEBUG    IP: 127.0.0.1       User: sheila   A message at DEBUG level with 2 parameters5772010-09-06 22:38:15,300 d.e.f ERROR    IP: 123.231.231.123 User: fred     A message at ERROR level with 2 parameters5782010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1     User: jim      A message at CRITICAL level with 2 parameters5792010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters5802010-09-06 22:38:15,300 d.e.f DEBUG    IP: 192.168.0.1     User: jim      A message at DEBUG level with 2 parameters5812010-09-06 22:38:15,301 d.e.f ERROR    IP: 127.0.0.1       User: sheila   A message at ERROR level with 2 parameters5822010-09-06 22:38:15,301 d.e.f DEBUG    IP: 123.231.231.123 User: fred     A message at DEBUG level with 2 parameters5832010-09-06 22:38:15,301 d.e.f INFO     IP: 123.231.231.123 User: fred     A message at INFO level with 2 parameters584```585586## Ведение журнала в один файл из нескольких процессов587588Хотя модуль logging является потокобезопасным и запись в один файл из нескольких потоков в одном процессе *поддерживается*, запись в один файл из *нескольких процессов* *не* поддерживается, поскольку в Python нет стандартного способа сериализовать доступ к одному файлу из нескольких процессов. Если нужно вести журнал в один файл из нескольких процессов, один из способов – сделать так, чтобы все процессы записывали данные в `SocketHandler`, а отдельный процесс реализовывал сокет-сервер, который читает из сокета и записывает в файл. (Если хотите, можно выделить один поток в одном из существующих процессов для выполнения этой функции.) [В этом разделе](https://python-all.ru/3.8/howto/logging-cookbook.html#network-logging) подробно описывается данный подход и приводится рабочий приёмник сокета, который можно использовать как отправную точку для адаптации в своих приложениях.589590Вы также можете написать собственный обработчик, который использует класс [`Lock`](https://python-all.ru/3.8/library/multiprocessing.html#multiprocessing.Lock) из модуля [`multiprocessing`](https://python-all.ru/3.8/library/multiprocessing.html#module-multiprocessing) для сериализации доступа к файлу из ваших процессов. Существующие `FileHandler` и подклассы в настоящее время не используют [`multiprocessing`](https://python-all.ru/3.8/library/multiprocessing.html#module-multiprocessing), хотя в будущем они могут это сделать. Обратите внимание, что в настоящее время модуль [`multiprocessing`](https://python-all.ru/3.8/library/multiprocessing.html#module-multiprocessing) не обеспечивает рабочую функциональность блокировки на всех платформах (см. [https://bugs.python.org/issue3770](https://python-all.ru/3.8/howto/logging-cookbook.html)).591592В качестве альтернативы можно использовать `Queue` и [`QueueHandler`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.QueueHandler) для отправки всех событий журналирования одному из процессов в вашем многопроцессном приложении. В следующем примере сценария показано, как это сделать; в примере отдельный процесс-слушатель ожидает события, отправленные другими процессами, и регистрирует их в соответствии со своей собственной конфигурацией журналирования. Хотя пример демонстрирует лишь один из способов (например, вместо отдельного процесса-слушателя можно использовать поток-слушатель – реализация будет аналогичной), он позволяет задать полностью разные конфигурации журналирования для слушателя и остальных процессов в вашем приложении и может быть использован как основа для кода, отвечающего вашим конкретным требованиям:593594```python595# Вам понадобятся эти импорты в вашем коде.596import logging597import logging.handlers598import multiprocessing599600# Следующие две строки импорта только для этой демонстрации.601from random import choice, random602import time603604#605# Поскольку нужно задать настройки логирования для слушателя и рабочих процессов, функции606# слушателя и рабочего процесса принимают параметр configurer – вызываемый объект для607# настройки логирования этого процесса. Эти функции также получают очередь, которую608# используют для взаимодействия.609#610# На практике слушателя можно настроить как угодно, но заметьте: в этом простом611# примере слушатель не применяет логику уровней или фильтров к полученным записям.612# На практике эту логику, вероятно, стоит вынести в рабочие процессы, чтобы не613# пересылать между процессами события, которые всё равно будут отфильтрованы.614#615# Размер файлов при ротации намеренно сделан небольшим, чтобы результат был хорошо виден.616def listener_configurer():617    root = logging.getLogger()618    h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)619    f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')620    h.setFormatter(f)621    root.addHandler(h)622623# Это главный цикл процесса-слушателя: ждём события логирования624# (LogRecords) в очереди и обрабатываем их; завершаем работу, когда получаем None вместо625# LogRecord.626def listener_process(queue, configurer):627    configurer()628    while True:629        try:630            record = queue.get()631            if record is None:  # Отправляем это как сигнал завершения, чтобы слушатель остановился.632                break633            logger = logging.getLogger(record.name)634            logger.handle(record)  # Никакой логики уровней и фильтров – просто делаем дело!635        except Exception:636            import sys, traceback637            print('Whoops! Problem:', file=sys.stderr)638            traceback.print_exc(file=sys.stderr)639640# Массивы для случайного выбора в этой демонстрации.641642LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,643          logging.ERROR, logging.CRITICAL]644645LOGGERS = ['a.b.c', 'd.e.f']646647MESSAGES = [648    'Random message #1',649    'Random message #2',650    'Random message #3',651]652653# Настройка рабочего процесса выполняется в начале его работы.654# Обратите внимание: в Windows нельзя полагаться на семантику fork, поэтому каждый процесс655# будет выполнять код настройки логирования при запуске.656def worker_configurer(queue):657    h = logging.handlers.QueueHandler(queue)  # Нужен только один обработчик.658    root = logging.getLogger()659    root.addHandler(h)660    # Отправляем все сообщения для демонстрации; никакой другой логики уровней или фильтров.661    root.setLevel(logging.DEBUG)662663# Это главный цикл рабочего процесса, который просто логирует десять событий с664# случайные задержки перед завершением.665# Сообщения print нужны лишь для того, чтобы было видно, что программа работает.666def worker_process(queue, configurer):667    configurer(queue)668    name = multiprocessing.current_process().name669    print('Worker started: %s' % name)670    for i in range(10):671        time.sleep(random())672        logger = logging.getLogger(choice(LOGGERS))673        level = choice(LEVELS)674        message = choice(MESSAGES)675        logger.log(level, message)676    print('Worker finished: %s' % name)677678# Здесь организуется демонстрация. Создать очередь, создать и запустить679# слушатель, создать десять рабочих процессов и запустить их, дождаться их завершения,680# затем отправить None в очередь, чтобы сообщить слушателю о завершении.681def main():682    queue = multiprocessing.Queue(-1)683    listener = multiprocessing.Process(target=listener_process,684                                       args=(queue, listener_configurer))685    listener.start()686    workers = []687    for i in range(10):688        worker = multiprocessing.Process(target=worker_process,689                                         args=(queue, worker_configurer))690        workers.append(worker)691        worker.start()692    for w in workers:693        w.join()694    queue.put_nowait(None)695    listener.join()696697if __name__ == '__main__':698    main()699```700701Вариант приведённого выше сценария оставляет ведение журнала в главном процессе, в отдельном потоке:702703```python704import logging705import logging.config706import logging.handlers707from multiprocessing import Process, Queue708import random709import threading710import time711712def logger_thread(q):713    while True:714        record = q.get()715        if record is None:716            break717        logger = logging.getLogger(record.name)718        logger.handle(record)719720def worker_process(q):721    qh = logging.handlers.QueueHandler(q)722    root = logging.getLogger()723    root.setLevel(logging.DEBUG)724    root.addHandler(qh)725    levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,726              logging.CRITICAL]727    loggers = ['foo', 'foo.bar', 'foo.bar.baz',728               'spam', 'spam.ham', 'spam.ham.eggs']729    for i in range(100):730        lvl = random.choice(levels)731        logger = logging.getLogger(random.choice(loggers))732        logger.log(lvl, 'Message no. %d', i)733734if __name__ == '__main__':735    q = Queue()736    d = {737        'version': 1,738        'formatters': {739            'detailed': {740                'class': 'logging.Formatter',741                'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'742            }743        },744        'handlers': {745            'console': {746                'class': 'logging.StreamHandler',747                'level': 'INFO',748            },749            'file': {750                'class': 'logging.FileHandler',751                'filename': 'mplog.log',752                'mode': 'w',753                'formatter': 'detailed',754            },755            'foofile': {756                'class': 'logging.FileHandler',757                'filename': 'mplog-foo.log',758                'mode': 'w',759                'formatter': 'detailed',760            },761            'errors': {762                'class': 'logging.FileHandler',763                'filename': 'mplog-errors.log',764                'mode': 'w',765                'level': 'ERROR',766                'formatter': 'detailed',767            },768        },769        'loggers': {770            'foo': {771                'handlers': ['foofile']772            }773        },774        'root': {775            'level': 'DEBUG',776            'handlers': ['console', 'file', 'errors']777        },778    }779    workers = []780    for i in range(5):781        wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))782        workers.append(wp)783        wp.start()784    logging.config.dictConfig(d)785    lp = threading.Thread(target=logger_thread, args=(q,))786    lp.start()787    # На этом этапе главный процесс может заняться своей полезной работой788    # Когда он с этим закончит, он может дождаться завершения рабочих процессов...789    for wp in workers:790        wp.join()791    # А теперь указать потоку журналирования завершиться792    q.put(None)793    lp.join()794```795796Этот вариант показывает, как можно, например, применить конфигурацию для определённых регистраторов – например, регистратор `foo` имеет специальный обработчик, который сохраняет все события подсистемы `foo` в файл `mplog-foo.log`. Это будет использовано механизмом журналирования в главном процессе (даже если события журналирования генерируются в рабочих процессах) для направления сообщений к соответствующим местам назначения.797798### Использование concurrent.futures.ProcessPoolExecutor799800Если вы хотите использовать [`concurrent.futures.ProcessPoolExecutor`](https://python-all.ru/3.8/library/concurrent.futures.html#concurrent.futures.ProcessPoolExecutor) для запуска рабочих процессов, необходимо создать очередь немного иначе. Вместо801802```python803queue = multiprocessing.Queue(-1)804```805806следует использовать807808```python809queue = multiprocessing.Manager().Queue(-1)  # также работает с примерами выше810```811812и затем можно заменить создание рабочего процесса с этого:813814```python815workers = []816for i in range(10):817    worker = multiprocessing.Process(target=worker_process,818                                     args=(queue, worker_configurer))819    workers.append(worker)820    worker.start()821for w in workers:822    w.join()823```824825на это (не забудьте сначала импортировать [`concurrent.futures`](https://python-all.ru/3.8/library/concurrent.futures.html#module-concurrent.futures)):826827```python828with concurrent.futures.ProcessPoolExecutor(max_workers=10) as executor:829    for i in range(10):830        executor.submit(worker_process, queue, worker_configurer)831```832833## Использование ротации файлов834835Иногда требуется позволить файлу журнала расти до определённого размера, затем открыть новый файл и вести запись в него. Может потребоваться сохранять определённое количество таких файлов, и когда будет создано заданное число файлов, выполнять ротацию, чтобы и количество, и размер файлов оставались в заданных границах. Для такого сценария использования пакет logging предоставляет `RotatingFileHandler`:836837```python838import glob839import logging840import logging.handlers841842LOG_FILENAME = 'logging_rotatingfile_example.out'843844# Настроить конкретный регистратор с нужным уровнем вывода845my_logger = logging.getLogger('MyLogger')846my_logger.setLevel(logging.DEBUG)847848# Добавить обработчик сообщений журнала в регистратор849handler = logging.handlers.RotatingFileHandler(850              LOG_FILENAME, maxBytes=20, backupCount=5)851852my_logger.addHandler(handler)853854# Записать несколько сообщений855for i in range(20):856    my_logger.debug('i = %d' % i)857858# Посмотреть, какие файлы созданы859logfiles = glob.glob('%s*' % LOG_FILENAME)860861for filename in logfiles:862    print(filename)863```864865В результате должно получиться 6 отдельных файлов, каждый из которых содержит часть истории журнала приложения:866867```text868logging_rotatingfile_example.out869logging_rotatingfile_example.out.1870logging_rotatingfile_example.out.2871logging_rotatingfile_example.out.3872logging_rotatingfile_example.out.4873logging_rotatingfile_example.out.5874```875876Самый свежий файл всегда называется `logging_rotatingfile_example.out`, и каждый раз при достижении ограничения по размеру он переименовывается с суффиксом `.1`. Каждый из существующих резервных файлов переименовывается с увеличением суффикса (`.1` становится `.2` и т.д.), а файл `.6` удаляется.877878Разумеется, в этом примере размер файла журнала установлен слишком маленьким для наглядности. В реальности нужно установить *maxBytes* в подходящее значение.879880## Использование альтернативных стилей форматирования881882Когда журналирование было добавлено в стандартную библиотеку Python, единственным способом форматирования сообщений с переменным содержимым было использование %-форматирования. С тех пор в Python появились два новых подхода к форматированию: [`string.Template`](https://python-all.ru/3.8/library/string.html#string.Template) (добавлен в Python 2.4) и [`str.format()`](https://python-all.ru/3.8/library/stdtypes.html#str.format) (добавлен в Python 2.6).883884Начиная с версии 3.2, модуль logging предоставляет улучшенную поддержку этих двух дополнительных стилей форматирования. Класс `Formatter` был расширен: добавлен дополнительный необязательный именованный параметр `style`. По умолчанию он равен `'%'`, но возможны также значения `'{'` и `'$'`, соответствующие двум другим стилям форматирования. Обратная совместимость сохраняется по умолчанию (как и следовало ожидать), но при явном указании параметра style появляется возможность задавать строки формата, работающие с [`str.format()`](https://python-all.ru/3.8/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.8/library/string.html#string.Template). Вот пример сеанса работы в консоли, демонстрирующий возможности:885886```pycon887>>> import logging888>>> root = logging.getLogger()889>>> root.setLevel(logging.DEBUG)890>>> handler = logging.StreamHandler()891>>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}',892...                        style='{')893>>> handler.setFormatter(bf)894>>> root.addHandler(handler)895>>> logger = logging.getLogger('foo.bar')896>>> logger.debug('This is a DEBUG message')8972010-10-28 15:11:55,341 foo.bar DEBUG    This is a DEBUG message898>>> logger.critical('This is a CRITICAL message')8992010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message900>>> df = logging.Formatter('$asctime $name ${levelname} $message',901...                        style='$')902>>> handler.setFormatter(df)903>>> logger.debug('This is a DEBUG message')9042010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message905>>> logger.critical('This is a CRITICAL message')9062010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message907>>>908```909910Обратите внимание: форматирование сообщений журнала для конечного вывода в файлы совершенно не зависит от того, как конструируется отдельное сообщение. Оно по-прежнему может использовать %-форматирование, как показано ниже:911912```python913>>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')9142010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message915>>>916```917918Вызовы функций журналирования (`logger.debug()`, `logger.info()` и т.д.) принимают только позиционные параметры для самого сообщения журнала; именованные параметры используются только для определения параметров обработки вызова (например, именованный параметр `exc_info` указывает, что нужно записать информацию о трассировке стека, или именованный параметр `extra` – добавить дополнительный контекст в журнал). Поэтому невозможно напрямую использовать синтаксис [`str.format()`](https://python-all.ru/3.8/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.8/library/string.html#string.Template) при вызовах, поскольку внутри пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Изменить это без нарушения обратной совместимости нельзя, так как все существующие вызовы logging в существующем коде используют %-формат строк.919920Однако существует способ использовать {}- и $-форматирование для построения отдельных сообщений журнала. Напомним, что в качестве строки формата сообщения можно использовать произвольный объект, и пакет logging вызовет у этого объекта `str()` для получения фактической строки формата. Рассмотрим следующие два класса:921922```python923class BraceMessage:924    def __init__(self, fmt, /, *args, **kwargs):925        self.fmt = fmt926        self.args = args927        self.kwargs = kwargs928929    def __str__(self):930        return self.fmt.format(*self.args, **self.kwargs)931932class DollarMessage:933    def __init__(self, fmt, /, **kwargs):934        self.fmt = fmt935        self.kwargs = kwargs936937    def __str__(self):938        from string import Template939        return Template(self.fmt).substitute(**self.kwargs)940```941942Любой из этих классов можно использовать вместо строки формата, чтобы разрешить применение {}- или $-форматирования для построения фактической части «message», которая появляется в отформатированном выводе журнала вместо «%(message)s», «{message}» или «$message». Это немного громоздко – использовать имена классов каждый раз при журналировании, но вполне приемлемо, если применить псевдоним, например \_\_ (двойное подчеркивание – не путать с \_, одинарным подчеркиванием, используемым как синоним/псевдоним для [`gettext.gettext()`](https://python-all.ru/3.8/library/gettext.html#gettext.gettext) или его аналогов).943944Вышеуказанные классы не входят в состав Python, но их легко скопировать и вставить в свой код. Их можно использовать следующим образом (предполагая, что они объявлены в модуле с именем `wherever`):945946```pycon947>>> from wherever import BraceMessage as __948>>> print(__('Message with {0} {name}', 2, name='placeholders'))949Message with 2 placeholders950>>> class Point: pass951...952>>> p = Point()953>>> p.x = 0.5954>>> p.y = 0.5955>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})',956...       point=p))957Message with coordinates: (0.50, 0.50)958>>> from wherever import DollarMessage as __959>>> print(__('Message with $num $what', num=2, what='placeholders'))960Message with 2 placeholders961>>>962```963964Хотя в приведённых выше примерах используется `print()` для демонстрации работы форматирования, в реальности для ведения журнала с помощью этого подхода следует использовать `logger.debug()` или аналогичную функцию.965966Следует отметить, что этот подход не даёт значительного снижения производительности с этим подходом: фактическое форматирование происходит не тогда, когда вы делаете вызов регистрации, а когда (и если) регистрируемое сообщение действительно должно быть выведено в журнал с помощью обработчика. Поэтому единственное, что может сбить с толку, – это то, что скобки ставятся вокруг строки формата и аргументов, а не только вокруг строки формата. Это потому, что нотация \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов XXXMessage.967968Если хотите, можно использовать `LoggerAdapter` для достижения аналогичного эффекта, как в следующем примере:969970```python971import logging972973class Message:974    def __init__(self, fmt, args):975        self.fmt = fmt976        self.args = args977978    def __str__(self):979        return self.fmt.format(*self.args)980981class StyleAdapter(logging.LoggerAdapter):982    def __init__(self, logger, extra=None):983        super().__init__(logger, extra or {})984985    def log(self, level, msg, /, *args, **kwargs):986        if self.isEnabledFor(level):987            msg, kwargs = self.process(msg, kwargs)988            self.logger._log(level, Message(msg, args), (), **kwargs)989990logger = StyleAdapter(logging.getLogger(__name__))991992def main():993    logger.debug('Hello, {}', 'world!')994995if __name__ == '__main__':996    logging.basicConfig(level=logging.DEBUG)997    main()998```9991000При запуске с Python 3.2 или новее указанный выше скрипт должен записать сообщение `Hello, world!`.10011002## Настройка `LogRecord`10031004Каждое событие журналирования представлено экземпляром [`LogRecord`](https://python-all.ru/3.8/library/logging.html#logging.LogRecord). Когда событие регистрируется и не отфильтровывается по уровню регистратора, создаётся [`LogRecord`](https://python-all.ru/3.8/library/logging.html#logging.LogRecord), заполняется информацией о событии и затем передаётся обработчикам для этого регистратора (и его предков, вплоть до регистратора, в котором дальнейшее распространение по иерархии отключено). До Python 3.2 было только два места, где выполнялось это создание:10051006- [`Logger.makeRecord()`](https://python-all.ru/3.8/library/logging.html#logging.Logger.makeRecord), который вызывается в обычном процессе регистрации события. Он напрямую вызывал [`LogRecord`](https://python-all.ru/3.8/library/logging.html#logging.LogRecord) для создания экземпляра.1007- [`makeLogRecord()`](https://python-all.ru/3.8/library/logging.html#logging.makeLogRecord), которая вызывается со словарем, содержащим атрибуты для добавления в LogRecord. Обычно она вызывается, когда подходящий словарь был получен по сети (например, в виде pickle через [`SocketHandler`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.SocketHandler) или в формате JSON через [`HTTPHandler`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.HTTPHandler)).10081009Обычно это означало, что если требуется выполнить какие-либо специальные действия с [`LogRecord`](https://python-all.ru/3.8/library/logging.html#logging.LogRecord), приходилось делать одно из следующего.10101011- Создать собственный подкласс [`Logger`](https://python-all.ru/3.8/library/logging.html#logging.Logger), который переопределяет [`Logger.makeRecord()`](https://python-all.ru/3.8/library/logging.html#logging.Logger.makeRecord), и установить его с помощью [`setLoggerClass()`](https://python-all.ru/3.8/library/logging.html#logging.setLoggerClass) до того, как будут созданы какие-либо логгеры, которые вас интересуют.1012- Добавить [`Filter`](https://python-all.ru/3.8/library/logging.html#logging.Filter) к логгеру или обработчику, который выполняет необходимые специальные манипуляции при вызове его метода [`filter()`](https://python-all.ru/3.8/library/logging.html#logging.Filter.filter).10131014Первый подход был бы несколько громоздким в сценарии, где (скажем) несколько разных библиотек хотели бы делать разные вещи. Каждая попыталась бы установить свой собственный подкласс [`Logger`](https://python-all.ru/3.8/library/logging.html#logging.Logger), и та, которая сделала это последней, победила бы.10151016Второй подход достаточно хорошо работает во многих случаях, но не позволяет, например, использовать специализированный подкласс [`LogRecord`](https://python-all.ru/3.8/library/logging.html#logging.LogRecord). Разработчики библиотек могут установить подходящий фильтр на своих логгерах, но им приходилось бы помнить об этом каждый раз, когда они добавляют новый логгер (что они делают, просто добавляя новые пакеты или модули и выполняя10171018```python1019logger = logging.getLogger(__name__)1020```10211022на уровне модуля). Вероятно, это одна из тех вещей, о которых нужно помнить. Разработчики также могли бы добавить фильтр к [`NullHandler`](https://python-all.ru/3.8/library/logging.handlers.html#logging.NullHandler), прикрепленному к их корневому логгеру, но он не будет вызываться, если разработчик приложения прикрепит обработчик к логгеру библиотеки нижнего уровня – так что вывод от этого обработчика не будет отражать намерений разработчика библиотеки.10231024В Python 3.2 и новее создание [`LogRecord`](https://python-all.ru/3.8/library/logging.html#logging.LogRecord) осуществляется через фабрику, которую можно указать. Фабрика – это просто вызываемый объект, который можно установить с помощью [`setLogRecordFactory()`](https://python-all.ru/3.8/library/logging.html#logging.setLogRecordFactory) и запросить с помощью [`getLogRecordFactory()`](https://python-all.ru/3.8/library/logging.html#logging.getLogRecordFactory). Фабрика вызывается с той же сигнатурой, что и конструктор [`LogRecord`](https://python-all.ru/3.8/library/logging.html#logging.LogRecord), поскольку [`LogRecord`](https://python-all.ru/3.8/library/logging.html#logging.LogRecord) является значением по умолчанию для фабрики.10251026Этот подход позволяет пользовательской фабрике контролировать все аспекты создания LogRecord. Например, можно вернуть подкласс или просто добавить несколько дополнительных атрибутов к записи после ее создания, используя шаблон, подобный следующему:10271028```python1029old_factory = logging.getLogRecordFactory()10301031def record_factory(*args, **kwargs):1032    record = old_factory(*args, **kwargs)1033    record.custom_attribute = 0xdecafbad1034    return record10351036logging.setLogRecordFactory(record_factory)1037```10381039Этот шаблон позволяет разным библиотекам объединять фабрики в цепочку, и пока они не перезаписывают атрибуты друг друга или случайно не перезаписывают стандартные атрибуты, никаких сюрпризов быть не должно. Однако следует иметь в виду, что каждое звено цепочки добавляет накладные расходы во время выполнения ко всем операциям логирования, и эту технику следует использовать только тогда, когда использование [`Filter`](https://python-all.ru/3.8/library/logging.html#logging.Filter) не дает желаемого результата.10401041## Создание подкласса QueueHandler – пример с ZeroMQ10421043Можно использовать подкласс `QueueHandler` для отправки сообщений в очереди других типов, например, в сокет ZeroMQ «publish». В приведенном ниже примере сокет создается отдельно и передается обработчику (в качестве его «очереди»):10441045```python1046import zmq   # с использованием pyzmq, привязки Python к ZeroMQ1047import json  # для переносимой сериализации записей10481049ctx = zmq.Context()1050sock = zmq.Socket(ctx, zmq.PUB)  # или zmq.PUSH, или другое подходящее значение1051sock.bind('tcp://*:5556')        # или где угодно10521053class ZeroMQSocketHandler(QueueHandler):1054    def enqueue(self, record):1055        self.queue.send_json(record.__dict__)10561057handler = ZeroMQSocketHandler(sock)1058```10591060Конечно, есть и другие способы организации этого, например, передача данных, необходимых обработчику для создания сокета:10611062```python1063class ZeroMQSocketHandler(QueueHandler):1064    def __init__(self, uri, socktype=zmq.PUB, ctx=None):1065        self.ctx = ctx or zmq.Context()1066        socket = zmq.Socket(self.ctx, socktype)1067        socket.bind(uri)1068        super().__init__(socket)10691070    def enqueue(self, record):1071        self.queue.send_json(record.__dict__)10721073    def close(self):1074        self.queue.close()1075```10761077## Создание подкласса QueueListener – пример с ZeroMQ10781079Можно также создать подкласс `QueueListener` для получения сообщений из очередей других типов, например, из сокета ZeroMQ «subscribe». Вот пример:10801081```python1082class ZeroMQSocketListener(QueueListener):1083    def __init__(self, uri, /, *handlers, **kwargs):1084        self.ctx = kwargs.get('ctx') or zmq.Context()1085        socket = zmq.Socket(self.ctx, zmq.SUB)1086        socket.setsockopt_string(zmq.SUBSCRIBE, '')  # подписаться на всё1087        socket.connect(uri)1088        super().__init__(socket, *handlers, **kwargs)10891090    def dequeue(self):1091        msg = self.queue.recv_json()1092        return logging.makeLogRecord(msg)1093```10941095> **См. также**1096>1097> **Модуль [`logging`](https://python-all.ru/3.8/library/logging.html#module-logging)**1098>1099> Справочник API для модуля logging.1100>1101> **Модуль [`logging.config`](https://python-all.ru/3.8/library/logging.config.html#module-logging.config)**1102>1103> API конфигурации для модуля logging.1104>1105> **Модуль [`logging.handlers`](https://python-all.ru/3.8/library/logging.handlers.html#module-logging.handlers)**1106>1107> Полезные обработчики, входящие в состав модуля logging.1108>1109> [Базовое руководство по логированию](https://python-all.ru/3.8/howto/logging.html#logging-basic-tutorial)1110>1111> [Более продвинутое руководство по логированию](https://python-all.ru/3.8/howto/logging.html#logging-advanced-tutorial)11121113## Пример конфигурации на основе словаря11141115Ниже приведен пример словаря конфигурации логирования – он взят из [документации проекта Django](https://python-all.ru/3.8/howto/logging-cookbook.html). Этот словарь передается в [`dictConfig()`](https://python-all.ru/3.8/library/logging.config.html#logging.config.dictConfig) для применения конфигурации:11161117```python1118LOGGING = {1119    'version': 1,1120    'disable_existing_loggers': True,1121    'formatters': {1122        'verbose': {1123            'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'1124        },1125        'simple': {1126            'format': '%(levelname)s %(message)s'1127        },1128    },1129    'filters': {1130        'special': {1131            '()': 'project.logging.SpecialFilter',1132            'foo': 'bar',1133        }1134    },1135    'handlers': {1136        'null': {1137            'level':'DEBUG',1138            'class':'django.utils.log.NullHandler',1139        },1140        'console':{1141            'level':'DEBUG',1142            'class':'logging.StreamHandler',1143            'formatter': 'simple'1144        },1145        'mail_admins': {1146            'level': 'ERROR',1147            'class': 'django.utils.log.AdminEmailHandler',1148            'filters': ['special']1149        }1150    },1151    'loggers': {1152        'django': {1153            'handlers':['null'],1154            'propagate': True,1155            'level':'INFO',1156        },1157        'django.request': {1158            'handlers': ['mail_admins'],1159            'level': 'ERROR',1160            'propagate': False,1161        },1162        'myproject.custom': {1163            'handlers': ['console', 'mail_admins'],1164            'level': 'INFO',1165            'filters': ['special']1166        }1167    }1168}1169```11701171Для получения дополнительной информации об этой конфигурации можно обратиться к [соответствующему разделу](https://python-all.ru/3.8/howto/logging-cookbook.html) документации Django.11721173## Использование ротатора и средства именования для настройки обработки ротации журналов11741175Пример того, как можно определить namer и rotator, приведен в следующем фрагменте кода, который демонстрирует сжатие журнала с использованием zlib:11761177```python1178def namer(name):1179    return name + ".gz"11801181def rotator(source, dest):1182    with open(source, "rb") as sf:1183        data = sf.read()1184        compressed = zlib.compress(data, 9)1185        with open(dest, "wb") as df:1186            df.write(compressed)1187    os.remove(source)11881189rh = logging.handlers.RotatingFileHandler(...)1190rh.rotator = rotator1191rh.namer = namer1192```11931194Это не «настоящие» .gz-файлы, поскольку они представляют собой просто сжатые данные без «контейнера», который присутствует в обычном gzip-файле. Данный фрагмент приведен только для иллюстрации.11951196## Более сложный пример с многопроцессностью11971198Следующий рабочий пример показывает, как можно использовать логирование с многопроцессностью с помощью файлов конфигурации. Конфигурации довольно просты, но служат иллюстрацией того, как можно реализовать более сложные в реальном сценарии многопроцессной обработки.11991200В примере главный процесс порождает процесс-слушатель и несколько рабочих процессов. Каждый из главного процесса, слушателя и рабочих имеет три отдельные конфигурации (все рабочие используют одну и ту же конфигурацию). Видно ведение журнала в главном процессе, как рабочие пишут в QueueHandler, а слушатель реализует QueueListener и более сложную конфигурацию ведения журнала, и организует отправку событий, полученных через очередь, обработчикам, указанным в конфигурации. Обратите внимание, что эти конфигурации чисто иллюстративные, но этот пример можно адаптировать под свой сценарий.12011202Вот скрипт – строки документации и комментарии, надеюсь, поясняют, как он работает:12031204```python1205import logging1206import logging.config1207import logging.handlers1208from multiprocessing import Process, Queue, Event, current_process1209import os1210import random1211import time12121213class MyHandler:1214    """1215    Простой обработчик для событий логирования. Он выполняется в процессе-слушателе и1216    распределяет события по логгерам на основе имени в полученной записи,1217    которые затем передаются системой логирования обработчикам,1218    настроенным для этих логгеров.1219    """12201221    def handle(self, record):1222        if record.name == "root":1223            logger = logging.getLogger()1224        else:1225            logger = logging.getLogger(record.name)12261227        if logger.isEnabledFor(record.levelno):1228            # Имя процесса преобразуется только для того, чтобы показать, что это слушатель1229            # выполняет логирование в файлы и консоль.1230            record.processName = '%s (for %s)' % (current_process().name, record.processName)1231            logger.handle(record)12321233def listener_process(q, stop_event, config):1234    """1235    Это можно было бы сделать в главном процессе, но сделано в отдельном1236    процессе для наглядности.12371238    Это инициализирует логирование согласно указанной конфигурации1239    запускает слушатель и ожидает сигнала от главного процесса о завершении1240    через событие. Затем слушатель останавливается, и процесс завершается.1241    """1242    logging.config.dictConfig(config)1243    listener = logging.handlers.QueueListener(q, MyHandler())1244    listener.start()1245    if os.name == 'posix':1246        # В POSIX логгер setup уже был настроен в1247        # родительском процессе, но должен был быть отключён после вызова1248        # dictConfig.1249        # В Windows, поскольку fork не используется, логгер setup не будет1250        # существовать в дочернем процессе, поэтому он будет создан, и сообщение1251        # появится – отсюда и конструкция "if posix".1252        logger = logging.getLogger('setup')1253        logger.critical('Should not appear, because of disabled logger ...')1254    stop_event.wait()1255    listener.stop()12561257def worker_process(config):1258    """1259    Некоторое количество таких процессов порождается для иллюстрации. На1260    практике это могла бы быть разнородная группа процессов, а не1261    идентичные друг другу.12621263    Это инициализирует логирование согласно указанной конфигурации1264    и записывает сотню сообщений со случайными уровнями в случайно выбранные1265    логгеры.12661267    Добавлена небольшая задержка, чтобы дать другим процессам шанс выполниться. Это1268    не является строго необходимым, но позволяет немного перемешать вывод от разных1269    процессов больше, чем если бы её не было.1270    """1271    logging.config.dictConfig(config)1272    levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1273              logging.CRITICAL]1274    loggers = ['foo', 'foo.bar', 'foo.bar.baz',1275               'spam', 'spam.ham', 'spam.ham.eggs']1276    if os.name == 'posix':1277        # В POSIX логгер setup уже был настроен в1278        # родительском процессе, но должен был быть отключён после вызова1279        # dictConfig.1280        # В Windows, поскольку fork не используется, логгер setup не будет1281        # существовать в дочернем процессе, поэтому он будет создан, и сообщение1282        # появится – отсюда и конструкция "if posix".1283        logger = logging.getLogger('setup')1284        logger.critical('Should not appear, because of disabled logger ...')1285    for i in range(100):1286        lvl = random.choice(levels)1287        logger = logging.getLogger(random.choice(loggers))1288        logger.log(lvl, 'Message no. %d', i)1289        time.sleep(0.01)12901291def main():1292    q = Queue()1293    # Главный процесс получает простую конфигурацию, которая выводит информацию в консоль.1294    config_initial = {1295        'version': 1,1296        'handlers': {1297            'console': {1298                'class': 'logging.StreamHandler',1299                'level': 'INFO'1300            }1301        },1302        'root': {1303            'handlers': ['console'],1304            'level': 'DEBUG'1305        }1306    }1307    # Конфигурация рабочего процесса представляет собой QueueHandler, прикреплённый к1308    # корневому логгеру, что позволяет отправлять все сообщения в очередь.1309    # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1310    # родительском процессе. Это необходимо в POSIX, потому что логгер будет1311    # присутствовать в дочернем процессе после вызова fork().1312    config_worker = {1313        'version': 1,1314        'disable_existing_loggers': True,1315        'handlers': {1316            'queue': {1317                'class': 'logging.handlers.QueueHandler',1318                'queue': q1319            }1320        },1321        'root': {1322            'handlers': ['queue'],1323            'level': 'DEBUG'1324        }1325    }1326    # Конфигурация процесса-слушателя показывает, что вся гибкость1327    # конфигурации логирования доступна для отправки событий обработчикам так, как1328    # требуется.1329    # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1330    # родительском процессе. Это необходимо в POSIX, потому что логгер будет1331    # присутствовать в дочернем процессе после вызова fork().1332    config_listener = {1333        'version': 1,1334        'disable_existing_loggers': True,1335        'formatters': {1336            'detailed': {1337                'class': 'logging.Formatter',1338                'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1339            },1340            'simple': {1341                'class': 'logging.Formatter',1342                'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1343            }1344        },1345        'handlers': {1346            'console': {1347                'class': 'logging.StreamHandler',1348                'formatter': 'simple',1349                'level': 'INFO'1350            },1351            'file': {1352                'class': 'logging.FileHandler',1353                'filename': 'mplog.log',1354                'mode': 'w',1355                'formatter': 'detailed'1356            },1357            'foofile': {1358                'class': 'logging.FileHandler',1359                'filename': 'mplog-foo.log',1360                'mode': 'w',1361                'formatter': 'detailed'1362            },1363            'errors': {1364                'class': 'logging.FileHandler',1365                'filename': 'mplog-errors.log',1366                'mode': 'w',1367                'formatter': 'detailed',1368                'level': 'ERROR'1369            }1370        },1371        'loggers': {1372            'foo': {1373                'handlers': ['foofile']1374            }1375        },1376        'root': {1377            'handlers': ['console', 'file', 'errors'],1378            'level': 'DEBUG'1379        }1380    }1381    # Записываем несколько начальных событий, просто чтобы показать, что логирование в родительском процессе работает1382    # нормально.1383    logging.config.dictConfig(config_initial)1384    logger = logging.getLogger('setup')1385    logger.info('About to create workers ...')1386    workers = []1387    for i in range(5):1388        wp = Process(target=worker_process, name='worker %d' % (i + 1),1389                     args=(config_worker,))1390        workers.append(wp)1391        wp.start()1392        logger.info('Started worker: %s', wp.name)1393    logger.info('About to create listener ...')1394    stop_event = Event()1395    lp = Process(target=listener_process, name='listener',1396                 args=(q, stop_event, config_listener))1397    lp.start()1398    logger.info('Started listener')1399    # Теперь ожидаем завершения работы рабочих процессов.1400    for wp in workers:1401        wp.join()1402    # Все рабочие процессы завершены, теперь можно остановить прослушивание.1403    # Логирование в родительском процессе всё ещё работает нормально.1404    logger.info('Telling listener to stop ...')1405    stop_event.set()1406    lp.join()1407    logger.info('All done.')14081409if __name__ == '__main__':1410    main()1411```14121413## Вставка BOM в сообщения, отправляемые в SysLogHandler14141415[**RFC 5424**](https://python-all.ru/3.8/howto/logging-cookbook.html) требует, чтобы сообщение Unicode отправлялось демону syslog в виде набора байтов, имеющего следующую структуру: необязательный чисто ASCII-компонент, за которым следует метка порядка байтов UTF-8 (BOM), а затем Unicode, закодированный в UTF-8. (См. [**соответствующий раздел спецификации**](https://python-all.ru/3.8/howto/logging-cookbook.html).)14161417В Python 3.1 в [`SysLogHandler`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.SysLogHandler) был добавлен код для вставки BOM в сообщение, но, к сожалению, он был реализован некорректно: BOM появлялся в начале сообщения и, следовательно, не допускал наличия чисто ASCII-компонента перед ним.14181419Поскольку такое поведение ошибочно, некорректный код вставки BOM удаляется из Python 3.2.4 и более поздних версий. Однако он не заменяется, и если требуется создавать сообщения, соответствующие [**RFC 5424**](https://python-all.ru/3.8/howto/logging-cookbook.html), которые включают BOM, необязательную чисто ASCII-последовательность перед ним и произвольный Unicode после него, закодированный в UTF-8, то необходимо сделать следующее:142014211. Необходимо присоединить экземпляр [`Formatter`](https://python-all.ru/3.8/library/logging.html#logging.Formatter) к экземпляру [`SysLogHandler`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.SysLogHandler), указав строку формата, например:14221423   ```python1424   'ASCII section\ufeffUnicode section'1425   ```14261427   Кодовая точка Unicode U+FEFF при кодировании в UTF-8 будет представлена как метка порядка байтов UTF-8 – строка байтов `b'\xef\xbb\xbf'`.14282. ASCII-часть следует заменить на любые подходящие заполнители, но необходимо следить, чтобы данные, которые появляются там после подстановки, всегда были в ASCII (таким образом, они останутся без изменений после кодирования UTF-8).14293. Unicode-часть следует заменить на любые заполнители; если данные после подстановки содержат символы за пределами диапазона ASCII, это нормально – они будут закодированы в UTF-8.14301431Отформатированное сообщение *будет* закодировано в UTF-8 с помощью `SysLogHandler`. Если следовать приведённым выше правилам, можно создавать сообщения, соответствующие [**RFC 5424**](https://python-all.ru/3.8/howto/logging-cookbook.html). Если этого не делать, модуль logging может не жаловаться, но сообщения не будут соответствовать RFC 5424, и демон syslog может выражать недовольство.14321433## Реализация структурированного ведения журнала14341435Хотя большинство сообщений журнала предназначены для чтения человеком и поэтому не предназначены для машинного разбора, могут возникнуть ситуации, когда требуется выводить сообщения в структурированном формате, *который* может быть разобран программой (без необходимости в сложных регулярных выражениях). Это легко достигается с помощью пакета logging. Существует несколько способов, но ниже приведён простой подход, использующий JSON для сериализации события в машиночитаемом виде.14361437```python1438import json1439import logging14401441class StructuredMessage:1442    def __init__(self, message, /, **kwargs):1443        self.message = message1444        self.kwargs = kwargs14451446    def __str__(self):1447        return '%s >>> %s' % (self.message, json.dumps(self.kwargs))14481449_ = StructuredMessage   # необязательно, для улучшения читаемости14501451logging.basicConfig(level=logging.INFO, format='%(message)s')1452logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))1453```14541455Если запустить приведённый выше скрипт, он выведет:14561457```text1458message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}1459```14601461Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.14621463Если требуется более специализированная обработка, можно использовать пользовательский кодировщик JSON, как в следующем полном примере:14641465```python1466from __future__ import unicode_literals14671468import json1469import logging14701471# Следующий фрагмент предназначен для того, чтобы скрипт работал без изменений в версиях 2.x и 3.x.1472try:1473    unicode1474except NameError:1475    unicode = str14761477class Encoder(json.JSONEncoder):1478    def default(self, o):1479        if isinstance(o, set):1480            return tuple(o)1481        elif isinstance(o, unicode):1482            return o.encode('unicode_escape').decode('ascii')1483        return super().default(o)14841485class StructuredMessage:1486    def __init__(self, message, /, **kwargs):1487        self.message = message1488        self.kwargs = kwargs14891490    def __str__(self):1491        s = Encoder().encode(self.kwargs)1492        return '%s >>> %s' % (self.message, s)14931494_ = StructuredMessage   # необязательно, для улучшения читаемости14951496def main():1497    logging.basicConfig(level=logging.INFO, format='%(message)s')1498    logging.info(_('message 1', set_value={1, 2, 3}, snowman='\u2603'))14991500if __name__ == '__main__':1501    main()1502```15031504При запуске приведённого выше скрипта он выведет:15051506```text1507message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}1508```15091510Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.15111512## Настройка обработчиков с помощью [`dictConfig()`](https://python-all.ru/3.8/library/logging.config.html#logging.config.dictConfig)15131514Иногда требуется настроить обработчики логирования особым образом, и при использовании [`dictConfig()`](https://python-all.ru/3.8/library/logging.config.html#logging.config.dictConfig) это можно сделать без создания подклассов. Например, может потребоваться установить владельца файла журнала. В POSIX это легко сделать с помощью [`shutil.chown()`](https://python-all.ru/3.8/library/shutil.html#shutil.chown), но файловые обработчики в стандартной библиотеке не предоставляют встроенной поддержки. Можно настроить создание обработчика с помощью обычной функции, такой как:15151516```python1517def owned_file_handler(filename, mode='a', encoding=None, owner=None):1518    if owner:1519        if not os.path.exists(filename):1520            open(filename, 'a').close()1521        shutil.chown(filename, *owner)1522    return logging.FileHandler(filename, mode, encoding)1523```15241525Затем в конфигурации логирования, передаваемой в [`dictConfig()`](https://python-all.ru/3.8/library/logging.config.html#logging.config.dictConfig), можно указать, что обработчик должен быть создан вызовом этой функции:15261527```python1528LOGGING = {1529    'version': 1,1530    'disable_existing_loggers': False,1531    'formatters': {1532        'default': {1533            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'1534        },1535    },1536    'handlers': {1537        'file':{1538            # Значения ниже извлекаются из этого словаря и1539            # используются для создания обработчика, установки его уровня и1540            # его форматтера.1541            '()': owned_file_handler,1542            'level':'DEBUG',1543            'formatter': 'default',1544            # Значения ниже передаются вызываемому объекту-создателю обработчика1545            # в качестве именованных аргументов.1546            'owner': ['pulse', 'pulse'],1547            'filename': 'chowntest.log',1548            'mode': 'w',1549            'encoding': 'utf-8',1550        },1551    },1552    'root': {1553        'handlers': ['file'],1554        'level': 'DEBUG',1555    },1556}1557```15581559В этом примере для иллюстрации права владения устанавливаются с использованием пользователя и группы `pulse`. Собирая всё вместе в рабочий скрипт, `chowntest.py`:15601561```python1562import logging, logging.config, os, shutil15631564def owned_file_handler(filename, mode='a', encoding=None, owner=None):1565    if owner:1566        if not os.path.exists(filename):1567            open(filename, 'a').close()1568        shutil.chown(filename, *owner)1569    return logging.FileHandler(filename, mode, encoding)15701571LOGGING = {1572    'version': 1,1573    'disable_existing_loggers': False,1574    'formatters': {1575        'default': {1576            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'1577        },1578    },1579    'handlers': {1580        'file':{1581            # Значения ниже извлекаются из этого словаря и1582            # используются для создания обработчика, установки его уровня и1583            # его форматтера.1584            '()': owned_file_handler,1585            'level':'DEBUG',1586            'formatter': 'default',1587            # Значения ниже передаются вызываемому объекту-создателю обработчика1588            # в качестве именованных аргументов.1589            'owner': ['pulse', 'pulse'],1590            'filename': 'chowntest.log',1591            'mode': 'w',1592            'encoding': 'utf-8',1593        },1594    },1595    'root': {1596        'handlers': ['file'],1597        'level': 'DEBUG',1598    },1599}16001601logging.config.dictConfig(LOGGING)1602logger = logging.getLogger('mylogger')1603logger.debug('A debug message')1604```16051606Для запуска, вероятно, потребуется выполнить от имени `root`:16071608```console1609$ sudo python3.3 chowntest.py1610$ cat chowntest.log16112013-11-05 09:34:51,128 DEBUG mylogger A debug message1612$ ls -l chowntest.log1613-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log1614```16151616Обратите внимание, что в этом примере используется Python 3.3, потому что в нём появился [`shutil.chown()`](https://python-all.ru/3.8/library/shutil.html#shutil.chown). Этот подход должен работать с любой версией Python, поддерживающей [`dictConfig()`](https://python-all.ru/3.8/library/logging.config.html#logging.config.dictConfig) – а именно Python 2.7, 3.2 или новее. В версиях до 3.3 потребовалось бы реализовать фактическую смену владельца, например, с помощью [`os.chown()`](https://python-all.ru/3.8/library/os.html#os.chown).16171618На практике функция создания обработчика может находиться в служебном модуле где-нибудь в вашем проекте. Вместо строки в конфигурации:16191620```python1621'()': owned_file_handler,1622```16231624можно использовать, например:16251626```python1627'()': 'ext://project.util.owned_file_handler',1628```16291630где `project.util` можно заменить на фактическое имя пакета, в котором находится функция. В приведённом рабочем скрипте должно сработать использование `'ext://__main__.owned_file_handler'`. Здесь фактический вызываемый объект разрешается с помощью [`dictConfig()`](https://python-all.ru/3.8/library/logging.config.html#logging.config.dictConfig) из спецификации `ext://`.16311632Этот пример, надеюсь, также показывает, как можно реализовать другие типы изменений файлов – например, установку определённых битов разрешений POSIX – аналогичным образом, с помощью [`os.chmod()`](https://python-all.ru/3.8/library/os.html#os.chmod).16331634Разумеется, этот подход можно распространить и на другие типы обработчиков, помимо [`FileHandler`](https://python-all.ru/3.8/library/logging.handlers.html#logging.FileHandler) – например, на один из вращающихся файловых обработчиков или на совершенно другой тип обработчика.16351636## Использование определённых стилей форматирования во всём приложении16371638В Python 3.2 у [`Formatter`](https://python-all.ru/3.8/library/logging.html#logging.Formatter) появился именованный параметр `style`, который, хотя по умолчанию для обратной совместимости он равен `%`, позволяет указать `{` или `$` для поддержки подходов к форматированию, поддерживаемых [`str.format()`](https://python-all.ru/3.8/library/stdtypes.html#str.format) и [`string.Template`](https://python-all.ru/3.8/library/string.html#string.Template). Обратите внимание, что это управляет форматированием сообщений журнала для окончательного вывода в журнал и совершенно не зависит от того, как конструируется отдельное сообщение журнала.16391640Вызовы логирования ([`debug()`](https://python-all.ru/3.8/library/logging.html#logging.Logger.debug), [`info()`](https://python-all.ru/3.8/library/logging.html#logging.Logger.info) и т.д.) принимают только позиционные параметры для самого сообщения логирования, а именованные параметры используются только для определения параметров обработки вызова (например, именованный параметр `exc_info` для указания, что информация о трассировке должна быть записана в журнал, или именованный параметр `extra` для указания дополнительной контекстной информации, добавляемой в журнал). Поэтому вы не можете напрямую выполнять вызовы логирования с использованием синтаксиса [`str.format()`](https://python-all.ru/3.8/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.8/library/string.html#string.Template), потому что внутренне пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Это нельзя изменить, сохраняя обратную совместимость, поскольку все существующие вызовы логирования в коде используют %-форматирование строк.16411642Высказывались предложения связывать стили форматирования с конкретными регистраторами, но этот подход также сталкивается с проблемами обратной совместимости, поскольку любой существующий код может использовать данное имя регистратора и %-форматирование.16431644Чтобы логирование работало совместимо между любыми сторонними библиотеками и вашим кодом, решения о форматировании необходимо принимать на уровне отдельного вызова логирования. Это открывает несколько способов, которыми можно реализовать альтернативные стили форматирования.16451646### Использование фабрик LogRecord16471648В Python 3.2, вместе с упомянутыми выше изменениями [`Formatter`](https://python-all.ru/3.8/library/logging.html#logging.Formatter), пакет logging получил возможность позволять пользователям устанавливать свои собственные подклассы [`LogRecord`](https://python-all.ru/3.8/library/logging.html#logging.LogRecord) с помощью функции [`setLogRecordFactory()`](https://python-all.ru/3.8/library/logging.html#logging.setLogRecordFactory). Вы можете использовать это, чтобы установить свой собственный подкласс [`LogRecord`](https://python-all.ru/3.8/library/logging.html#logging.LogRecord), который делает правильные вещи, переопределяя метод [`getMessage()`](https://python-all.ru/3.8/library/logging.html#logging.LogRecord.getMessage). В реализации базового класса этого метода происходит форматирование `msg % args`, и именно здесь можно подставить альтернативное форматирование; однако следует быть осторожным, чтобы поддерживать все стили форматирования и разрешить %-форматирование по умолчанию для обеспечения совместимости с другим кодом. Также следует позаботиться о вызове `str(self.msg)`, как это делает базовая реализация.16491650Обратитесь к справочной документации по [`setLogRecordFactory()`](https://python-all.ru/3.8/library/logging.html#logging.setLogRecordFactory) и [`LogRecord`](https://python-all.ru/3.8/library/logging.html#logging.LogRecord) для получения дополнительной информации.16511652### Использование пользовательских объектов сообщений16531654Есть еще один, возможно, более простой способ использовать {}- и $-форматирование для построения отдельных сообщений лога. Вы, возможно, помните (из раздела [Использование произвольных объектов в качестве сообщений](https://python-all.ru/3.8/howto/logging.html#arbitrary-object-messages)), что при логировании можно использовать произвольный объект в качестве строки формата сообщения, и пакет logging вызовет [`str()`](https://python-all.ru/3.8/library/stdtypes.html#str) для этого объекта, чтобы получить фактическую строку формата. Рассмотрим следующие два класса:16551656```python1657class BraceMessage:1658    def __init__(self, fmt, /, *args, **kwargs):1659        self.fmt = fmt1660        self.args = args1661        self.kwargs = kwargs16621663    def __str__(self):1664        return self.fmt.format(*self.args, **self.kwargs)16651666class DollarMessage:1667    def __init__(self, fmt, /, **kwargs):1668        self.fmt = fmt1669        self.kwargs = kwargs16701671    def __str__(self):1672        from string import Template1673        return Template(self.fmt).substitute(**self.kwargs)1674```16751676Любой из них можно использовать вместо строки формата, чтобы разрешить {}- или $-форматирование для построения фактической части «message», которая появляется в форматированном выводе лога вместо «%(message)s», «{message}» или «$message». Если вам кажется неудобным использовать имена классов каждый раз при логировании, вы можете сделать это более приятным, используя псевдоним, такой как `M` или `_` для сообщения (или, возможно, `__`, если вы используете `_` для локализации).16771678Примеры этого подхода приведены ниже. Во-первых, форматирование с помощью [`str.format()`](https://python-all.ru/3.8/library/stdtypes.html#str.format):16791680```python1681>>> __ = BraceMessage1682>>> print(__('Message with {0} {1}', 2, 'placeholders'))1683Message with 2 placeholders1684>>> class Point: pass1685...1686>>> p = Point()1687>>> p.x = 0.51688>>> p.y = 0.51689>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))1690Message with coordinates: (0.50, 0.50)1691```16921693Во-вторых, форматирование с помощью [`string.Template`](https://python-all.ru/3.8/library/string.html#string.Template):16941695```python1696>>> __ = DollarMessage1697>>> print(__('Message with $num $what', num=2, what='placeholders'))1698Message with 2 placeholders1699>>>1700```17011702Стоит отметить, что при таком подходе вы не платите значительных потерь производительности: фактическое форматирование происходит не при вызове логирования, а когда (и если) сообщение лога действительно должно быть выведено в лог обработчиком. Так что единственная необычная вещь, которая может вас сбить с толку, это то, что круглые скобки ставятся вокруг строки формата и аргументов, а не только вокруг строки формата. Это потому, что нотация \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов `XXXMessage`, показанных выше.17031704## Настройка фильтров с помощью [`dictConfig()`](https://python-all.ru/3.8/library/logging.config.html#logging.config.dictConfig)17051706*Можно* настраивать фильтры с помощью [`dictConfig()`](https://python-all.ru/3.8/library/logging.config.html#logging.config.dictConfig), хотя с первого взгляда может быть неочевидно, как это сделать (поэтому и дан этот рецепт). Поскольку [`Filter`](https://python-all.ru/3.8/library/logging.html#logging.Filter) – единственный класс фильтра, включенный в стандартную библиотеку, и вряд ли он удовлетворит многие требования (он присутствует только как базовый класс), вам, как правило, потребуется определить свой собственный подкласс [`Filter`](https://python-all.ru/3.8/library/logging.html#logging.Filter) с переопределенным методом [`filter()`](https://python-all.ru/3.8/library/logging.html#logging.Filter.filter). Для этого укажите ключ `()` в словаре конфигурации для фильтра, указав вызываемый объект, который будет использоваться для создания фильтра (класс – наиболее очевидный вариант, но вы можете предоставить любой вызываемый объект, возвращающий экземпляр [`Filter`](https://python-all.ru/3.8/library/logging.html#logging.Filter)). Вот полный пример:17071708```python1709import logging1710import logging.config1711import sys17121713class MyFilter(logging.Filter):1714    def __init__(self, param=None):1715        self.param = param17161717    def filter(self, record):1718        if self.param is None:1719            allow = True1720        else:1721            allow = self.param not in record.msg1722        if allow:1723            record.msg = 'changed: ' + record.msg1724        return allow17251726LOGGING = {1727    'version': 1,1728    'filters': {1729        'myfilter': {1730            '()': MyFilter,1731            'param': 'noshow',1732        }1733    },1734    'handlers': {1735        'console': {1736            'class': 'logging.StreamHandler',1737            'filters': ['myfilter']1738        }1739    },1740    'root': {1741        'level': 'DEBUG',1742        'handlers': ['console']1743    },1744}17451746if __name__ == '__main__':1747    logging.config.dictConfig(LOGGING)1748    logging.debug('hello')1749    logging.debug('hello - noshow')1750```17511752Этот пример показывает, как можно передавать конфигурационные данные вызываемому объекту, который создает экземпляр, в виде именованных параметров. При запуске приведенный выше скрипт выведет:17531754```text1755changed: hello1756```17571758что показывает, что фильтр работает в соответствии с настройками.17591760Несколько дополнительных моментов, на которые стоит обратить внимание:17611762- Если вы не можете сослаться на вызываемый объект напрямую в конфигурации (например, если он находится в другом модуле, и вы не можете импортировать его напрямую в том месте, где находится словарь конфигурации), вы можете использовать форму `ext://...`, как описано в разделе [Доступ к внешним объектам](https://python-all.ru/3.8/library/logging.config.html#logging-config-dict-externalobj). Например, в приведенном выше примере можно было использовать текст `'ext://__main__.MyFilter'` вместо `MyFilter`.1763- Помимо фильтров, этот метод также можно использовать для настройки пользовательских обработчиков и форматтеров. Смотрите раздел [Пользовательские объекты](https://python-all.ru/3.8/library/logging.config.html#logging-config-dict-userdef) для получения дополнительной информации о том, как logging поддерживает использование пользовательских объектов в своей конфигурации, а также см. другой рецепт из этой книги рецептов [Настройка обработчиков с помощью dictConfig()](https://python-all.ru/3.8/howto/logging-cookbook.html#custom-handlers) выше.17641765## Настраиваемое форматирование исключений17661767Могут возникнуть ситуации, когда вы захотите настроить форматирование исключений – для примера, предположим, вы хотите ровно одну строку на каждое событие лога, даже если присутствует информация об исключении. Вы можете сделать это с помощью пользовательского класса форматтера, как показано в следующем примере:17681769```python1770import logging17711772class OneLineExceptionFormatter(logging.Formatter):1773    def formatException(self, exc_info):1774        """1775        Форматировать исключение так, чтобы оно выводилось одной строкой.1776        """1777        result = super().formatException(exc_info)1778        return repr(result)  # или форматировать одной строкой по своему усмотрению17791780    def format(self, record):1781        s = super().format(record)1782        if record.exc_text:1783            s = s.replace('\n', '') + '|'1784        return s17851786def configure_logging():1787    fh = logging.FileHandler('output.txt', 'w')1788    f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',1789                                  '%d/%m/%Y %H:%M:%S')1790    fh.setFormatter(f)1791    root = logging.getLogger()1792    root.setLevel(logging.DEBUG)1793    root.addHandler(fh)17941795def main():1796    configure_logging()1797    logging.info('Sample message')1798    try:1799        x = 1 / 01800    except ZeroDivisionError as e:1801        logging.exception('ZeroDivisionError: %s', e)18021803if __name__ == '__main__':1804    main()1805```18061807При запуске это создает файл ровно с двумя строками:18081809```text181028/01/2015 07:21:23|INFO|Sample message|181128/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'|1812```18131814Хотя описанный выше подход упрощен, он показывает путь к тому, как можно форматировать информацию об исключениях по своему вкусу. Модуль [`traceback`](https://python-all.ru/3.8/library/traceback.html#module-traceback) может быть полезен для более специализированных нужд.18151816## Озвучивание сообщений лога18171818Могут быть ситуации, когда желательно выводить сообщения лога в звуковом, а не визуальном формате. Это легко сделать, если в вашей системе доступна функция преобразования текста в речь (TTS), даже если у нее нет привязки к Python. Большинство TTS-систем имеют программу командной строки, которую можно запустить, и ее можно вызвать из обработчика с помощью [`subprocess`](https://python-all.ru/3.8/library/subprocess.html#module-subprocess). Здесь предполагается, что программы командной строки TTS не будут ожидать взаимодействия с пользователем или занимать много времени для завершения, и что частота сообщений лога не будет настолько высокой, чтобы перегружать пользователя сообщениями, и что допустимо проговаривать сообщения по одному, а не одновременно. В приведенном ниже примере реализации ожидается, пока одно сообщение не будет произнесено, прежде чем обрабатывать следующее, и это может заставить другие обработчики ждать. Вот короткий пример, демонстрирующий подход, который предполагает, что доступен TTS-пакет `espeak`:18191820```python1821import logging1822import subprocess1823import sys18241825class TTSHandler(logging.Handler):1826    def emit(self, record):1827        msg = self.format(record)1828        # Говорить медленно женским английским голосом.1829        cmd = ['espeak', '-s150', '-ven+f3', msg]1830        p = subprocess.Popen(cmd, stdout=subprocess.PIPE,1831                             stderr=subprocess.STDOUT)1832        # дождаться завершения программы1833        p.communicate()18341835def configure_logging():1836    h = TTSHandler()1837    root = logging.getLogger()1838    root.addHandler(h)1839    # стандартный форматтер просто возвращает сообщение1840    root.setLevel(logging.DEBUG)18411842def main():1843    logging.info('Hello')1844    logging.debug('Goodbye')18451846if __name__ == '__main__':1847    configure_logging()1848    sys.exit(main())1849```18501851При запуске этот скрипт должен сказать «Hello», а затем «Goodbye» женским голосом.18521853Описанный выше подход, конечно, можно адаптировать для других TTS-систем и даже для других систем, которые могут обрабатывать сообщения через внешние программы, запускаемые из командной строки.18541855## Буферизация сообщений лога и условный вывод18561857Могут возникнуть ситуации, когда вы хотите записывать сообщения во временную область и выводить их только при наступлении определенного условия. Например, вы можете начать запись отладочных событий в функции, и если функция завершится без ошибок, вы не захотите засорять лог собранной отладочной информацией, но если возникнет ошибка, вы захотите вывести всю отладочную информацию вместе с ошибкой.18581859Вот пример, показывающий, как это можно сделать с помощью декоратора для ваших функций, где вы хотите, чтобы логирование вело себя таким образом. Он использует [`logging.handlers.MemoryHandler`](https://python-all.ru/3.8/library/logging.handlers.html#logging.handlers.MemoryHandler), который позволяет буферизовать зарегистрированные события до наступления некоторого условия, после чего буферизованные события `flushed` – передаются другому обработчику (обработчику `target`) для обработки. По умолчанию `MemoryHandler` сбрасывается, когда его буфер заполняется или встречается событие, уровень которого больше или равен указанному порогу. Вы можете использовать этот рецепт с более специализированным подклассом `MemoryHandler`, если хотите настроить поведение сброса.18601861Пример скрипта содержит простую функцию `foo`, которая просто перебирает все уровни логирования, записывая в `sys.stderr` информацию о том, какой уровень будет использоваться, а затем регистрирует сообщение на этом уровне. Вы можете передать параметр в `foo`, который, если равен true, будет регистрировать на уровнях ERROR и CRITICAL – в противном случае он регистрирует только на уровнях DEBUG, INFO и WARNING.18621863Скрипт просто настраивает декорирование `foo` декоратором, который будет выполнять необходимое условное логирование. Декоратор принимает регистратор в качестве параметра и подключает обработчик памяти на время вызова декорированной функции. Декоратор можно дополнительно параметризовать с помощью целевого обработчика, уровня, при котором должен происходить сброс, и емкости буфера (количество буферизируемых записей). По умолчанию они равны [`StreamHandler`](https://python-all.ru/3.8/library/logging.handlers.html#logging.StreamHandler), который пишет в `sys.stderr`, `logging.ERROR` и `100` соответственно.18641865Вот скрипт:18661867```python1868import logging1869from logging.handlers import MemoryHandler1870import sys18711872logger = logging.getLogger(__name__)1873logger.addHandler(logging.NullHandler())18741875def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):1876    if target_handler is None:1877        target_handler = logging.StreamHandler()1878    if flush_level is None:1879        flush_level = logging.ERROR1880    if capacity is None:1881        capacity = 1001882    handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)18831884    def decorator(fn):1885        def wrapper(*args, **kwargs):1886            logger.addHandler(handler)1887            try:1888                return fn(*args, **kwargs)1889            except Exception:1890                logger.exception('call failed')1891                raise1892            finally:1893                super(MemoryHandler, handler).flush()1894                logger.removeHandler(handler)1895        return wrapper18961897    return decorator18981899def write_line(s):1900    sys.stderr.write('%s\n' % s)19011902def foo(fail=False):1903    write_line('about to log at DEBUG ...')1904    logger.debug('Actually logged at DEBUG')1905    write_line('about to log at INFO ...')1906    logger.info('Actually logged at INFO')1907    write_line('about to log at WARNING ...')1908    logger.warning('Actually logged at WARNING')1909    if fail:1910        write_line('about to log at ERROR ...')1911        logger.error('Actually logged at ERROR')1912        write_line('about to log at CRITICAL ...')1913        logger.critical('Actually logged at CRITICAL')1914    return fail19151916decorated_foo = log_if_errors(logger)(foo)19171918if __name__ == '__main__':1919    logger.setLevel(logging.DEBUG)1920    write_line('Calling undecorated foo with False')1921    assert not foo(False)1922    write_line('Calling undecorated foo with True')1923    assert foo(True)1924    write_line('Calling decorated foo with False')1925    assert not decorated_foo(False)1926    write_line('Calling decorated foo with True')1927    assert decorated_foo(True)1928```19291930При запуске этого скрипта отобразится следующий вывод:19311932```text1933Calling undecorated foo with False1934about to log at DEBUG ...1935about to log at INFO ...1936about to log at WARNING ...1937Calling undecorated foo with True1938about to log at DEBUG ...1939about to log at INFO ...1940about to log at WARNING ...1941about to log at ERROR ...1942about to log at CRITICAL ...1943Calling decorated foo with False1944about to log at DEBUG ...1945about to log at INFO ...1946about to log at WARNING ...1947Calling decorated foo with True1948about to log at DEBUG ...1949about to log at INFO ...1950about to log at WARNING ...1951about to log at ERROR ...1952Actually logged at DEBUG1953Actually logged at INFO1954Actually logged at WARNING1955Actually logged at ERROR1956about to log at CRITICAL ...1957Actually logged at CRITICAL1958```19591960Как видно, фактический вывод журнала происходит только при регистрации события, уровень которого ERROR или выше, но в этом случае также регистрируются все предыдущие события с более низкими уровнями.19611962Конечно, можно использовать обычные средства декорирования:19631964```python1965@log_if_errors(logger)1966def foo(fail=False):1967    ...1968```19691970## Форматирование времени с использованием UTC (GMT) через конфигурацию19711972Иногда требуется форматировать время по UTC, что можно сделать с помощью класса такого как *UTCFormatter*, показанного ниже:19731974```python1975import logging1976import time19771978class UTCFormatter(logging.Formatter):1979    converter = time.gmtime1980```19811982и затем можно использовать `UTCFormatter` в своём коде вместо [`Formatter`](https://python-all.ru/3.8/library/logging.html#logging.Formatter). Если требуется сделать это через конфигурацию, можно воспользоваться API [`dictConfig()`](https://python-all.ru/3.8/library/logging.config.html#logging.config.dictConfig), как показано в следующем полном примере:19831984```python1985import logging1986import logging.config1987import time19881989class UTCFormatter(logging.Formatter):1990    converter = time.gmtime19911992LOGGING = {1993    'version': 1,1994    'disable_existing_loggers': False,1995    'formatters': {1996        'utc': {1997            '()': UTCFormatter,1998            'format': '%(asctime)s %(message)s',1999        },2000        'local': {2001            'format': '%(asctime)s %(message)s',2002        }2003    },2004    'handlers': {2005        'console1': {2006            'class': 'logging.StreamHandler',2007            'formatter': 'utc',2008        },2009        'console2': {2010            'class': 'logging.StreamHandler',2011            'formatter': 'local',2012        },2013    },2014    'root': {2015        'handlers': ['console1', 'console2'],2016   }2017}20182019if __name__ == '__main__':2020    logging.config.dictConfig(LOGGING)2021    logging.warning('The local time is %s', time.asctime())2022```20232024При запуске этого скрипта он должен вывести примерно следующее:20252026```text20272015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 201520282015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 20152029```20302031показывая, как время форматируется как в местном времени, так и в UTC, по одному для каждого обработчика.20322033## Использование контекстного менеджера для выборочного журналирования20342035Бывают ситуации, когда полезно временно изменить конфигурацию журналирования, а затем вернуть её обратно после выполнения каких-то действий. Для этого контекстный менеджер – самый очевидный способ сохранить и восстановить контекст журналирования. Вот простой пример такого контекстного менеджера, который позволяет по желанию изменить уровень журналирования и добавить обработчик журнала исключительно в области действия контекстного менеджера:20362037```python2038import logging2039import sys20402041class LoggingContext:2042    def __init__(self, logger, level=None, handler=None, close=True):2043        self.logger = logger2044        self.level = level2045        self.handler = handler2046        self.close = close20472048    def __enter__(self):2049        if self.level is not None:2050            self.old_level = self.logger.level2051            self.logger.setLevel(self.level)2052        if self.handler:2053            self.logger.addHandler(self.handler)20542055    def __exit__(self, et, ev, tb):2056        if self.level is not None:2057            self.logger.setLevel(self.old_level)2058        if self.handler:2059            self.logger.removeHandler(self.handler)2060        if self.handler and self.close:2061            self.handler.close()2062        # неявный возврат None => не подавлять исключения2063```20642065Если указать значение уровня, уровень регистратора устанавливается на это значение в области действия блока with, охватываемого контекстным менеджером. Если указать обработчик, он добавляется к регистратору при входе в блок и удаляется при выходе из блока. Также можно попросить менеджер закрыть обработчик при выходе из блока – это можно сделать, если обработчик больше не нужен.20662067Чтобы проиллюстрировать, как это работает, можно добавить следующий блок кода к предыдущему:20682069```python2070if __name__ == '__main__':2071    logger = logging.getLogger('foo')2072    logger.addHandler(logging.StreamHandler())2073    logger.setLevel(logging.INFO)2074    logger.info('1. This should appear just once on stderr.')2075    logger.debug('2. This should not appear.')2076    with LoggingContext(logger, level=logging.DEBUG):2077        logger.debug('3. This should appear once on stderr.')2078    logger.debug('4. This should not appear.')2079    h = logging.StreamHandler(sys.stdout)2080    with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):2081        logger.debug('5. This should appear twice - once on stderr and once on stdout.')2082    logger.info('6. This should appear just once on stderr.')2083    logger.debug('7. This should not appear.')2084```20852086Изначально устанавливаем уровень регистратора равным `INFO`, поэтому сообщение №1 отображается, а сообщение №2 – нет. Затем временно меняем уровень на `DEBUG` в следующем блоке `with`, и сообщение №3 отображается. После выхода из блока уровень регистратора восстанавливается до `INFO`, поэтому сообщение №4 не отображается. В следующем блоке `with` снова устанавливаем уровень `DEBUG`, но также добавляем обработчик, записывающий в `sys.stdout`. Таким образом, сообщение №5 отображается дважды на консоли (один раз через `stderr` и один раз через `stdout`). После завершения оператора `with` состояние возвращается к исходному, поэтому сообщение №6 отображается (как сообщение №1), а сообщение №7 – нет (как сообщение №2).20872088Если запустить полученный скрипт, результат будет следующим:20892090```console2091$ python logctx.py20921. This should appear just once on stderr.20933. This should appear once on stderr.20945. This should appear twice - once on stderr and once on stdout.20955. This should appear twice - once on stderr and once on stdout.20966. This should appear just once on stderr.2097```20982099Если запустить его снова, но перенаправить `stderr` в `/dev/null`, мы увидим следующее, что является единственным сообщением, записанным в `stdout`:21002101```console2102$ python logctx.py 2>/dev/null21035. This should appear twice - once on stderr and once on stdout.2104```21052106Ещё раз, но перенаправляя `stdout` в `/dev/null`, получаем:21072108```console2109$ python logctx.py >/dev/null21101. This should appear just once on stderr.21113. This should appear once on stderr.21125. This should appear twice - once on stderr and once on stdout.21136. This should appear just once on stderr.2114```21152116В этом случае сообщение №5, выведенное в `stdout`, не отображается, как и ожидалось.21172118Разумеется, описанный подход можно обобщить, например, для временного подключения фильтров журналирования. Обратите внимание, что приведённый выше код работает как в Python 2, так и в Python 3.21192120## Шаблон для запуска CLI-приложения21212122Вот пример, показывающий, как можно:21232124- Использовать уровень журналирования на основе аргументов командной строки2125- Перенаправлять вызовы к нескольким подкомандам в отдельных файлах, все с журналированием на одном уровне согласованным образом2126- Использовать простую минимальную конфигурацию21272128Предположим, у нас есть приложение командной строки, которое останавливает, запускает или перезапускает некоторые службы. Для иллюстрации это может быть организовано в виде файла `app.py`, который является главным скриптом приложения, с отдельными командами, реализованными в `start.py`, `stop.py` и `restart.py`. Предположим также, что мы хотим управлять степенью подробности вывода приложения через аргумент командной строки с значением по умолчанию `logging.INFO`. Вот один из способов, как мог бы быть написан `app.py`:21292130```python2131import argparse2132import importlib2133import logging2134import os2135import sys21362137def main(args=None):2138    scriptname = os.path.basename(__file__)2139    parser = argparse.ArgumentParser(scriptname)2140    levels = ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')2141    parser.add_argument('--log-level', default='INFO', choices=levels)2142    subparsers = parser.add_subparsers(dest='command',2143                                       help='Available commands:')2144    start_cmd = subparsers.add_parser('start', help='Start a service')2145    start_cmd.add_argument('name', metavar='NAME',2146                           help='Name of service to start')2147    stop_cmd = subparsers.add_parser('stop',2148                                     help='Stop one or more services')2149    stop_cmd.add_argument('names', metavar='NAME', nargs='+',2150                          help='Name of service to stop')2151    restart_cmd = subparsers.add_parser('restart',2152                                        help='Restart one or more services')2153    restart_cmd.add_argument('names', metavar='NAME', nargs='+',2154                             help='Name of service to restart')2155    options = parser.parse_args()2156    # весь код для отправки команд мог бы быть в этом файле. Для целей2157    # только в целях иллюстрации каждая команда реализована в отдельном модуле.2158    try:2159        mod = importlib.import_module(options.command)2160        cmd = getattr(mod, 'command')2161    except (ImportError, AttributeError):2162        print('Unable to find the code for command \'%s\'' % options.command)2163        return 12164    # Здесь можно было бы сделать по-хитрому и загрузить конфигурацию из файла или словаря2165    logging.basicConfig(level=options.log_level,2166                        format='%(levelname)s %(name)s %(message)s')2167    cmd(options)21682169if __name__ == '__main__':2170    sys.exit(main())2171```21722173А команды `start`, `stop` и `restart` могут быть реализованы в отдельных модулях, например, для запуска:21742175```python2176# start.py2177import logging21782179logger = logging.getLogger(__name__)21802181def command(options):2182    logger.debug('About to start %s', options.name)2183    # здесь происходит фактическая обработка команды...2184    logger.info('Started the \'%s\' service.', options.name)2185```21862187и аналогично для остановки:21882189```python2190# stop.py2191import logging21922193logger = logging.getLogger(__name__)21942195def command(options):2196    n = len(options.names)2197    if n == 1:2198        plural = ''2199        services = '\'%s\'' % options.names[0]2200    else:2201        plural = 's'2202        services = ', '.join('\'%s\'' % name for name in options.names)2203        i = services.rfind(', ')2204        services = services[:i] + ' and ' + services[i + 2:]2205    logger.debug('About to stop %s', services)2206    # здесь происходит фактическая обработка команды...2207    logger.info('Stopped the %s service%s.', services, plural)2208```22092210и аналогично для перезапуска:22112212```python2213# restart.py2214import logging22152216logger = logging.getLogger(__name__)22172218def command(options):2219    n = len(options.names)2220    if n == 1:2221        plural = ''2222        services = '\'%s\'' % options.names[0]2223    else:2224        plural = 's'2225        services = ', '.join('\'%s\'' % name for name in options.names)2226        i = services.rfind(', ')2227        services = services[:i] + ' and ' + services[i + 2:]2228    logger.debug('About to restart %s', services)2229    # здесь происходит фактическая обработка команды...2230    logger.info('Restarted the %s service%s.', services, plural)2231```22322233Если запустить это приложение с уровнем журналирования по умолчанию, мы получим примерно такой вывод:22342235```console2236$ python app.py start foo2237INFO start Started the 'foo' service.22382239$ python app.py stop foo bar2240INFO stop Stopped the 'foo' and 'bar' services.22412242$ python app.py restart foo bar baz2243INFO restart Restarted the 'foo', 'bar' and 'baz' services.2244```22452246Первое слово – уровень журналирования, а второе – имя модуля или пакета, в котором было зарегистрировано событие.22472248Если изменить уровень журналирования, можно изменить объём информации, отправляемой в журнал. Например, чтобы получить больше информации:22492250```console2251$ python app.py --log-level DEBUG start foo2252DEBUG start About to start foo2253INFO start Started the 'foo' service.22542255$ python app.py --log-level DEBUG stop foo bar2256DEBUG stop About to stop 'foo' and 'bar'2257INFO stop Stopped the 'foo' and 'bar' services.22582259$ python app.py --log-level DEBUG restart foo bar baz2260DEBUG restart About to restart 'foo', 'bar' and 'baz'2261INFO restart Restarted the 'foo', 'bar' and 'baz' services.2262```22632264А если нужно меньше:22652266```console2267$ python app.py --log-level WARNING start foo2268$ python app.py --log-level WARNING stop foo bar2269$ python app.py --log-level WARNING restart foo bar baz2270```22712272В этом случае команды ничего не выводят в консоль, поскольку ни одно сообщение уровня `WARNING` и выше ими не записывается.22732274## Графический интерфейс Qt для журналирования22752276Время от времени возникает вопрос о том, как организовать логирование в GUI-приложении. Фреймворк [Qt](https://python-all.ru/3.8/howto/logging-cookbook.html) – популярная кроссплатформенная UI-среда с привязками к Python через библиотеки [PySide2](https://python-all.ru/3.8/howto/logging-cookbook.html) или [PyQt5](https://python-all.ru/3.8/howto/logging-cookbook.html).22772278В следующем примере показано, как выполнять журналирование в графический интерфейс Qt. Он представляет простой класс `QtHandler`, который принимает вызываемый объект – слот главного потока, обновляющий GUI. Также создаётся рабочий поток, чтобы продемонстрировать возможность журналирования как из самого интерфейса (через кнопку для ручной записи), так и из фонового рабочего потока (который в данном случае просто выводит сообщения со случайными уровнями и случайными короткими задержками).22792280Рабочий поток реализован с помощью класса `QThread` из Qt, а не модуля [`threading`](https://python-all.ru/3.8/library/threading.html#module-threading), поскольку бывают ситуации, когда необходимо использовать `QThread`, который обеспечивает лучшую интеграцию с другими компонентами `Qt`.22812282Код должен работать с последними версиями `PySide2` или `PyQt5`. Вы сможете адаптировать подход для более старых версий Qt. Обратитесь к комментариям в фрагменте кода за более подробной информацией.22832284```python2285import datetime2286import logging2287import random2288import sys2289import time22902291# Обработка мелких различий между PySide2 и PyQt52292try:2293    from PySide2 import QtCore, QtGui, QtWidgets2294    Signal = QtCore.Signal2295    Slot = QtCore.Slot2296except ImportError:2297    from PyQt5 import QtCore, QtGui, QtWidgets2298    Signal = QtCore.pyqtSignal2299    Slot = QtCore.pyqtSlot23002301logger = logging.getLogger(__name__)23022303#2304# Сигналы должны содержаться в QObject или подклассе, чтобы корректно2305# инициализироваться.2306#2307class Signaller(QtCore.QObject):2308    signal = Signal(str, logging.LogRecord)23092310#2311# Вывод в графический интерфейс Qt должен происходить только в главном потоке. Поэтому данный2312# обработчик спроектирован так, чтобы принимать функцию-слот, настроенную на выполнение в главном2313# потоке. В этом примере функция принимает строковый аргумент, который является2314# отформатированным сообщением лога, и запись лога, которая его породила. Отформатированная2315# строка – это просто удобство; можно отформатировать строку для вывода любым способом2316# в самой функции-слоте.2317#2318# Функцию-слот можно настроить на любые нужные обновления GUI. Обработчик2319# не знает и не заботится о конкретных элементах интерфейса.2320#2321class QtHandler(logging.Handler):2322    def __init__(self, slotfunc, *args, **kwargs):2323        super().__init__(*args, **kwargs)2324        self.signaller = Signaller()2325        self.signaller.signal.connect(slotfunc)23262327    def emit(self, record):2328        s = self.format(record)2329        self.signaller.signal.emit(s, record)23302331#2332# В этом примере используются QThreads, что означает, что потоки на уровне Python2333# называются как-то вроде "Dummy-1". Функция ниже получает имя Qt2334# текущего потока.2335#2336def ctname():2337    return QtCore.QThread.currentThread().objectName()23382339#2340# Используется для генерации случайных уровней для логирования.2341#2342LEVELS = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,2343          logging.CRITICAL)23442345#2346# Этот класс-воркер представляет работу, выполняемую в потоке, отдельном от2347# главного потока. Поток запускается на выполнение работы по нажатию кнопки,2348# которая соединяется со слотом в воркере.2349#2350# Поскольку значение threadName по умолчанию в LogRecord не очень полезно, мы добавляем2351# qThreadName, содержащий имя QThread, вычисленное выше, и передаём это2352# значение в словаре "extra", который используется для обновления LogRecord с помощью2353# имя QThread.2354#2355# Этот пример рабочего просто выводит сообщения последовательно, перемежая их случайными задержками порядка нескольких секунд.2356# Позволяет потоку выполняться до прерывания. Это обеспечивает достаточно чистую остановку потока.2357#2358class Worker(QtCore.QObject):2359    @Slot()2360    def start(self):2361        extra = {'qThreadName': ctname() }2362        logger.debug('Started work', extra=extra)2363        i = 12364        # Реализует простой пользовательский интерфейс для этого примера из кулинарной книги. Он содержит:2365        # * Окно текстового редактора только для чтения, которое содержит форматированные сообщения журнала2366        while not QtCore.QThread.currentThread().isInterruptionRequested():2367            delay = 0.5 + random.random() * 22368            time.sleep(delay)2369            level = random.choice(LEVELS)2370            logger.log(level, 'Message after delay of %3.1f: %d', delay, i, extra=extra)2371            i += 123722373#2374# * Кнопка запуска работы и записи в журнал в отдельном потоке2375#2376# * Кнопка записи чего-либо из основного потока2377# * Кнопка очистки окна журнала2378# Устанавливает моноширинный шрифт, принятый по умолчанию на платформе2379# для Qt62380#2381class Window(QtWidgets.QWidget):23822383    COLORS = {2384        logging.DEBUG: 'black',2385        logging.INFO: 'blue',2386        logging.WARNING: 'orange',2387        logging.ERROR: 'red',2388        logging.CRITICAL: 'purple',2389    }23902391    def __init__(self, app):2392        super().__init__()2393        self.app = app2394        self.textedit = te = QtWidgets.QPlainTextEdit(self)2395        # Устанавливает моноширинный шрифт по умолчанию для платформы2396        f = QtGui.QFont('nosuchfont')2397        f.setStyleHint(f.Monospace)2398        te.setFont(f)2399        te.setReadOnly(True)2400        PB = QtWidgets.QPushButton2401        self.work_button = PB('Start background work', self)2402        self.log_button = PB('Log a message at a random level', self)2403        self.clear_button = PB('Clear log window', self)2404        self.handler = h = QtHandler(self.update_status)2405        # Размещает все виджеты2406        fs = '%(asctime)s %(qThreadName)-12s %(levelname)-8s %(message)s'2407        formatter = logging.Formatter(fs)2408        h.setFormatter(formatter)2409        logger.addHandler(h)2410        # Подключает слоты и сигналы, не относящиеся к рабочему2411        app.aboutToQuit.connect(self.force_quit)24122413        # Запускает новый рабочий поток и подключает слоты для рабочего2414        layout = QtWidgets.QVBoxLayout(self)2415        layout.addWidget(te)2416        layout.addWidget(self.work_button)2417        layout.addWidget(self.log_button)2418        layout.addWidget(self.clear_button)2419        self.setFixedSize(900, 400)24202421        # После запуска кнопка должна быть отключена2422        self.log_button.clicked.connect(self.manual_update)2423        self.clear_button.clicked.connect(self.clear_display)24242425        # Запустить новый рабочий поток и подключить слоты для рабочего2426        self.start_thread()2427        self.work_button.clicked.connect(self.worker.start)2428        # Это запустит цикл событий в рабочем потоке2429        self.work_button.clicked.connect(lambda : self.work_button.setEnabled(False))24302431    def start_thread(self):2432        self.worker = Worker()2433        self.worker_thread = QtCore.QThread()2434        self.worker.setObjectName('Worker')2435        self.worker_thread.setObjectName('WorkerThread')  # Просто скажите рабочему остановиться, затем скажите ему выйти и дождитесь этого2436        self.worker.moveToThread(self.worker_thread)2437        # Для использования при закрытии окна2438        self.worker_thread.start()24392440    def kill_thread(self):2441        # Функции ниже обновляют интерфейс и выполняются в основном потоке, поскольку слоты настроены именно там2442        # Эта функция использует переданное форматированное сообщение, но также использует информацию из записи, чтобы отформатировать сообщение подходящим цветом в соответствии с его серьёзностью (уровнем).2443        self.worker_thread.requestInterruption()2444        if self.worker_thread.isRunning():2445            self.worker_thread.quit()2446            self.worker_thread.wait()2447        else:2448            print('worker has already exited.')24492450    def force_quit(self):2451        # Для использования при закрытии окна2452        if self.worker_thread.isRunning():2453            self.kill_thread()24542455    # Функции ниже обновляют пользовательский интерфейс и выполняются в главном потоке, потому что2456    # здесь настраиваются слоты24572458    @Slot(str, logging.LogRecord)2459    def update_status(self, status, record):2460        color = self.COLORS.get(record.levelno, 'black')2461        s = '<pre><font color="%s">%s</font></pre>' % (color, status)2462        self.textedit.appendHtml(s)24632464    @Slot()2465    def manual_update(self):2466        # Эта функция использует переданное форматированное сообщение, а также использует2467        # информацию из записи для форматирования сообщения в подходящий2468        # цвет в соответствии с его серьёзностью (уровнем).2469        level = random.choice(LEVELS)2470        extra = {'qThreadName': ctname() }2471        logger.log(level, 'Manually logged!', extra=extra)24722473    @Slot()2474    def clear_display(self):2475        self.textedit.clear()24762477def main():2478    QtCore.QThread.currentThread().setObjectName('MainThread')2479    logging.getLogger().setLevel(logging.DEBUG)2480    app = QtWidgets.QApplication(sys.argv)2481    example = Window(app)2482    example.show()2483    sys.exit(app.exec_())24842485if __name__=='__main__':2486    main()2487```2488