logging-cookbook.md

1> **Источник:** https://python-all.ru/3.9/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.9/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.9/library/logging.handlers.html#logging.handlers.SMTPHandler): отправка электронной почты может занимать много времени по ряду причин, не зависящих от разработчика (например, из-за плохой работы почтовой или сетевой инфраструктуры). Но почти любой сетевой обработчик может блокировать: даже операция [`SocketHandler`](https://python-all.ru/3.9/library/logging.handlers.html#logging.handlers.SocketHandler) может выполнять DNS-запрос «под капотом», который оказывается слишком медленным (и этот запрос может быть глубоко в коде библиотеки сокетов, ниже уровня Python и вне вашего контроля).311312Одно из решений – использовать двухчастный подход. На первом этапе к логгерам, к которым обращаются из критичных по производительности потоков, следует подключать только [`QueueHandler`](https://python-all.ru/3.9/library/logging.handlers.html#logging.handlers.QueueHandler). Они просто пишут в свою очередь, которую можно настроить на достаточно большую ёмкость или инициализировать без верхнего ограничения размера. Запись в очередь обычно выполняется быстро, хотя в коде желательно перехватывать исключение [`queue.Full`](https://python-all.ru/3.9/library/queue.html#queue.Full) на всякий случай. Если вы – разработчик библиотеки, в коде которой есть критичные по производительности потоки, обязательно задокументируйте это (вместе с рекомендацией подключать к вашим логгерам только `QueueHandlers`) для пользы других разработчиков, которые будут использовать ваш код.313314Вторая часть решения – [`QueueListener`](https://python-all.ru/3.9/library/logging.handlers.html#logging.handlers.QueueListener), который был разработан как аналог [`QueueHandler`](https://python-all.ru/3.9/library/logging.handlers.html#logging.handlers.QueueHandler). [`QueueListener`](https://python-all.ru/3.9/library/logging.handlers.html#logging.handlers.QueueListener) устроен очень просто: ему передаётся очередь и несколько обработчиков, и он запускает внутренний поток, который слушает свою очередь на предмет LogRecords, отправленных из `QueueHandlers` (или любого другого источника `LogRecords`). `LogRecords` извлекаются из очереди и передаются обработчикам для обработки.315316Преимущество отдельного класса [`QueueListener`](https://python-all.ru/3.9/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.9/library/logging.handlers.html#logging.handlers.QueueListener) всегда передавал каждое полученное из очереди сообщение каждому обработчику, с которыми был инициализирован. (Это объяснялось тем, что предполагалось, что фильтрация по уровню полностью выполняется на стороне наполнения очереди.) Начиная с версии 3.5 это поведение можно изменить, передав именованный аргумент `respect_handler_level=True` конструктору слушателя. Когда это сделано, слушатель сравнивает уровень каждого сообщения с уровнем обработчика и передаёт сообщение обработчику, только если это уместно.345346## Отправка и получение событий логирования по сети347348Допустим, вы хотите отправлять события логирования по сети и обрабатывать их на принимающей стороне. Простой способ – подключить экземпляр [`SocketHandler`](https://python-all.ru/3.9/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.9/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Для запуска слушателя логирования в production может потребоваться инструмент управления процессами, такой как [Supervisor](https://python-all.ru/3.9/howto/logging-cookbook.html). [Здесь](https://python-all.ru/3.9/howto/logging-cookbook.html) находится Gist, который содержит базовые файлы для запуска описанной функциональности с помощью Supervisor: вам нужно изменить части */path/to/* в Gist, чтобы указать фактические пути, которые вы хотите использовать.480481## Добавление контекстной информации в вывод журнала482483Иногда требуется, чтобы вывод журнала содержал контекстную информацию в дополнение к параметрам, переданным в вызове логирования. Например, в сетевом приложении может быть желательно записывать в журнал информацию, специфичную для клиента (например, имя пользователя удалённого клиента или IP-адрес). Хотя для этого можно использовать параметр *extra*, не всегда удобно передавать информацию таким образом. Может возникнуть соблазн создавать экземпляры `Logger` для каждого соединения, но это плохая идея, поскольку такие экземпляры не собираются сборщиком мусора. Хотя на практике это не проблема, когда количество экземпляров `Logger` зависит от уровня детализации, используемого при логировании приложения, управление ими может стать сложным, если количество экземпляров `Logger` станет фактически неограниченным.484485### Использование LoggerAdapter для добавления контекстной информации486487Простой способ передавать контекстную информацию для вывода вместе с информацией о событиях логирования – использовать класс `LoggerAdapter`. Этот класс спроектирован так, чтобы выглядеть как `Logger`, что позволяет вызывать `debug()`, `info()`, `warning()`, `error()`, `exception()`, `critical()` и `log()`. Эти методы имеют те же сигнатуры, что и их аналоги в `Logger`, поэтому экземпляры обоих типов можно использовать взаимозаменяемо.488489При создании экземпляра `LoggerAdapter` вы передаёте ему экземпляр `Logger` и объект, подобный словарю, содержащий вашу контекстную информацию. Когда вы вызываете один из методов логирования на экземпляре `LoggerAdapter`, он делегирует вызов базовому экземпляру `Logger`, переданному в конструктор, и организует передачу контекстной информации в этом делегированном вызове. Вот фрагмент кода `LoggerAdapter`:490491```python492def debug(self, msg, /, *args, **kwargs):493    """494    Передаёт вызов отладки нижележащему регистратору после добавления495    контекстной информации из данного экземпляра адаптера.496    """497    msg, kwargs = self.process(msg, kwargs)498    self.logger.debug(msg, *args, **kwargs)499```500501Метод `process()` класса `LoggerAdapter` – это то место, где контекстная информация добавляется в вывод журнала. Ему передаются сообщение и именованные аргументы вызова логирования, а он возвращает (потенциально) изменённые версии для использования в вызове базового регистратора. В реализации по умолчанию этот метод оставляет сообщение без изменений, но вставляет ключ 'extra' в именованные аргументы, значением которого является объект, подобный словарю, переданный конструктору. Конечно, если вы передали именованный аргумент 'extra' в вызове адаптера, он будет молча перезаписан.502503Преимущество использования 'extra' в том, что значения из объекта, подобного словарю, сливаются в \_\_dict\_\_ экземпляра `LogRecord`, что позволяет использовать настроенные строки с экземплярами `Formatter`, которые знают о ключах этого объекта. Если вам нужен другой метод, например, добавить контекстную информацию в начало или конец строки сообщения, достаточно создать подкласс `LoggerAdapter` и переопределить `process()` для нужного поведения. Вот простой пример:504505```python506class CustomAdapter(logging.LoggerAdapter):507    """508    Данный пример адаптера ожидает, что переданный объект, подобный словарю, содержит509    ключ 'connid', значение которого в квадратных скобках добавляется к началу сообщения журнала.510    """511    def process(self, msg, kwargs):512        return '[%s] %s' % (self.extra['connid'], msg), kwargs513```514515который можно использовать так:516517```python518logger = logging.getLogger(__name__)519adapter = CustomAdapter(logger, {'connid': some_conn_id})520```521522Тогда все события, регистрируемые через адаптер, будут содержать значение `some_conn_id`, добавленное в начало сообщений журнала.523524#### Использование объектов, отличных от словарей, для передачи контекстной информации525526Необязательно передавать в `LoggerAdapter` именно словарь – можно передать экземпляр класса, реализующего `__getitem__` и `__iter__`, чтобы он выглядел как словарь для системы логирования. Это полезно, если нужно генерировать значения динамически (тогда как значения в словаре были бы постоянными).527528### Использование фильтров для добавления контекстной информации529530Вы также можете добавлять контекстную информацию в вывод журнала с помощью определённого пользователем `Filter`. Экземплярам `Filter` разрешено изменять `LogRecords`, переданный им, включая добавление дополнительных атрибутов, которые затем можно выводить с помощью подходящей форматной строки или, если необходимо, пользовательского `Formatter`.531532Например, в веб-приложении обрабатываемый запрос (или, по крайней мере, его интересные части) можно сохранить в потоковой локальной переменной ([`threading.local`](https://python-all.ru/3.9/library/threading.html#threading.local)), а затем из `Filter` получить к ней доступ, чтобы добавить, скажем, информацию из запроса – например, удалённый IP-адрес и имя пользователя – в `LogRecord`, используя имена атрибутов 'ip' и 'user', как в примере с `LoggerAdapter` выше. В этом случае можно использовать ту же форматную строку для получения вывода, аналогичного показанному выше. Вот пример скрипта:533534```python535import logging536from random import choice537538class ContextFilter(logging.Filter):539    """540    Это фильтр, который внедряет контекстную информацию в журнал.541542    Вместо использования реальной контекстной информации в данном примере используются случайные543    данные.544    """545546    USERS = ['jim', 'fred', 'sheila']547    IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']548549    def filter(self, record):550551        record.ip = choice(ContextFilter.IPS)552        record.user = choice(ContextFilter.USERS)553        return True554555if __name__ == '__main__':556    levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)557    logging.basicConfig(level=logging.DEBUG,558                        format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')559    a1 = logging.getLogger('a.b.c')560    a2 = logging.getLogger('d.e.f')561562    f = ContextFilter()563    a1.addFilter(f)564    a2.addFilter(f)565    a1.debug('A debug message')566    a1.info('An info message with %s', 'some parameters')567    for x in range(10):568        lvl = choice(levels)569        lvlname = logging.getLevelName(lvl)570        a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')571```572573который при запуске выдаёт примерно следующее:574575```text5762010-09-06 22:38:15,292 a.b.c DEBUG    IP: 123.231.231.123 User: fred     A debug message5772010-09-06 22:38:15,300 a.b.c INFO     IP: 192.168.0.1     User: sheila   An info message with some parameters5782010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters5792010-09-06 22:38:15,300 d.e.f ERROR    IP: 127.0.0.1       User: jim      A message at ERROR level with 2 parameters5802010-09-06 22:38:15,300 d.e.f DEBUG    IP: 127.0.0.1       User: sheila   A message at DEBUG level with 2 parameters5812010-09-06 22:38:15,300 d.e.f ERROR    IP: 123.231.231.123 User: fred     A message at ERROR level with 2 parameters5822010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1     User: jim      A message at CRITICAL level with 2 parameters5832010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters5842010-09-06 22:38:15,300 d.e.f DEBUG    IP: 192.168.0.1     User: jim      A message at DEBUG level with 2 parameters5852010-09-06 22:38:15,301 d.e.f ERROR    IP: 127.0.0.1       User: sheila   A message at ERROR level with 2 parameters5862010-09-06 22:38:15,301 d.e.f DEBUG    IP: 123.231.231.123 User: fred     A message at DEBUG level with 2 parameters5872010-09-06 22:38:15,301 d.e.f INFO     IP: 123.231.231.123 User: fred     A message at INFO level with 2 parameters588```589590## Ведение журнала в один файл из нескольких процессов591592Хотя модуль logging является потокобезопасным и запись в один файл из нескольких потоков в одном процессе *поддерживается*, запись в один файл из *нескольких процессов* *не* поддерживается, поскольку в Python нет стандартного способа сериализовать доступ к одному файлу из нескольких процессов. Если нужно вести журнал в один файл из нескольких процессов, один из способов – сделать так, чтобы все процессы записывали данные в `SocketHandler`, а отдельный процесс реализовывал сокет-сервер, который читает из сокета и записывает в файл. (Если хотите, можно выделить один поток в одном из существующих процессов для выполнения этой функции.) [В этом разделе](https://python-all.ru/3.9/howto/logging-cookbook.html#network-logging) подробно описывается данный подход и приводится рабочий приёмник сокета, который можно использовать как отправную точку для адаптации в своих приложениях.593594Вы также можете написать собственный обработчик, который использует класс [`Lock`](https://python-all.ru/3.9/library/multiprocessing.html#multiprocessing.Lock) из модуля [`multiprocessing`](https://python-all.ru/3.9/library/multiprocessing.html#module-multiprocessing) для сериализации доступа к файлу из ваших процессов. Существующие `FileHandler` и подклассы в настоящее время не используют [`multiprocessing`](https://python-all.ru/3.9/library/multiprocessing.html#module-multiprocessing), хотя в будущем они могут это сделать. Обратите внимание, что в настоящее время модуль [`multiprocessing`](https://python-all.ru/3.9/library/multiprocessing.html#module-multiprocessing) не обеспечивает рабочую функциональность блокировки на всех платформах (см. [https://bugs.python.org/issue3770](https://python-all.ru/3.9/howto/logging-cookbook.html)).595596В качестве альтернативы можно использовать `Queue` и [`QueueHandler`](https://python-all.ru/3.9/library/logging.handlers.html#logging.handlers.QueueHandler) для отправки всех событий журналирования одному из процессов в вашем многопроцессном приложении. В следующем примере сценария показано, как это сделать; в примере отдельный процесс-слушатель ожидает события, отправленные другими процессами, и регистрирует их в соответствии со своей собственной конфигурацией журналирования. Хотя пример демонстрирует лишь один из способов (например, вместо отдельного процесса-слушателя можно использовать поток-слушатель – реализация будет аналогичной), он позволяет задать полностью разные конфигурации журналирования для слушателя и остальных процессов в вашем приложении и может быть использован как основа для кода, отвечающего вашим конкретным требованиям:597598```python599# Вам понадобятся эти импорты в вашем коде.600import logging601import logging.handlers602import multiprocessing603604# Следующие две строки импорта только для этой демонстрации.605from random import choice, random606import time607608#609# Поскольку нужно задать настройки логирования для слушателя и рабочих процессов, функции610# слушателя и рабочего процесса принимают параметр configurer – вызываемый объект для611# настройки логирования этого процесса. Эти функции также получают очередь, которую612# используют для взаимодействия.613#614# На практике слушателя можно настроить как угодно, но заметьте: в этом простом615# примере слушатель не применяет логику уровней или фильтров к полученным записям.616# На практике эту логику, вероятно, стоит вынести в рабочие процессы, чтобы не617# пересылать между процессами события, которые всё равно будут отфильтрованы.618#619# Размер файлов при ротации намеренно сделан небольшим, чтобы результат был хорошо виден.620def listener_configurer():621    root = logging.getLogger()622    h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)623    f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')624    h.setFormatter(f)625    root.addHandler(h)626627# Это главный цикл процесса-слушателя: ждём события логирования628# (LogRecords) в очереди и обрабатываем их; завершаем работу, когда получаем None вместо629# LogRecord.630def listener_process(queue, configurer):631    configurer()632    while True:633        try:634            record = queue.get()635            if record is None:  # Отправляем это как сигнал завершения, чтобы слушатель остановился.636                break637            logger = logging.getLogger(record.name)638            logger.handle(record)  # Никакой логики уровней и фильтров – просто делаем дело!639        except Exception:640            import sys, traceback641            print('Whoops! Problem:', file=sys.stderr)642            traceback.print_exc(file=sys.stderr)643644# Массивы для случайного выбора в этой демонстрации.645646LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,647          logging.ERROR, logging.CRITICAL]648649LOGGERS = ['a.b.c', 'd.e.f']650651MESSAGES = [652    'Random message #1',653    'Random message #2',654    'Random message #3',655]656657# Настройка рабочего процесса выполняется в начале его работы.658# Обратите внимание: в Windows нельзя полагаться на семантику fork, поэтому каждый процесс659# будет выполнять код настройки логирования при запуске.660def worker_configurer(queue):661    h = logging.handlers.QueueHandler(queue)  # Нужен только один обработчик.662    root = logging.getLogger()663    root.addHandler(h)664    # Отправляем все сообщения для демонстрации; никакой другой логики уровней или фильтров.665    root.setLevel(logging.DEBUG)666667# Это главный цикл рабочего процесса, который просто логирует десять событий с668# случайные задержки перед завершением.669# Сообщения print нужны лишь для того, чтобы было видно, что программа работает.670def worker_process(queue, configurer):671    configurer(queue)672    name = multiprocessing.current_process().name673    print('Worker started: %s' % name)674    for i in range(10):675        time.sleep(random())676        logger = logging.getLogger(choice(LOGGERS))677        level = choice(LEVELS)678        message = choice(MESSAGES)679        logger.log(level, message)680    print('Worker finished: %s' % name)681682# Здесь организуется демонстрация. Создать очередь, создать и запустить683# слушатель, создать десять рабочих процессов и запустить их, дождаться их завершения,684# затем отправить None в очередь, чтобы сообщить слушателю о завершении.685def main():686    queue = multiprocessing.Queue(-1)687    listener = multiprocessing.Process(target=listener_process,688                                       args=(queue, listener_configurer))689    listener.start()690    workers = []691    for i in range(10):692        worker = multiprocessing.Process(target=worker_process,693                                         args=(queue, worker_configurer))694        workers.append(worker)695        worker.start()696    for w in workers:697        w.join()698    queue.put_nowait(None)699    listener.join()700701if __name__ == '__main__':702    main()703```704705Вариант приведённого выше сценария оставляет ведение журнала в главном процессе, в отдельном потоке:706707```python708import logging709import logging.config710import logging.handlers711from multiprocessing import Process, Queue712import random713import threading714import time715716def logger_thread(q):717    while True:718        record = q.get()719        if record is None:720            break721        logger = logging.getLogger(record.name)722        logger.handle(record)723724def worker_process(q):725    qh = logging.handlers.QueueHandler(q)726    root = logging.getLogger()727    root.setLevel(logging.DEBUG)728    root.addHandler(qh)729    levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,730              logging.CRITICAL]731    loggers = ['foo', 'foo.bar', 'foo.bar.baz',732               'spam', 'spam.ham', 'spam.ham.eggs']733    for i in range(100):734        lvl = random.choice(levels)735        logger = logging.getLogger(random.choice(loggers))736        logger.log(lvl, 'Message no. %d', i)737738if __name__ == '__main__':739    q = Queue()740    d = {741        'version': 1,742        'formatters': {743            'detailed': {744                'class': 'logging.Formatter',745                'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'746            }747        },748        'handlers': {749            'console': {750                'class': 'logging.StreamHandler',751                'level': 'INFO',752            },753            'file': {754                'class': 'logging.FileHandler',755                'filename': 'mplog.log',756                'mode': 'w',757                'formatter': 'detailed',758            },759            'foofile': {760                'class': 'logging.FileHandler',761                'filename': 'mplog-foo.log',762                'mode': 'w',763                'formatter': 'detailed',764            },765            'errors': {766                'class': 'logging.FileHandler',767                'filename': 'mplog-errors.log',768                'mode': 'w',769                'level': 'ERROR',770                'formatter': 'detailed',771            },772        },773        'loggers': {774            'foo': {775                'handlers': ['foofile']776            }777        },778        'root': {779            'level': 'DEBUG',780            'handlers': ['console', 'file', 'errors']781        },782    }783    workers = []784    for i in range(5):785        wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))786        workers.append(wp)787        wp.start()788    logging.config.dictConfig(d)789    lp = threading.Thread(target=logger_thread, args=(q,))790    lp.start()791    # На этом этапе главный процесс может заняться своей полезной работой792    # Когда он с этим закончит, он может дождаться завершения рабочих процессов...793    for wp in workers:794        wp.join()795    # А теперь указать потоку журналирования завершиться796    q.put(None)797    lp.join()798```799800Этот вариант показывает, как можно, например, применить конфигурацию для определённых регистраторов – например, регистратор `foo` имеет специальный обработчик, который сохраняет все события подсистемы `foo` в файл `mplog-foo.log`. Это будет использовано механизмом журналирования в главном процессе (даже если события журналирования генерируются в рабочих процессах) для направления сообщений к соответствующим местам назначения.801802### Использование concurrent.futures.ProcessPoolExecutor803804Если вы хотите использовать [`concurrent.futures.ProcessPoolExecutor`](https://python-all.ru/3.9/library/concurrent.futures.html#concurrent.futures.ProcessPoolExecutor) для запуска рабочих процессов, необходимо создать очередь немного иначе. Вместо805806```python807queue = multiprocessing.Queue(-1)808```809810следует использовать811812```python813queue = multiprocessing.Manager().Queue(-1)  # также работает с примерами выше814```815816и затем можно заменить создание рабочего процесса с этого:817818```python819workers = []820for i in range(10):821    worker = multiprocessing.Process(target=worker_process,822                                     args=(queue, worker_configurer))823    workers.append(worker)824    worker.start()825for w in workers:826    w.join()827```828829на это (не забудьте сначала импортировать [`concurrent.futures`](https://python-all.ru/3.9/library/concurrent.futures.html#module-concurrent.futures)):830831```python832with concurrent.futures.ProcessPoolExecutor(max_workers=10) as executor:833    for i in range(10):834        executor.submit(worker_process, queue, worker_configurer)835```836837### Развертывание веб-приложений с использованием Gunicorn и uWSGI838839При развертывании веб-приложений с использованием [Gunicorn](https://python-all.ru/3.9/howto/logging-cookbook.html) или [uWSGI](https://python-all.ru/3.9/howto/logging-cookbook.html) (или аналогичных) создается несколько рабочих процессов для обработки клиентских запросов. В таких средах избегайте создания обработчиков, основанных на файлах, непосредственно в вашем веб-приложении. Вместо этого используйте [`SocketHandler`](https://python-all.ru/3.9/library/logging.handlers.html#logging.handlers.SocketHandler) для логирования из веб-приложения в слушатель в отдельном процессе. Это можно настроить с помощью инструмента управления процессами, такого как Supervisor – см. [Запуск слушателя сокета логирования в производственной среде](https://python-all.ru/3.9/howto/logging-cookbook.html#running-a-logging-socket-listener-in-production) для получения дополнительной информации.840841## Использование ротации файлов842843Иногда требуется позволить файлу журнала расти до определённого размера, затем открыть новый файл и вести запись в него. Может потребоваться сохранять определённое количество таких файлов, и когда будет создано заданное число файлов, выполнять ротацию, чтобы и количество, и размер файлов оставались в заданных границах. Для такого сценария использования пакет logging предоставляет `RotatingFileHandler`:844845```python846import glob847import logging848import logging.handlers849850LOG_FILENAME = 'logging_rotatingfile_example.out'851852# Настроить конкретный регистратор с нужным уровнем вывода853my_logger = logging.getLogger('MyLogger')854my_logger.setLevel(logging.DEBUG)855856# Добавить обработчик сообщений журнала в регистратор857handler = logging.handlers.RotatingFileHandler(858              LOG_FILENAME, maxBytes=20, backupCount=5)859860my_logger.addHandler(handler)861862# Записать несколько сообщений863for i in range(20):864    my_logger.debug('i = %d' % i)865866# Посмотреть, какие файлы созданы867logfiles = glob.glob('%s*' % LOG_FILENAME)868869for filename in logfiles:870    print(filename)871```872873В результате должно получиться 6 отдельных файлов, каждый из которых содержит часть истории журнала приложения:874875```text876logging_rotatingfile_example.out877logging_rotatingfile_example.out.1878logging_rotatingfile_example.out.2879logging_rotatingfile_example.out.3880logging_rotatingfile_example.out.4881logging_rotatingfile_example.out.5882```883884Самый свежий файл всегда называется `logging_rotatingfile_example.out`, и каждый раз при достижении ограничения по размеру он переименовывается с суффиксом `.1`. Каждый из существующих резервных файлов переименовывается с увеличением суффикса (`.1` становится `.2` и т.д.), а файл `.6` удаляется.885886Разумеется, в этом примере размер файла журнала установлен слишком маленьким для наглядности. В реальности нужно установить *maxBytes* в подходящее значение.887888## Использование альтернативных стилей форматирования889890Когда журналирование было добавлено в стандартную библиотеку Python, единственным способом форматирования сообщений с переменным содержимым было использование %-форматирования. С тех пор в Python появились два новых подхода к форматированию: [`string.Template`](https://python-all.ru/3.9/library/string.html#string.Template) (добавлен в Python 2.4) и [`str.format()`](https://python-all.ru/3.9/library/stdtypes.html#str.format) (добавлен в Python 2.6).891892Начиная с версии 3.2, модуль logging предоставляет улучшенную поддержку этих двух дополнительных стилей форматирования. Класс `Formatter` был расширен: добавлен дополнительный необязательный именованный параметр `style`. По умолчанию он равен `'%'`, но возможны также значения `'{'` и `'$'`, соответствующие двум другим стилям форматирования. Обратная совместимость сохраняется по умолчанию (как и следовало ожидать), но при явном указании параметра style появляется возможность задавать строки формата, работающие с [`str.format()`](https://python-all.ru/3.9/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.9/library/string.html#string.Template). Вот пример сеанса работы в консоли, демонстрирующий возможности:893894```pycon895>>> import logging896>>> root = logging.getLogger()897>>> root.setLevel(logging.DEBUG)898>>> handler = logging.StreamHandler()899>>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}',900...                        style='{')901>>> handler.setFormatter(bf)902>>> root.addHandler(handler)903>>> logger = logging.getLogger('foo.bar')904>>> logger.debug('This is a DEBUG message')9052010-10-28 15:11:55,341 foo.bar DEBUG    This is a DEBUG message906>>> logger.critical('This is a CRITICAL message')9072010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message908>>> df = logging.Formatter('$asctime $name ${levelname} $message',909...                        style='$')910>>> handler.setFormatter(df)911>>> logger.debug('This is a DEBUG message')9122010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message913>>> logger.critical('This is a CRITICAL message')9142010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message915>>>916```917918Обратите внимание: форматирование сообщений журнала для конечного вывода в файлы совершенно не зависит от того, как конструируется отдельное сообщение. Оно по-прежнему может использовать %-форматирование, как показано ниже:919920```python921>>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')9222010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message923>>>924```925926Вызовы функций журналирования (`logger.debug()`, `logger.info()` и т.д.) принимают только позиционные параметры для самого сообщения журнала; именованные параметры используются только для определения параметров обработки вызова (например, именованный параметр `exc_info` указывает, что нужно записать информацию о трассировке стека, или именованный параметр `extra` – добавить дополнительный контекст в журнал). Поэтому невозможно напрямую использовать синтаксис [`str.format()`](https://python-all.ru/3.9/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.9/library/string.html#string.Template) при вызовах, поскольку внутри пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Изменить это без нарушения обратной совместимости нельзя, так как все существующие вызовы logging в существующем коде используют %-формат строк.927928Однако существует способ использовать {}- и $-форматирование для построения отдельных сообщений журнала. Напомним, что в качестве строки формата сообщения можно использовать произвольный объект, и пакет logging вызовет у этого объекта `str()` для получения фактической строки формата. Рассмотрим следующие два класса:929930```python931class BraceMessage:932    def __init__(self, fmt, /, *args, **kwargs):933        self.fmt = fmt934        self.args = args935        self.kwargs = kwargs936937    def __str__(self):938        return self.fmt.format(*self.args, **self.kwargs)939940class DollarMessage:941    def __init__(self, fmt, /, **kwargs):942        self.fmt = fmt943        self.kwargs = kwargs944945    def __str__(self):946        from string import Template947        return Template(self.fmt).substitute(**self.kwargs)948```949950Любой из этих классов можно использовать вместо строки формата, чтобы разрешить применение {}- или $-форматирования для построения фактической части «message», которая появляется в отформатированном выводе журнала вместо «%(message)s», «{message}» или «$message». Это немного громоздко – использовать имена классов каждый раз при журналировании, но вполне приемлемо, если применить псевдоним, например \_\_ (двойное подчеркивание – не путать с \_, одинарным подчеркиванием, используемым как синоним/псевдоним для [`gettext.gettext()`](https://python-all.ru/3.9/library/gettext.html#gettext.gettext) или его аналогов).951952Вышеуказанные классы не входят в состав Python, но их легко скопировать и вставить в свой код. Их можно использовать следующим образом (предполагая, что они объявлены в модуле с именем `wherever`):953954```pycon955>>> from wherever import BraceMessage as __956>>> print(__('Message with {0} {name}', 2, name='placeholders'))957Message with 2 placeholders958>>> class Point: pass959...960>>> p = Point()961>>> p.x = 0.5962>>> p.y = 0.5963>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})',964...       point=p))965Message with coordinates: (0.50, 0.50)966>>> from wherever import DollarMessage as __967>>> print(__('Message with $num $what', num=2, what='placeholders'))968Message with 2 placeholders969>>>970```971972Хотя в приведённых выше примерах используется `print()` для демонстрации работы форматирования, в реальности для ведения журнала с помощью этого подхода следует использовать `logger.debug()` или аналогичную функцию.973974Следует отметить, что этот подход не даёт значительного снижения производительности с этим подходом: фактическое форматирование происходит не тогда, когда вы делаете вызов регистрации, а когда (и если) регистрируемое сообщение действительно должно быть выведено в журнал с помощью обработчика. Поэтому единственное, что может сбить с толку, – это то, что скобки ставятся вокруг строки формата и аргументов, а не только вокруг строки формата. Это потому, что нотация \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов XXXMessage.975976Если хотите, можно использовать `LoggerAdapter` для достижения аналогичного эффекта, как в следующем примере:977978```python979import logging980981class Message:982    def __init__(self, fmt, args):983        self.fmt = fmt984        self.args = args985986    def __str__(self):987        return self.fmt.format(*self.args)988989class StyleAdapter(logging.LoggerAdapter):990    def __init__(self, logger, extra=None):991        super().__init__(logger, extra or {})992993    def log(self, level, msg, /, *args, **kwargs):994        if self.isEnabledFor(level):995            msg, kwargs = self.process(msg, kwargs)996            self.logger._log(level, Message(msg, args), (), **kwargs)997998logger = StyleAdapter(logging.getLogger(__name__))9991000def main():1001    logger.debug('Hello, {}', 'world!')10021003if __name__ == '__main__':1004    logging.basicConfig(level=logging.DEBUG)1005    main()1006```10071008При запуске с Python 3.2 или новее указанный выше скрипт должен записать сообщение `Hello, world!`.10091010## Настройка `LogRecord`10111012Каждое событие журналирования представлено экземпляром [`LogRecord`](https://python-all.ru/3.9/library/logging.html#logging.LogRecord). Когда событие регистрируется и не отфильтровывается по уровню регистратора, создаётся [`LogRecord`](https://python-all.ru/3.9/library/logging.html#logging.LogRecord), заполняется информацией о событии и затем передаётся обработчикам для этого регистратора (и его предков, вплоть до регистратора, в котором дальнейшее распространение по иерархии отключено). До Python 3.2 было только два места, где выполнялось это создание:10131014- [`Logger.makeRecord()`](https://python-all.ru/3.9/library/logging.html#logging.Logger.makeRecord), который вызывается в обычном процессе регистрации события. Он напрямую вызывал [`LogRecord`](https://python-all.ru/3.9/library/logging.html#logging.LogRecord) для создания экземпляра.1015- [`makeLogRecord()`](https://python-all.ru/3.9/library/logging.html#logging.makeLogRecord), которая вызывается со словарем, содержащим атрибуты для добавления в LogRecord. Обычно она вызывается, когда подходящий словарь был получен по сети (например, в виде pickle через [`SocketHandler`](https://python-all.ru/3.9/library/logging.handlers.html#logging.handlers.SocketHandler) или в формате JSON через [`HTTPHandler`](https://python-all.ru/3.9/library/logging.handlers.html#logging.handlers.HTTPHandler)).10161017Обычно это означало, что если требуется выполнить какие-либо специальные действия с [`LogRecord`](https://python-all.ru/3.9/library/logging.html#logging.LogRecord), приходилось делать одно из следующего.10181019- Создать собственный подкласс [`Logger`](https://python-all.ru/3.9/library/logging.html#logging.Logger), который переопределяет [`Logger.makeRecord()`](https://python-all.ru/3.9/library/logging.html#logging.Logger.makeRecord), и установить его с помощью [`setLoggerClass()`](https://python-all.ru/3.9/library/logging.html#logging.setLoggerClass) до того, как будут созданы какие-либо логгеры, которые вас интересуют.1020- Добавить [`Filter`](https://python-all.ru/3.9/library/logging.html#logging.Filter) к логгеру или обработчику, который выполняет необходимые специальные манипуляции при вызове его метода [`filter()`](https://python-all.ru/3.9/library/logging.html#logging.Filter.filter).10211022Первый подход был бы несколько громоздким в сценарии, где (скажем) несколько разных библиотек хотели бы делать разные вещи. Каждая попыталась бы установить свой собственный подкласс [`Logger`](https://python-all.ru/3.9/library/logging.html#logging.Logger), и та, которая сделала это последней, победила бы.10231024Второй подход достаточно хорошо работает во многих случаях, но не позволяет, например, использовать специализированный подкласс [`LogRecord`](https://python-all.ru/3.9/library/logging.html#logging.LogRecord). Разработчики библиотек могут установить подходящий фильтр на своих логгерах, но им приходилось бы помнить об этом каждый раз, когда они добавляют новый логгер (что они делают, просто добавляя новые пакеты или модули и выполняя10251026```python1027logger = logging.getLogger(__name__)1028```10291030на уровне модуля). Вероятно, это одна из тех вещей, о которых нужно помнить. Разработчики также могли бы добавить фильтр к [`NullHandler`](https://python-all.ru/3.9/library/logging.handlers.html#logging.NullHandler), прикрепленному к их корневому логгеру, но он не будет вызываться, если разработчик приложения прикрепит обработчик к логгеру библиотеки нижнего уровня – так что вывод от этого обработчика не будет отражать намерений разработчика библиотеки.10311032В Python 3.2 и новее создание [`LogRecord`](https://python-all.ru/3.9/library/logging.html#logging.LogRecord) осуществляется через фабрику, которую можно указать. Фабрика – это просто вызываемый объект, который можно установить с помощью [`setLogRecordFactory()`](https://python-all.ru/3.9/library/logging.html#logging.setLogRecordFactory) и запросить с помощью [`getLogRecordFactory()`](https://python-all.ru/3.9/library/logging.html#logging.getLogRecordFactory). Фабрика вызывается с той же сигнатурой, что и конструктор [`LogRecord`](https://python-all.ru/3.9/library/logging.html#logging.LogRecord), поскольку [`LogRecord`](https://python-all.ru/3.9/library/logging.html#logging.LogRecord) является значением по умолчанию для фабрики.10331034Этот подход позволяет пользовательской фабрике контролировать все аспекты создания LogRecord. Например, можно вернуть подкласс или просто добавить несколько дополнительных атрибутов к записи после ее создания, используя шаблон, подобный следующему:10351036```python1037old_factory = logging.getLogRecordFactory()10381039def record_factory(*args, **kwargs):1040    record = old_factory(*args, **kwargs)1041    record.custom_attribute = 0xdecafbad1042    return record10431044logging.setLogRecordFactory(record_factory)1045```10461047Этот шаблон позволяет разным библиотекам объединять фабрики в цепочку, и пока они не перезаписывают атрибуты друг друга или случайно не перезаписывают стандартные атрибуты, никаких сюрпризов быть не должно. Однако следует иметь в виду, что каждое звено цепочки добавляет накладные расходы во время выполнения ко всем операциям логирования, и эту технику следует использовать только тогда, когда использование [`Filter`](https://python-all.ru/3.9/library/logging.html#logging.Filter) не дает желаемого результата.10481049## Создание подкласса QueueHandler – пример с ZeroMQ10501051Можно использовать подкласс `QueueHandler` для отправки сообщений в очереди других типов, например, в сокет ZeroMQ «publish». В приведенном ниже примере сокет создается отдельно и передается обработчику (в качестве его «очереди»):10521053```python1054import zmq   # с использованием pyzmq, привязки Python к ZeroMQ1055import json  # для переносимой сериализации записей10561057ctx = zmq.Context()1058sock = zmq.Socket(ctx, zmq.PUB)  # или zmq.PUSH, или другое подходящее значение1059sock.bind('tcp://*:5556')        # или где угодно10601061class ZeroMQSocketHandler(QueueHandler):1062    def enqueue(self, record):1063        self.queue.send_json(record.__dict__)10641065handler = ZeroMQSocketHandler(sock)1066```10671068Конечно, есть и другие способы организации этого, например, передача данных, необходимых обработчику для создания сокета:10691070```python1071class ZeroMQSocketHandler(QueueHandler):1072    def __init__(self, uri, socktype=zmq.PUB, ctx=None):1073        self.ctx = ctx or zmq.Context()1074        socket = zmq.Socket(self.ctx, socktype)1075        socket.bind(uri)1076        super().__init__(socket)10771078    def enqueue(self, record):1079        self.queue.send_json(record.__dict__)10801081    def close(self):1082        self.queue.close()1083```10841085## Создание подкласса QueueListener – пример с ZeroMQ10861087Можно также создать подкласс `QueueListener` для получения сообщений из очередей других типов, например, из сокета ZeroMQ «subscribe». Вот пример:10881089```python1090class ZeroMQSocketListener(QueueListener):1091    def __init__(self, uri, /, *handlers, **kwargs):1092        self.ctx = kwargs.get('ctx') or zmq.Context()1093        socket = zmq.Socket(self.ctx, zmq.SUB)1094        socket.setsockopt_string(zmq.SUBSCRIBE, '')  # подписаться на всё1095        socket.connect(uri)1096        super().__init__(socket, *handlers, **kwargs)10971098    def dequeue(self):1099        msg = self.queue.recv_json()1100        return logging.makeLogRecord(msg)1101```11021103> **См. также**1104>1105> **Модуль [`logging`](https://python-all.ru/3.9/library/logging.html#module-logging)**1106>1107> Справочник API для модуля logging.1108>1109> **Модуль [`logging.config`](https://python-all.ru/3.9/library/logging.config.html#module-logging.config)**1110>1111> API конфигурации для модуля logging.1112>1113> **Модуль [`logging.handlers`](https://python-all.ru/3.9/library/logging.handlers.html#module-logging.handlers)**1114>1115> Полезные обработчики, входящие в состав модуля logging.1116>1117> [Базовое руководство по логированию](https://python-all.ru/3.9/howto/logging.html#logging-basic-tutorial)1118>1119> [Более продвинутое руководство по логированию](https://python-all.ru/3.9/howto/logging.html#logging-advanced-tutorial)11201121## Пример конфигурации на основе словаря11221123Ниже приведен пример словаря конфигурации логирования – он взят из [документации проекта Django](https://python-all.ru/3.9/howto/logging-cookbook.html). Этот словарь передается в [`dictConfig()`](https://python-all.ru/3.9/library/logging.config.html#logging.config.dictConfig) для применения конфигурации:11241125```python1126LOGGING = {1127    'version': 1,1128    'disable_existing_loggers': True,1129    'formatters': {1130        'verbose': {1131            'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'1132        },1133        'simple': {1134            'format': '%(levelname)s %(message)s'1135        },1136    },1137    'filters': {1138        'special': {1139            '()': 'project.logging.SpecialFilter',1140            'foo': 'bar',1141        }1142    },1143    'handlers': {1144        'null': {1145            'level':'DEBUG',1146            'class':'django.utils.log.NullHandler',1147        },1148        'console':{1149            'level':'DEBUG',1150            'class':'logging.StreamHandler',1151            'formatter': 'simple'1152        },1153        'mail_admins': {1154            'level': 'ERROR',1155            'class': 'django.utils.log.AdminEmailHandler',1156            'filters': ['special']1157        }1158    },1159    'loggers': {1160        'django': {1161            'handlers':['null'],1162            'propagate': True,1163            'level':'INFO',1164        },1165        'django.request': {1166            'handlers': ['mail_admins'],1167            'level': 'ERROR',1168            'propagate': False,1169        },1170        'myproject.custom': {1171            'handlers': ['console', 'mail_admins'],1172            'level': 'INFO',1173            'filters': ['special']1174        }1175    }1176}1177```11781179Для получения дополнительной информации об этой конфигурации можно обратиться к [соответствующему разделу](https://python-all.ru/3.9/howto/logging-cookbook.html) документации Django.11801181## Использование ротатора и средства именования для настройки обработки ротации журналов11821183Пример того, как можно определить namer и rotator, приведен в следующем фрагменте кода, который демонстрирует сжатие журнала с использованием zlib:11841185```python1186def namer(name):1187    return name + ".gz"11881189def rotator(source, dest):1190    with open(source, "rb") as sf:1191        data = sf.read()1192        compressed = zlib.compress(data, 9)1193        with open(dest, "wb") as df:1194            df.write(compressed)1195    os.remove(source)11961197rh = logging.handlers.RotatingFileHandler(...)1198rh.rotator = rotator1199rh.namer = namer1200```12011202Это не «настоящие» .gz-файлы, поскольку они представляют собой просто сжатые данные без «контейнера», который присутствует в обычном gzip-файле. Данный фрагмент приведен только для иллюстрации.12031204## Более сложный пример с многопроцессностью12051206Следующий рабочий пример показывает, как можно использовать логирование с многопроцессностью с помощью файлов конфигурации. Конфигурации довольно просты, но служат иллюстрацией того, как можно реализовать более сложные в реальном сценарии многопроцессной обработки.12071208В примере главный процесс порождает процесс-слушатель и несколько рабочих процессов. Каждый из главного процесса, слушателя и рабочих имеет три отдельные конфигурации (все рабочие используют одну и ту же конфигурацию). Видно ведение журнала в главном процессе, как рабочие пишут в QueueHandler, а слушатель реализует QueueListener и более сложную конфигурацию ведения журнала, и организует отправку событий, полученных через очередь, обработчикам, указанным в конфигурации. Обратите внимание, что эти конфигурации чисто иллюстративные, но этот пример можно адаптировать под свой сценарий.12091210Вот скрипт – строки документации и комментарии, надеюсь, поясняют, как он работает:12111212```python1213import logging1214import logging.config1215import logging.handlers1216from multiprocessing import Process, Queue, Event, current_process1217import os1218import random1219import time12201221class MyHandler:1222    """1223    Простой обработчик для событий логирования. Он выполняется в процессе-слушателе и1224    распределяет события по логгерам на основе имени в полученной записи,1225    которые затем передаются системой логирования обработчикам,1226    настроенным для этих логгеров.1227    """12281229    def handle(self, record):1230        if record.name == "root":1231            logger = logging.getLogger()1232        else:1233            logger = logging.getLogger(record.name)12341235        if logger.isEnabledFor(record.levelno):1236            # Имя процесса преобразуется только для того, чтобы показать, что это слушатель1237            # выполняет логирование в файлы и консоль.1238            record.processName = '%s (for %s)' % (current_process().name, record.processName)1239            logger.handle(record)12401241def listener_process(q, stop_event, config):1242    """1243    Это можно было бы сделать в главном процессе, но сделано в отдельном1244    процессе для наглядности.12451246    Это инициализирует логирование согласно указанной конфигурации1247    запускает слушатель и ожидает сигнала от главного процесса о завершении1248    через событие. Затем слушатель останавливается, и процесс завершается.1249    """1250    logging.config.dictConfig(config)1251    listener = logging.handlers.QueueListener(q, MyHandler())1252    listener.start()1253    if os.name == 'posix':1254        # В POSIX логгер setup уже был настроен в1255        # родительском процессе, но должен был быть отключён после вызова1256        # dictConfig.1257        # В Windows, поскольку fork не используется, логгер setup не будет1258        # существовать в дочернем процессе, поэтому он будет создан, и сообщение1259        # появится – отсюда и конструкция "if posix".1260        logger = logging.getLogger('setup')1261        logger.critical('Should not appear, because of disabled logger ...')1262    stop_event.wait()1263    listener.stop()12641265def worker_process(config):1266    """1267    Некоторое количество таких процессов порождается для иллюстрации. На1268    практике это могла бы быть разнородная группа процессов, а не1269    идентичные друг другу.12701271    Это инициализирует логирование согласно указанной конфигурации1272    и записывает сотню сообщений со случайными уровнями в случайно выбранные1273    логгеры.12741275    Добавлена небольшая задержка, чтобы дать другим процессам шанс выполниться. Это1276    не является строго необходимым, но позволяет немного перемешать вывод от разных1277    процессов больше, чем если бы её не было.1278    """1279    logging.config.dictConfig(config)1280    levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1281              logging.CRITICAL]1282    loggers = ['foo', 'foo.bar', 'foo.bar.baz',1283               'spam', 'spam.ham', 'spam.ham.eggs']1284    if os.name == 'posix':1285        # В POSIX логгер setup уже был настроен в1286        # родительском процессе, но должен был быть отключён после вызова1287        # dictConfig.1288        # В Windows, поскольку fork не используется, логгер setup не будет1289        # существовать в дочернем процессе, поэтому он будет создан, и сообщение1290        # появится – отсюда и конструкция "if posix".1291        logger = logging.getLogger('setup')1292        logger.critical('Should not appear, because of disabled logger ...')1293    for i in range(100):1294        lvl = random.choice(levels)1295        logger = logging.getLogger(random.choice(loggers))1296        logger.log(lvl, 'Message no. %d', i)1297        time.sleep(0.01)12981299def main():1300    q = Queue()1301    # Главный процесс получает простую конфигурацию, которая выводит информацию в консоль.1302    config_initial = {1303        'version': 1,1304        'handlers': {1305            'console': {1306                'class': 'logging.StreamHandler',1307                'level': 'INFO'1308            }1309        },1310        'root': {1311            'handlers': ['console'],1312            'level': 'DEBUG'1313        }1314    }1315    # Конфигурация рабочего процесса представляет собой QueueHandler, прикреплённый к1316    # корневому логгеру, что позволяет отправлять все сообщения в очередь.1317    # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1318    # родительском процессе. Это необходимо в POSIX, потому что логгер будет1319    # присутствовать в дочернем процессе после вызова fork().1320    config_worker = {1321        'version': 1,1322        'disable_existing_loggers': True,1323        'handlers': {1324            'queue': {1325                'class': 'logging.handlers.QueueHandler',1326                'queue': q1327            }1328        },1329        'root': {1330            'handlers': ['queue'],1331            'level': 'DEBUG'1332        }1333    }1334    # Конфигурация процесса-слушателя показывает, что вся гибкость1335    # конфигурации логирования доступна для отправки событий обработчикам так, как1336    # требуется.1337    # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1338    # родительском процессе. Это необходимо в POSIX, потому что логгер будет1339    # присутствовать в дочернем процессе после вызова fork().1340    config_listener = {1341        'version': 1,1342        'disable_existing_loggers': True,1343        'formatters': {1344            'detailed': {1345                'class': 'logging.Formatter',1346                'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1347            },1348            'simple': {1349                'class': 'logging.Formatter',1350                'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1351            }1352        },1353        'handlers': {1354            'console': {1355                'class': 'logging.StreamHandler',1356                'formatter': 'simple',1357                'level': 'INFO'1358            },1359            'file': {1360                'class': 'logging.FileHandler',1361                'filename': 'mplog.log',1362                'mode': 'w',1363                'formatter': 'detailed'1364            },1365            'foofile': {1366                'class': 'logging.FileHandler',1367                'filename': 'mplog-foo.log',1368                'mode': 'w',1369                'formatter': 'detailed'1370            },1371            'errors': {1372                'class': 'logging.FileHandler',1373                'filename': 'mplog-errors.log',1374                'mode': 'w',1375                'formatter': 'detailed',1376                'level': 'ERROR'1377            }1378        },1379        'loggers': {1380            'foo': {1381                'handlers': ['foofile']1382            }1383        },1384        'root': {1385            'handlers': ['console', 'file', 'errors'],1386            'level': 'DEBUG'1387        }1388    }1389    # Записываем несколько начальных событий, просто чтобы показать, что логирование в родительском процессе работает1390    # нормально.1391    logging.config.dictConfig(config_initial)1392    logger = logging.getLogger('setup')1393    logger.info('About to create workers ...')1394    workers = []1395    for i in range(5):1396        wp = Process(target=worker_process, name='worker %d' % (i + 1),1397                     args=(config_worker,))1398        workers.append(wp)1399        wp.start()1400        logger.info('Started worker: %s', wp.name)1401    logger.info('About to create listener ...')1402    stop_event = Event()1403    lp = Process(target=listener_process, name='listener',1404                 args=(q, stop_event, config_listener))1405    lp.start()1406    logger.info('Started listener')1407    # Теперь ожидаем завершения работы рабочих процессов.1408    for wp in workers:1409        wp.join()1410    # Все рабочие процессы завершены, теперь можно остановить прослушивание.1411    # Логирование в родительском процессе всё ещё работает нормально.1412    logger.info('Telling listener to stop ...')1413    stop_event.set()1414    lp.join()1415    logger.info('All done.')14161417if __name__ == '__main__':1418    main()1419```14201421## Вставка BOM в сообщения, отправляемые в SysLogHandler14221423[**RFC 5424**](https://python-all.ru/3.9/howto/logging-cookbook.html) требует, чтобы сообщение Unicode отправлялось демону syslog в виде набора байтов, имеющего следующую структуру: необязательный чисто ASCII-компонент, за которым следует метка порядка байтов UTF-8 (BOM), а затем Unicode, закодированный в UTF-8. (См. [**соответствующий раздел спецификации**](https://python-all.ru/3.9/howto/logging-cookbook.html).)14241425В Python 3.1 в [`SysLogHandler`](https://python-all.ru/3.9/library/logging.handlers.html#logging.handlers.SysLogHandler) был добавлен код для вставки BOM в сообщение, но, к сожалению, он был реализован некорректно: BOM появлялся в начале сообщения и, следовательно, не допускал наличия чисто ASCII-компонента перед ним.14261427Поскольку такое поведение ошибочно, некорректный код вставки BOM удаляется из Python 3.2.4 и более поздних версий. Однако он не заменяется, и если требуется создавать сообщения, соответствующие [**RFC 5424**](https://python-all.ru/3.9/howto/logging-cookbook.html), которые включают BOM, необязательную чисто ASCII-последовательность перед ним и произвольный Unicode после него, закодированный в UTF-8, то необходимо сделать следующее:142814291. Необходимо присоединить экземпляр [`Formatter`](https://python-all.ru/3.9/library/logging.html#logging.Formatter) к экземпляру [`SysLogHandler`](https://python-all.ru/3.9/library/logging.handlers.html#logging.handlers.SysLogHandler), указав строку формата, например:14301431   ```python1432   'ASCII section\ufeffUnicode section'1433   ```14341435   Кодовая точка Unicode U+FEFF при кодировании в UTF-8 будет представлена как метка порядка байтов UTF-8 – строка байтов `b'\xef\xbb\xbf'`.14362. ASCII-часть следует заменить на любые подходящие заполнители, но необходимо следить, чтобы данные, которые появляются там после подстановки, всегда были в ASCII (таким образом, они останутся без изменений после кодирования UTF-8).14373. Unicode-часть следует заменить на любые заполнители; если данные после подстановки содержат символы за пределами диапазона ASCII, это нормально – они будут закодированы в UTF-8.14381439Отформатированное сообщение *будет* закодировано в UTF-8 с помощью `SysLogHandler`. Если следовать приведённым выше правилам, можно создавать сообщения, соответствующие [**RFC 5424**](https://python-all.ru/3.9/howto/logging-cookbook.html). Если этого не делать, модуль logging может не жаловаться, но сообщения не будут соответствовать RFC 5424, и демон syslog может выражать недовольство.14401441## Реализация структурированного ведения журнала14421443Хотя большинство сообщений журнала предназначены для чтения человеком и поэтому не предназначены для машинного разбора, могут возникнуть ситуации, когда требуется выводить сообщения в структурированном формате, *который* может быть разобран программой (без необходимости в сложных регулярных выражениях). Это легко достигается с помощью пакета logging. Существует несколько способов, но ниже приведён простой подход, использующий JSON для сериализации события в машиночитаемом виде.14441445```python1446import json1447import logging14481449class StructuredMessage:1450    def __init__(self, message, /, **kwargs):1451        self.message = message1452        self.kwargs = kwargs14531454    def __str__(self):1455        return '%s >>> %s' % (self.message, json.dumps(self.kwargs))14561457_ = StructuredMessage   # необязательно, для улучшения читаемости14581459logging.basicConfig(level=logging.INFO, format='%(message)s')1460logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))1461```14621463Если запустить приведённый выше скрипт, он выведет:14641465```text1466message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}1467```14681469Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.14701471Если требуется более специализированная обработка, можно использовать пользовательский кодировщик JSON, как в следующем полном примере:14721473```python1474from __future__ import unicode_literals14751476import json1477import logging14781479# Следующий фрагмент предназначен для того, чтобы скрипт работал без изменений в версиях 2.x и 3.x.1480try:1481    unicode1482except NameError:1483    unicode = str14841485class Encoder(json.JSONEncoder):1486    def default(self, o):1487        if isinstance(o, set):1488            return tuple(o)1489        elif isinstance(o, unicode):1490            return o.encode('unicode_escape').decode('ascii')1491        return super().default(o)14921493class StructuredMessage:1494    def __init__(self, message, /, **kwargs):1495        self.message = message1496        self.kwargs = kwargs14971498    def __str__(self):1499        s = Encoder().encode(self.kwargs)1500        return '%s >>> %s' % (self.message, s)15011502_ = StructuredMessage   # необязательно, для улучшения читаемости15031504def main():1505    logging.basicConfig(level=logging.INFO, format='%(message)s')1506    logging.info(_('message 1', set_value={1, 2, 3}, snowman='\u2603'))15071508if __name__ == '__main__':1509    main()1510```15111512При запуске приведённого выше скрипта он выведет:15131514```text1515message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}1516```15171518Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.15191520## Настройка обработчиков с помощью [`dictConfig()`](https://python-all.ru/3.9/library/logging.config.html#logging.config.dictConfig)15211522Иногда требуется настроить обработчики логирования особым образом, и при использовании [`dictConfig()`](https://python-all.ru/3.9/library/logging.config.html#logging.config.dictConfig) это можно сделать без создания подклассов. Например, может потребоваться установить владельца файла журнала. В POSIX это легко сделать с помощью [`shutil.chown()`](https://python-all.ru/3.9/library/shutil.html#shutil.chown), но файловые обработчики в стандартной библиотеке не предоставляют встроенной поддержки. Можно настроить создание обработчика с помощью обычной функции, такой как:15231524```python1525def owned_file_handler(filename, mode='a', encoding=None, owner=None):1526    if owner:1527        if not os.path.exists(filename):1528            open(filename, 'a').close()1529        shutil.chown(filename, *owner)1530    return logging.FileHandler(filename, mode, encoding)1531```15321533Затем в конфигурации логирования, передаваемой в [`dictConfig()`](https://python-all.ru/3.9/library/logging.config.html#logging.config.dictConfig), можно указать, что обработчик должен быть создан вызовом этой функции:15341535```python1536LOGGING = {1537    'version': 1,1538    'disable_existing_loggers': False,1539    'formatters': {1540        'default': {1541            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'1542        },1543    },1544    'handlers': {1545        'file':{1546            # Значения ниже извлекаются из этого словаря и1547            # используются для создания обработчика, установки его уровня и1548            # его форматтера.1549            '()': owned_file_handler,1550            'level':'DEBUG',1551            'formatter': 'default',1552            # Значения ниже передаются вызываемому объекту-создателю обработчика1553            # в качестве именованных аргументов.1554            'owner': ['pulse', 'pulse'],1555            'filename': 'chowntest.log',1556            'mode': 'w',1557            'encoding': 'utf-8',1558        },1559    },1560    'root': {1561        'handlers': ['file'],1562        'level': 'DEBUG',1563    },1564}1565```15661567В этом примере для иллюстрации права владения устанавливаются с использованием пользователя и группы `pulse`. Собирая всё вместе в рабочий скрипт, `chowntest.py`:15681569```python1570import logging, logging.config, os, shutil15711572def owned_file_handler(filename, mode='a', encoding=None, owner=None):1573    if owner:1574        if not os.path.exists(filename):1575            open(filename, 'a').close()1576        shutil.chown(filename, *owner)1577    return logging.FileHandler(filename, mode, encoding)15781579LOGGING = {1580    'version': 1,1581    'disable_existing_loggers': False,1582    'formatters': {1583        'default': {1584            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'1585        },1586    },1587    'handlers': {1588        'file':{1589            # Значения ниже извлекаются из этого словаря и1590            # используются для создания обработчика, установки его уровня и1591            # его форматтера.1592            '()': owned_file_handler,1593            'level':'DEBUG',1594            'formatter': 'default',1595            # Значения ниже передаются вызываемому объекту-создателю обработчика1596            # в качестве именованных аргументов.1597            'owner': ['pulse', 'pulse'],1598            'filename': 'chowntest.log',1599            'mode': 'w',1600            'encoding': 'utf-8',1601        },1602    },1603    'root': {1604        'handlers': ['file'],1605        'level': 'DEBUG',1606    },1607}16081609logging.config.dictConfig(LOGGING)1610logger = logging.getLogger('mylogger')1611logger.debug('A debug message')1612```16131614Для запуска, вероятно, потребуется выполнить от имени `root`:16151616```console1617$ sudo python3.3 chowntest.py1618$ cat chowntest.log16192013-11-05 09:34:51,128 DEBUG mylogger A debug message1620$ ls -l chowntest.log1621-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log1622```16231624Обратите внимание, что в этом примере используется Python 3.3, потому что в нём появился [`shutil.chown()`](https://python-all.ru/3.9/library/shutil.html#shutil.chown). Этот подход должен работать с любой версией Python, поддерживающей [`dictConfig()`](https://python-all.ru/3.9/library/logging.config.html#logging.config.dictConfig) – а именно Python 2.7, 3.2 или новее. В версиях до 3.3 потребовалось бы реализовать фактическую смену владельца, например, с помощью [`os.chown()`](https://python-all.ru/3.9/library/os.html#os.chown).16251626На практике функция создания обработчика может находиться в служебном модуле где-нибудь в вашем проекте. Вместо строки в конфигурации:16271628```python1629'()': owned_file_handler,1630```16311632можно использовать, например:16331634```python1635'()': 'ext://project.util.owned_file_handler',1636```16371638где `project.util` можно заменить на фактическое имя пакета, в котором находится функция. В приведённом рабочем скрипте должно сработать использование `'ext://__main__.owned_file_handler'`. Здесь фактический вызываемый объект разрешается с помощью [`dictConfig()`](https://python-all.ru/3.9/library/logging.config.html#logging.config.dictConfig) из спецификации `ext://`.16391640Этот пример, надеюсь, также показывает, как можно реализовать другие типы изменений файлов – например, установку определённых битов разрешений POSIX – аналогичным образом, с помощью [`os.chmod()`](https://python-all.ru/3.9/library/os.html#os.chmod).16411642Разумеется, этот подход можно распространить и на другие типы обработчиков, помимо [`FileHandler`](https://python-all.ru/3.9/library/logging.handlers.html#logging.FileHandler) – например, на один из вращающихся файловых обработчиков или на совершенно другой тип обработчика.16431644## Использование определённых стилей форматирования во всём приложении16451646В Python 3.2 у [`Formatter`](https://python-all.ru/3.9/library/logging.html#logging.Formatter) появился именованный параметр `style`, который, хотя по умолчанию для обратной совместимости он равен `%`, позволяет указать `{` или `$` для поддержки подходов к форматированию, поддерживаемых [`str.format()`](https://python-all.ru/3.9/library/stdtypes.html#str.format) и [`string.Template`](https://python-all.ru/3.9/library/string.html#string.Template). Обратите внимание, что это управляет форматированием сообщений журнала для окончательного вывода в журнал и совершенно не зависит от того, как конструируется отдельное сообщение журнала.16471648Вызовы логирования ([`debug()`](https://python-all.ru/3.9/library/logging.html#logging.Logger.debug), [`info()`](https://python-all.ru/3.9/library/logging.html#logging.Logger.info) и т.д.) принимают только позиционные параметры для самого сообщения логирования, а именованные параметры используются только для определения параметров обработки вызова (например, именованный параметр `exc_info` для указания, что информация о трассировке должна быть записана в журнал, или именованный параметр `extra` для указания дополнительной контекстной информации, добавляемой в журнал). Поэтому вы не можете напрямую выполнять вызовы логирования с использованием синтаксиса [`str.format()`](https://python-all.ru/3.9/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.9/library/string.html#string.Template), потому что внутренне пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Это нельзя изменить, сохраняя обратную совместимость, поскольку все существующие вызовы логирования в коде используют %-форматирование строк.16491650Высказывались предложения связывать стили форматирования с конкретными регистраторами, но этот подход также сталкивается с проблемами обратной совместимости, поскольку любой существующий код может использовать данное имя регистратора и %-форматирование.16511652Чтобы логирование работало совместимо между любыми сторонними библиотеками и вашим кодом, решения о форматировании необходимо принимать на уровне отдельного вызова логирования. Это открывает несколько способов, которыми можно реализовать альтернативные стили форматирования.16531654### Использование фабрик LogRecord16551656В Python 3.2, вместе с упомянутыми выше изменениями [`Formatter`](https://python-all.ru/3.9/library/logging.html#logging.Formatter), пакет logging получил возможность позволять пользователям устанавливать свои собственные подклассы [`LogRecord`](https://python-all.ru/3.9/library/logging.html#logging.LogRecord) с помощью функции [`setLogRecordFactory()`](https://python-all.ru/3.9/library/logging.html#logging.setLogRecordFactory). Вы можете использовать это, чтобы установить свой собственный подкласс [`LogRecord`](https://python-all.ru/3.9/library/logging.html#logging.LogRecord), который делает правильные вещи, переопределяя метод [`getMessage()`](https://python-all.ru/3.9/library/logging.html#logging.LogRecord.getMessage). В реализации базового класса этого метода происходит форматирование `msg % args`, и именно здесь можно подставить альтернативное форматирование; однако следует быть осторожным, чтобы поддерживать все стили форматирования и разрешить %-форматирование по умолчанию для обеспечения совместимости с другим кодом. Также следует позаботиться о вызове `str(self.msg)`, как это делает базовая реализация.16571658Обратитесь к справочной документации по [`setLogRecordFactory()`](https://python-all.ru/3.9/library/logging.html#logging.setLogRecordFactory) и [`LogRecord`](https://python-all.ru/3.9/library/logging.html#logging.LogRecord) для получения дополнительной информации.16591660### Использование пользовательских объектов сообщений16611662Есть еще один, возможно, более простой способ использовать {}- и $-форматирование для построения отдельных сообщений лога. Вы, возможно, помните (из раздела [Использование произвольных объектов в качестве сообщений](https://python-all.ru/3.9/howto/logging.html#arbitrary-object-messages)), что при логировании можно использовать произвольный объект в качестве строки формата сообщения, и пакет logging вызовет [`str()`](https://python-all.ru/3.9/library/stdtypes.html#str) для этого объекта, чтобы получить фактическую строку формата. Рассмотрим следующие два класса:16631664```python1665class BraceMessage:1666    def __init__(self, fmt, /, *args, **kwargs):1667        self.fmt = fmt1668        self.args = args1669        self.kwargs = kwargs16701671    def __str__(self):1672        return self.fmt.format(*self.args, **self.kwargs)16731674class DollarMessage:1675    def __init__(self, fmt, /, **kwargs):1676        self.fmt = fmt1677        self.kwargs = kwargs16781679    def __str__(self):1680        from string import Template1681        return Template(self.fmt).substitute(**self.kwargs)1682```16831684Любой из них можно использовать вместо строки формата, чтобы разрешить {}- или $-форматирование для построения фактической части «message», которая появляется в форматированном выводе лога вместо «%(message)s», «{message}» или «$message». Если вам кажется неудобным использовать имена классов каждый раз при логировании, вы можете сделать это более приятным, используя псевдоним, такой как `M` или `_` для сообщения (или, возможно, `__`, если вы используете `_` для локализации).16851686Примеры этого подхода приведены ниже. Во-первых, форматирование с помощью [`str.format()`](https://python-all.ru/3.9/library/stdtypes.html#str.format):16871688```python1689>>> __ = BraceMessage1690>>> print(__('Message with {0} {1}', 2, 'placeholders'))1691Message with 2 placeholders1692>>> class Point: pass1693...1694>>> p = Point()1695>>> p.x = 0.51696>>> p.y = 0.51697>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))1698Message with coordinates: (0.50, 0.50)1699```17001701Во-вторых, форматирование с помощью [`string.Template`](https://python-all.ru/3.9/library/string.html#string.Template):17021703```python1704>>> __ = DollarMessage1705>>> print(__('Message with $num $what', num=2, what='placeholders'))1706Message with 2 placeholders1707>>>1708```17091710Стоит отметить, что при таком подходе вы не платите значительных потерь производительности: фактическое форматирование происходит не при вызове логирования, а когда (и если) сообщение лога действительно должно быть выведено в лог обработчиком. Так что единственная необычная вещь, которая может вас сбить с толку, это то, что круглые скобки ставятся вокруг строки формата и аргументов, а не только вокруг строки формата. Это потому, что нотация \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов `XXXMessage`, показанных выше.17111712## Настройка фильтров с помощью [`dictConfig()`](https://python-all.ru/3.9/library/logging.config.html#logging.config.dictConfig)17131714*Можно* настраивать фильтры с помощью [`dictConfig()`](https://python-all.ru/3.9/library/logging.config.html#logging.config.dictConfig), хотя с первого взгляда может быть неочевидно, как это сделать (поэтому и дан этот рецепт). Поскольку [`Filter`](https://python-all.ru/3.9/library/logging.html#logging.Filter) – единственный класс фильтра, включенный в стандартную библиотеку, и вряд ли он удовлетворит многие требования (он присутствует только как базовый класс), вам, как правило, потребуется определить свой собственный подкласс [`Filter`](https://python-all.ru/3.9/library/logging.html#logging.Filter) с переопределенным методом [`filter()`](https://python-all.ru/3.9/library/logging.html#logging.Filter.filter). Для этого укажите ключ `()` в словаре конфигурации для фильтра, указав вызываемый объект, который будет использоваться для создания фильтра (класс – наиболее очевидный вариант, но вы можете предоставить любой вызываемый объект, возвращающий экземпляр [`Filter`](https://python-all.ru/3.9/library/logging.html#logging.Filter)). Вот полный пример:17151716```python1717import logging1718import logging.config1719import sys17201721class MyFilter(logging.Filter):1722    def __init__(self, param=None):1723        self.param = param17241725    def filter(self, record):1726        if self.param is None:1727            allow = True1728        else:1729            allow = self.param not in record.msg1730        if allow:1731            record.msg = 'changed: ' + record.msg1732        return allow17331734LOGGING = {1735    'version': 1,1736    'filters': {1737        'myfilter': {1738            '()': MyFilter,1739            'param': 'noshow',1740        }1741    },1742    'handlers': {1743        'console': {1744            'class': 'logging.StreamHandler',1745            'filters': ['myfilter']1746        }1747    },1748    'root': {1749        'level': 'DEBUG',1750        'handlers': ['console']1751    },1752}17531754if __name__ == '__main__':1755    logging.config.dictConfig(LOGGING)1756    logging.debug('hello')1757    logging.debug('hello - noshow')1758```17591760Этот пример показывает, как можно передавать конфигурационные данные вызываемому объекту, который создает экземпляр, в виде именованных параметров. При запуске приведенный выше скрипт выведет:17611762```text1763changed: hello1764```17651766что показывает, что фильтр работает в соответствии с настройками.17671768Несколько дополнительных моментов, на которые стоит обратить внимание:17691770- Если вы не можете сослаться на вызываемый объект напрямую в конфигурации (например, если он находится в другом модуле, и вы не можете импортировать его напрямую в том месте, где находится словарь конфигурации), вы можете использовать форму `ext://...`, как описано в разделе [Доступ к внешним объектам](https://python-all.ru/3.9/library/logging.config.html#logging-config-dict-externalobj). Например, в приведенном выше примере можно было использовать текст `'ext://__main__.MyFilter'` вместо `MyFilter`.1771- Помимо фильтров, этот метод также можно использовать для настройки пользовательских обработчиков и форматтеров. Смотрите раздел [Пользовательские объекты](https://python-all.ru/3.9/library/logging.config.html#logging-config-dict-userdef) для получения дополнительной информации о том, как logging поддерживает использование пользовательских объектов в своей конфигурации, а также см. другой рецепт из этой книги рецептов [Настройка обработчиков с помощью dictConfig()](https://python-all.ru/3.9/howto/logging-cookbook.html#custom-handlers) выше.17721773## Настраиваемое форматирование исключений17741775Могут возникнуть ситуации, когда вы захотите настроить форматирование исключений – для примера, предположим, вы хотите ровно одну строку на каждое событие лога, даже если присутствует информация об исключении. Вы можете сделать это с помощью пользовательского класса форматтера, как показано в следующем примере:17761777```python1778import logging17791780class OneLineExceptionFormatter(logging.Formatter):1781    def formatException(self, exc_info):1782        """1783        Форматировать исключение так, чтобы оно выводилось одной строкой.1784        """1785        result = super().formatException(exc_info)1786        return repr(result)  # или форматировать одной строкой по своему усмотрению17871788    def format(self, record):1789        s = super().format(record)1790        if record.exc_text:1791            s = s.replace('\n', '') + '|'1792        return s17931794def configure_logging():1795    fh = logging.FileHandler('output.txt', 'w')1796    f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',1797                                  '%d/%m/%Y %H:%M:%S')1798    fh.setFormatter(f)1799    root = logging.getLogger()1800    root.setLevel(logging.DEBUG)1801    root.addHandler(fh)18021803def main():1804    configure_logging()1805    logging.info('Sample message')1806    try:1807        x = 1 / 01808    except ZeroDivisionError as e:1809        logging.exception('ZeroDivisionError: %s', e)18101811if __name__ == '__main__':1812    main()1813```18141815При запуске это создает файл ровно с двумя строками:18161817```text181828/01/2015 07:21:23|INFO|Sample message|181928/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'|1820```18211822Хотя описанный выше подход упрощен, он показывает путь к тому, как можно форматировать информацию об исключениях по своему вкусу. Модуль [`traceback`](https://python-all.ru/3.9/library/traceback.html#module-traceback) может быть полезен для более специализированных нужд.18231824## Озвучивание сообщений лога18251826Могут быть ситуации, когда желательно выводить сообщения лога в звуковом, а не визуальном формате. Это легко сделать, если в вашей системе доступна функция преобразования текста в речь (TTS), даже если у нее нет привязки к Python. Большинство TTS-систем имеют программу командной строки, которую можно запустить, и ее можно вызвать из обработчика с помощью [`subprocess`](https://python-all.ru/3.9/library/subprocess.html#module-subprocess). Здесь предполагается, что программы командной строки TTS не будут ожидать взаимодействия с пользователем или занимать много времени для завершения, и что частота сообщений лога не будет настолько высокой, чтобы перегружать пользователя сообщениями, и что допустимо проговаривать сообщения по одному, а не одновременно. В приведенном ниже примере реализации ожидается, пока одно сообщение не будет произнесено, прежде чем обрабатывать следующее, и это может заставить другие обработчики ждать. Вот короткий пример, демонстрирующий подход, который предполагает, что доступен TTS-пакет `espeak`:18271828```python1829import logging1830import subprocess1831import sys18321833class TTSHandler(logging.Handler):1834    def emit(self, record):1835        msg = self.format(record)1836        # Говорить медленно женским английским голосом.1837        cmd = ['espeak', '-s150', '-ven+f3', msg]1838        p = subprocess.Popen(cmd, stdout=subprocess.PIPE,1839                             stderr=subprocess.STDOUT)1840        # дождаться завершения программы1841        p.communicate()18421843def configure_logging():1844    h = TTSHandler()1845    root = logging.getLogger()1846    root.addHandler(h)1847    # стандартный форматтер просто возвращает сообщение1848    root.setLevel(logging.DEBUG)18491850def main():1851    logging.info('Hello')1852    logging.debug('Goodbye')18531854if __name__ == '__main__':1855    configure_logging()1856    sys.exit(main())1857```18581859При запуске этот скрипт должен сказать «Hello», а затем «Goodbye» женским голосом.18601861Описанный выше подход, конечно, можно адаптировать для других TTS-систем и даже для других систем, которые могут обрабатывать сообщения через внешние программы, запускаемые из командной строки.18621863## Буферизация сообщений лога и условный вывод18641865Могут возникнуть ситуации, когда вы хотите записывать сообщения во временную область и выводить их только при наступлении определенного условия. Например, вы можете начать запись отладочных событий в функции, и если функция завершится без ошибок, вы не захотите засорять лог собранной отладочной информацией, но если возникнет ошибка, вы захотите вывести всю отладочную информацию вместе с ошибкой.18661867Вот пример, показывающий, как это можно сделать с помощью декоратора для ваших функций, где вы хотите, чтобы логирование вело себя таким образом. Он использует [`logging.handlers.MemoryHandler`](https://python-all.ru/3.9/library/logging.handlers.html#logging.handlers.MemoryHandler), который позволяет буферизовать зарегистрированные события до наступления некоторого условия, после чего буферизованные события `flushed` – передаются другому обработчику (обработчику `target`) для обработки. По умолчанию `MemoryHandler` сбрасывается, когда его буфер заполняется или встречается событие, уровень которого больше или равен указанному порогу. Вы можете использовать этот рецепт с более специализированным подклассом `MemoryHandler`, если хотите настроить поведение сброса.18681869Пример скрипта содержит простую функцию `foo`, которая просто перебирает все уровни логирования, записывая в `sys.stderr` информацию о том, какой уровень будет использоваться, а затем регистрирует сообщение на этом уровне. Вы можете передать параметр в `foo`, который, если равен true, будет регистрировать на уровнях ERROR и CRITICAL – в противном случае он регистрирует только на уровнях DEBUG, INFO и WARNING.18701871Скрипт просто настраивает декорирование `foo` декоратором, который будет выполнять необходимое условное логирование. Декоратор принимает регистратор в качестве параметра и подключает обработчик памяти на время вызова декорированной функции. Декоратор можно дополнительно параметризовать с помощью целевого обработчика, уровня, при котором должен происходить сброс, и емкости буфера (количество буферизируемых записей). По умолчанию они равны [`StreamHandler`](https://python-all.ru/3.9/library/logging.handlers.html#logging.StreamHandler), который пишет в `sys.stderr`, `logging.ERROR` и `100` соответственно.18721873Вот скрипт:18741875```python1876import logging1877from logging.handlers import MemoryHandler1878import sys18791880logger = logging.getLogger(__name__)1881logger.addHandler(logging.NullHandler())18821883def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):1884    if target_handler is None:1885        target_handler = logging.StreamHandler()1886    if flush_level is None:1887        flush_level = logging.ERROR1888    if capacity is None:1889        capacity = 1001890    handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)18911892    def decorator(fn):1893        def wrapper(*args, **kwargs):1894            logger.addHandler(handler)1895            try:1896                return fn(*args, **kwargs)1897            except Exception:1898                logger.exception('call failed')1899                raise1900            finally:1901                super(MemoryHandler, handler).flush()1902                logger.removeHandler(handler)1903        return wrapper19041905    return decorator19061907def write_line(s):1908    sys.stderr.write('%s\n' % s)19091910def foo(fail=False):1911    write_line('about to log at DEBUG ...')1912    logger.debug('Actually logged at DEBUG')1913    write_line('about to log at INFO ...')1914    logger.info('Actually logged at INFO')1915    write_line('about to log at WARNING ...')1916    logger.warning('Actually logged at WARNING')1917    if fail:1918        write_line('about to log at ERROR ...')1919        logger.error('Actually logged at ERROR')1920        write_line('about to log at CRITICAL ...')1921        logger.critical('Actually logged at CRITICAL')1922    return fail19231924decorated_foo = log_if_errors(logger)(foo)19251926if __name__ == '__main__':1927    logger.setLevel(logging.DEBUG)1928    write_line('Calling undecorated foo with False')1929    assert not foo(False)1930    write_line('Calling undecorated foo with True')1931    assert foo(True)1932    write_line('Calling decorated foo with False')1933    assert not decorated_foo(False)1934    write_line('Calling decorated foo with True')1935    assert decorated_foo(True)1936```19371938При запуске этого скрипта отобразится следующий вывод:19391940```text1941Calling undecorated foo with False1942about to log at DEBUG ...1943about to log at INFO ...1944about to log at WARNING ...1945Calling undecorated foo with True1946about to log at DEBUG ...1947about to log at INFO ...1948about to log at WARNING ...1949about to log at ERROR ...1950about to log at CRITICAL ...1951Calling decorated foo with False1952about to log at DEBUG ...1953about to log at INFO ...1954about to log at WARNING ...1955Calling decorated foo with True1956about to log at DEBUG ...1957about to log at INFO ...1958about to log at WARNING ...1959about to log at ERROR ...1960Actually logged at DEBUG1961Actually logged at INFO1962Actually logged at WARNING1963Actually logged at ERROR1964about to log at CRITICAL ...1965Actually logged at CRITICAL1966```19671968Как видно, фактический вывод журнала происходит только при регистрации события, уровень которого ERROR или выше, но в этом случае также регистрируются все предыдущие события с более низкими уровнями.19691970Конечно, можно использовать обычные средства декорирования:19711972```python1973@log_if_errors(logger)1974def foo(fail=False):1975    ...1976```19771978## Форматирование времени с использованием UTC (GMT) через конфигурацию19791980Иногда требуется форматировать время по UTC, что можно сделать с помощью класса такого как *UTCFormatter*, показанного ниже:19811982```python1983import logging1984import time19851986class UTCFormatter(logging.Formatter):1987    converter = time.gmtime1988```19891990и затем можно использовать `UTCFormatter` в своём коде вместо [`Formatter`](https://python-all.ru/3.9/library/logging.html#logging.Formatter). Если требуется сделать это через конфигурацию, можно воспользоваться API [`dictConfig()`](https://python-all.ru/3.9/library/logging.config.html#logging.config.dictConfig), как показано в следующем полном примере:19911992```python1993import logging1994import logging.config1995import time19961997class UTCFormatter(logging.Formatter):1998    converter = time.gmtime19992000LOGGING = {2001    'version': 1,2002    'disable_existing_loggers': False,2003    'formatters': {2004        'utc': {2005            '()': UTCFormatter,2006            'format': '%(asctime)s %(message)s',2007        },2008        'local': {2009            'format': '%(asctime)s %(message)s',2010        }2011    },2012    'handlers': {2013        'console1': {2014            'class': 'logging.StreamHandler',2015            'formatter': 'utc',2016        },2017        'console2': {2018            'class': 'logging.StreamHandler',2019            'formatter': 'local',2020        },2021    },2022    'root': {2023        'handlers': ['console1', 'console2'],2024   }2025}20262027if __name__ == '__main__':2028    logging.config.dictConfig(LOGGING)2029    logging.warning('The local time is %s', time.asctime())2030```20312032При запуске этого скрипта он должен вывести примерно следующее:20332034```text20352015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 201520362015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 20152037```20382039показывая, как время форматируется как в местном времени, так и в UTC, по одному для каждого обработчика.20402041## Использование контекстного менеджера для выборочного журналирования20422043Бывают ситуации, когда полезно временно изменить конфигурацию журналирования, а затем вернуть её обратно после выполнения каких-то действий. Для этого контекстный менеджер – самый очевидный способ сохранить и восстановить контекст журналирования. Вот простой пример такого контекстного менеджера, который позволяет по желанию изменить уровень журналирования и добавить обработчик журнала исключительно в области действия контекстного менеджера:20442045```python2046import logging2047import sys20482049class LoggingContext:2050    def __init__(self, logger, level=None, handler=None, close=True):2051        self.logger = logger2052        self.level = level2053        self.handler = handler2054        self.close = close20552056    def __enter__(self):2057        if self.level is not None:2058            self.old_level = self.logger.level2059            self.logger.setLevel(self.level)2060        if self.handler:2061            self.logger.addHandler(self.handler)20622063    def __exit__(self, et, ev, tb):2064        if self.level is not None:2065            self.logger.setLevel(self.old_level)2066        if self.handler:2067            self.logger.removeHandler(self.handler)2068        if self.handler and self.close:2069            self.handler.close()2070        # неявный возврат None => не подавлять исключения2071```20722073Если указать значение уровня, уровень регистратора устанавливается на это значение в области действия блока with, охватываемого контекстным менеджером. Если указать обработчик, он добавляется к регистратору при входе в блок и удаляется при выходе из блока. Также можно попросить менеджер закрыть обработчик при выходе из блока – это можно сделать, если обработчик больше не нужен.20742075Чтобы проиллюстрировать, как это работает, можно добавить следующий блок кода к предыдущему:20762077```python2078if __name__ == '__main__':2079    logger = logging.getLogger('foo')2080    logger.addHandler(logging.StreamHandler())2081    logger.setLevel(logging.INFO)2082    logger.info('1. This should appear just once on stderr.')2083    logger.debug('2. This should not appear.')2084    with LoggingContext(logger, level=logging.DEBUG):2085        logger.debug('3. This should appear once on stderr.')2086    logger.debug('4. This should not appear.')2087    h = logging.StreamHandler(sys.stdout)2088    with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):2089        logger.debug('5. This should appear twice - once on stderr and once on stdout.')2090    logger.info('6. This should appear just once on stderr.')2091    logger.debug('7. This should not appear.')2092```20932094Изначально устанавливаем уровень регистратора равным `INFO`, поэтому сообщение №1 отображается, а сообщение №2 – нет. Затем временно меняем уровень на `DEBUG` в следующем блоке `with`, и сообщение №3 отображается. После выхода из блока уровень регистратора восстанавливается до `INFO`, поэтому сообщение №4 не отображается. В следующем блоке `with` снова устанавливаем уровень `DEBUG`, но также добавляем обработчик, записывающий в `sys.stdout`. Таким образом, сообщение №5 отображается дважды на консоли (один раз через `stderr` и один раз через `stdout`). После завершения оператора `with` состояние возвращается к исходному, поэтому сообщение №6 отображается (как сообщение №1), а сообщение №7 – нет (как сообщение №2).20952096Если запустить полученный скрипт, результат будет следующим:20972098```console2099$ python logctx.py21001. This should appear just once on stderr.21013. This should appear once on stderr.21025. This should appear twice - once on stderr and once on stdout.21035. This should appear twice - once on stderr and once on stdout.21046. This should appear just once on stderr.2105```21062107Если запустить его снова, но перенаправить `stderr` в `/dev/null`, мы увидим следующее, что является единственным сообщением, записанным в `stdout`:21082109```console2110$ python logctx.py 2>/dev/null21115. This should appear twice - once on stderr and once on stdout.2112```21132114Ещё раз, но перенаправляя `stdout` в `/dev/null`, получаем:21152116```console2117$ python logctx.py >/dev/null21181. This should appear just once on stderr.21193. This should appear once on stderr.21205. This should appear twice - once on stderr and once on stdout.21216. This should appear just once on stderr.2122```21232124В этом случае сообщение №5, выведенное в `stdout`, не отображается, как и ожидалось.21252126Разумеется, описанный подход можно обобщить, например, для временного подключения фильтров журналирования. Обратите внимание, что приведённый выше код работает как в Python 2, так и в Python 3.21272128## Шаблон для запуска CLI-приложения21292130Вот пример, показывающий, как можно:21312132- Использовать уровень журналирования на основе аргументов командной строки2133- Перенаправлять вызовы к нескольким подкомандам в отдельных файлах, все с журналированием на одном уровне согласованным образом2134- Использовать простую минимальную конфигурацию21352136Предположим, у нас есть приложение командной строки, которое останавливает, запускает или перезапускает некоторые службы. Для иллюстрации это может быть организовано в виде файла `app.py`, который является главным скриптом приложения, с отдельными командами, реализованными в `start.py`, `stop.py` и `restart.py`. Предположим также, что мы хотим управлять степенью подробности вывода приложения через аргумент командной строки с значением по умолчанию `logging.INFO`. Вот один из способов, как мог бы быть написан `app.py`:21372138```python2139import argparse2140import importlib2141import logging2142import os2143import sys21442145def main(args=None):2146    scriptname = os.path.basename(__file__)2147    parser = argparse.ArgumentParser(scriptname)2148    levels = ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')2149    parser.add_argument('--log-level', default='INFO', choices=levels)2150    subparsers = parser.add_subparsers(dest='command',2151                                       help='Available commands:')2152    start_cmd = subparsers.add_parser('start', help='Start a service')2153    start_cmd.add_argument('name', metavar='NAME',2154                           help='Name of service to start')2155    stop_cmd = subparsers.add_parser('stop',2156                                     help='Stop one or more services')2157    stop_cmd.add_argument('names', metavar='NAME', nargs='+',2158                          help='Name of service to stop')2159    restart_cmd = subparsers.add_parser('restart',2160                                        help='Restart one or more services')2161    restart_cmd.add_argument('names', metavar='NAME', nargs='+',2162                             help='Name of service to restart')2163    options = parser.parse_args()2164    # весь код для отправки команд мог бы быть в этом файле. Для целей2165    # только в целях иллюстрации каждая команда реализована в отдельном модуле.2166    try:2167        mod = importlib.import_module(options.command)2168        cmd = getattr(mod, 'command')2169    except (ImportError, AttributeError):2170        print('Unable to find the code for command \'%s\'' % options.command)2171        return 12172    # Здесь можно было бы сделать по-хитрому и загрузить конфигурацию из файла или словаря2173    logging.basicConfig(level=options.log_level,2174                        format='%(levelname)s %(name)s %(message)s')2175    cmd(options)21762177if __name__ == '__main__':2178    sys.exit(main())2179```21802181А команды `start`, `stop` и `restart` могут быть реализованы в отдельных модулях, например, для запуска:21822183```python2184# start.py2185import logging21862187logger = logging.getLogger(__name__)21882189def command(options):2190    logger.debug('About to start %s', options.name)2191    # здесь происходит фактическая обработка команды...2192    logger.info('Started the \'%s\' service.', options.name)2193```21942195и аналогично для остановки:21962197```python2198# stop.py2199import logging22002201logger = logging.getLogger(__name__)22022203def command(options):2204    n = len(options.names)2205    if n == 1:2206        plural = ''2207        services = '\'%s\'' % options.names[0]2208    else:2209        plural = 's'2210        services = ', '.join('\'%s\'' % name for name in options.names)2211        i = services.rfind(', ')2212        services = services[:i] + ' and ' + services[i + 2:]2213    logger.debug('About to stop %s', services)2214    # здесь происходит фактическая обработка команды...2215    logger.info('Stopped the %s service%s.', services, plural)2216```22172218и аналогично для перезапуска:22192220```python2221# restart.py2222import logging22232224logger = logging.getLogger(__name__)22252226def command(options):2227    n = len(options.names)2228    if n == 1:2229        plural = ''2230        services = '\'%s\'' % options.names[0]2231    else:2232        plural = 's'2233        services = ', '.join('\'%s\'' % name for name in options.names)2234        i = services.rfind(', ')2235        services = services[:i] + ' and ' + services[i + 2:]2236    logger.debug('About to restart %s', services)2237    # здесь происходит фактическая обработка команды...2238    logger.info('Restarted the %s service%s.', services, plural)2239```22402241Если запустить это приложение с уровнем журналирования по умолчанию, мы получим примерно такой вывод:22422243```console2244$ python app.py start foo2245INFO start Started the 'foo' service.22462247$ python app.py stop foo bar2248INFO stop Stopped the 'foo' and 'bar' services.22492250$ python app.py restart foo bar baz2251INFO restart Restarted the 'foo', 'bar' and 'baz' services.2252```22532254Первое слово – уровень журналирования, а второе – имя модуля или пакета, в котором было зарегистрировано событие.22552256Если изменить уровень журналирования, можно изменить объём информации, отправляемой в журнал. Например, чтобы получить больше информации:22572258```console2259$ python app.py --log-level DEBUG start foo2260DEBUG start About to start foo2261INFO start Started the 'foo' service.22622263$ python app.py --log-level DEBUG stop foo bar2264DEBUG stop About to stop 'foo' and 'bar'2265INFO stop Stopped the 'foo' and 'bar' services.22662267$ python app.py --log-level DEBUG restart foo bar baz2268DEBUG restart About to restart 'foo', 'bar' and 'baz'2269INFO restart Restarted the 'foo', 'bar' and 'baz' services.2270```22712272А если нужно меньше:22732274```console2275$ python app.py --log-level WARNING start foo2276$ python app.py --log-level WARNING stop foo bar2277$ python app.py --log-level WARNING restart foo bar baz2278```22792280В этом случае команды ничего не выводят в консоль, поскольку ни одно сообщение уровня `WARNING` и выше ими не записывается.22812282## Графический интерфейс Qt для журналирования22832284Время от времени возникает вопрос о том, как организовать логирование в GUI-приложении. Фреймворк [Qt](https://python-all.ru/3.9/howto/logging-cookbook.html) – популярная кроссплатформенная UI-среда с привязками к Python через библиотеки [PySide2](https://python-all.ru/3.9/howto/logging-cookbook.html) или [PyQt5](https://python-all.ru/3.9/howto/logging-cookbook.html).22852286В следующем примере показано, как выполнять журналирование в графический интерфейс Qt. Он представляет простой класс `QtHandler`, который принимает вызываемый объект – слот главного потока, обновляющий GUI. Также создаётся рабочий поток, чтобы продемонстрировать возможность журналирования как из самого интерфейса (через кнопку для ручной записи), так и из фонового рабочего потока (который в данном случае просто выводит сообщения со случайными уровнями и случайными короткими задержками).22872288Рабочий поток реализован с помощью класса `QThread` из Qt, а не модуля [`threading`](https://python-all.ru/3.9/library/threading.html#module-threading), поскольку бывают ситуации, когда необходимо использовать `QThread`, который обеспечивает лучшую интеграцию с другими компонентами `Qt`.22892290Код должен работать с последними версиями `PySide2` или `PyQt5`. Вы сможете адаптировать подход для более старых версий Qt. Обратитесь к комментариям в фрагменте кода за более подробной информацией.22912292```python2293import datetime2294import logging2295import random2296import sys2297import time22982299# Обработка мелких различий между PySide2 и PyQt52300try:2301    from PySide2 import QtCore, QtGui, QtWidgets2302    Signal = QtCore.Signal2303    Slot = QtCore.Slot2304except ImportError:2305    from PyQt5 import QtCore, QtGui, QtWidgets2306    Signal = QtCore.pyqtSignal2307    Slot = QtCore.pyqtSlot23082309logger = logging.getLogger(__name__)23102311#2312# Сигналы должны содержаться в QObject или подклассе, чтобы корректно2313# инициализироваться.2314#2315class Signaller(QtCore.QObject):2316    signal = Signal(str, logging.LogRecord)23172318#2319# Вывод в графический интерфейс Qt должен происходить только в главном потоке. Поэтому данный2320# обработчик спроектирован так, чтобы принимать функцию-слот, настроенную на выполнение в главном2321# потоке. В этом примере функция принимает строковый аргумент, который является2322# отформатированным сообщением лога, и запись лога, которая его породила. Отформатированная2323# строка – это просто удобство; можно отформатировать строку для вывода любым способом2324# в самой функции-слоте.2325#2326# Функцию-слот можно настроить на любые нужные обновления GUI. Обработчик2327# не знает и не заботится о конкретных элементах интерфейса.2328#2329class QtHandler(logging.Handler):2330    def __init__(self, slotfunc, *args, **kwargs):2331        super().__init__(*args, **kwargs)2332        self.signaller = Signaller()2333        self.signaller.signal.connect(slotfunc)23342335    def emit(self, record):2336        s = self.format(record)2337        self.signaller.signal.emit(s, record)23382339#2340# В этом примере используются QThreads, что означает, что потоки на уровне Python2341# называются как-то вроде "Dummy-1". Функция ниже получает имя Qt2342# текущего потока.2343#2344def ctname():2345    return QtCore.QThread.currentThread().objectName()23462347#2348# Используется для генерации случайных уровней для логирования.2349#2350LEVELS = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,2351          logging.CRITICAL)23522353#2354# Этот класс-воркер представляет работу, выполняемую в потоке, отдельном от2355# главного потока. Поток запускается на выполнение работы по нажатию кнопки,2356# которая соединяется со слотом в воркере.2357#2358# Поскольку значение threadName по умолчанию в LogRecord не очень полезно, мы добавляем2359# qThreadName, содержащий имя QThread, вычисленное выше, и передаём это2360# значение в словаре "extra", который используется для обновления LogRecord с помощью2361# имя QThread.2362#2363# Этот пример рабочего просто выводит сообщения последовательно, перемежая их случайными задержками порядка нескольких секунд.2364# Позволяет потоку выполняться до прерывания. Это обеспечивает достаточно чистую остановку потока.2365#2366class Worker(QtCore.QObject):2367    @Slot()2368    def start(self):2369        extra = {'qThreadName': ctname() }2370        logger.debug('Started work', extra=extra)2371        i = 12372        # Реализует простой пользовательский интерфейс для этого примера из кулинарной книги. Он содержит:2373        # * Окно текстового редактора только для чтения, которое содержит форматированные сообщения журнала2374        while not QtCore.QThread.currentThread().isInterruptionRequested():2375            delay = 0.5 + random.random() * 22376            time.sleep(delay)2377            level = random.choice(LEVELS)2378            logger.log(level, 'Message after delay of %3.1f: %d', delay, i, extra=extra)2379            i += 123802381#2382# * Кнопка запуска работы и записи в журнал в отдельном потоке2383#2384# * Кнопка записи чего-либо из основного потока2385# * Кнопка очистки окна журнала2386# Устанавливает моноширинный шрифт, принятый по умолчанию на платформе2387# для Qt62388#2389class Window(QtWidgets.QWidget):23902391    COLORS = {2392        logging.DEBUG: 'black',2393        logging.INFO: 'blue',2394        logging.WARNING: 'orange',2395        logging.ERROR: 'red',2396        logging.CRITICAL: 'purple',2397    }23982399    def __init__(self, app):2400        super().__init__()2401        self.app = app2402        self.textedit = te = QtWidgets.QPlainTextEdit(self)2403        # Устанавливает моноширинный шрифт по умолчанию для платформы2404        f = QtGui.QFont('nosuchfont')2405        f.setStyleHint(f.Monospace)2406        te.setFont(f)2407        te.setReadOnly(True)2408        PB = QtWidgets.QPushButton2409        self.work_button = PB('Start background work', self)2410        self.log_button = PB('Log a message at a random level', self)2411        self.clear_button = PB('Clear log window', self)2412        self.handler = h = QtHandler(self.update_status)2413        # Размещает все виджеты2414        fs = '%(asctime)s %(qThreadName)-12s %(levelname)-8s %(message)s'2415        formatter = logging.Formatter(fs)2416        h.setFormatter(formatter)2417        logger.addHandler(h)2418        # Подключает слоты и сигналы, не относящиеся к рабочему2419        app.aboutToQuit.connect(self.force_quit)24202421        # Запускает новый рабочий поток и подключает слоты для рабочего2422        layout = QtWidgets.QVBoxLayout(self)2423        layout.addWidget(te)2424        layout.addWidget(self.work_button)2425        layout.addWidget(self.log_button)2426        layout.addWidget(self.clear_button)2427        self.setFixedSize(900, 400)24282429        # После запуска кнопка должна быть отключена2430        self.log_button.clicked.connect(self.manual_update)2431        self.clear_button.clicked.connect(self.clear_display)24322433        # Запустить новый рабочий поток и подключить слоты для рабочего2434        self.start_thread()2435        self.work_button.clicked.connect(self.worker.start)2436        # Это запустит цикл событий в рабочем потоке2437        self.work_button.clicked.connect(lambda : self.work_button.setEnabled(False))24382439    def start_thread(self):2440        self.worker = Worker()2441        self.worker_thread = QtCore.QThread()2442        self.worker.setObjectName('Worker')2443        self.worker_thread.setObjectName('WorkerThread')  # Просто скажите рабочему остановиться, затем скажите ему выйти и дождитесь этого2444        self.worker.moveToThread(self.worker_thread)2445        # Для использования при закрытии окна2446        self.worker_thread.start()24472448    def kill_thread(self):2449        # Функции ниже обновляют интерфейс и выполняются в основном потоке, поскольку слоты настроены именно там2450        # Эта функция использует переданное форматированное сообщение, но также использует информацию из записи, чтобы отформатировать сообщение подходящим цветом в соответствии с его серьёзностью (уровнем).2451        self.worker_thread.requestInterruption()2452        if self.worker_thread.isRunning():2453            self.worker_thread.quit()2454            self.worker_thread.wait()2455        else:2456            print('worker has already exited.')24572458    def force_quit(self):2459        # Для использования при закрытии окна2460        if self.worker_thread.isRunning():2461            self.kill_thread()24622463    # Функции ниже обновляют пользовательский интерфейс и выполняются в главном потоке, потому что2464    # здесь настраиваются слоты24652466    @Slot(str, logging.LogRecord)2467    def update_status(self, status, record):2468        color = self.COLORS.get(record.levelno, 'black')2469        s = '<pre><font color="%s">%s</font></pre>' % (color, status)2470        self.textedit.appendHtml(s)24712472    @Slot()2473    def manual_update(self):2474        # Эта функция использует переданное форматированное сообщение, а также использует2475        # информацию из записи для форматирования сообщения в подходящий2476        # цвет в соответствии с его серьёзностью (уровнем).2477        level = random.choice(LEVELS)2478        extra = {'qThreadName': ctname() }2479        logger.log(level, 'Manually logged!', extra=extra)24802481    @Slot()2482    def clear_display(self):2483        self.textedit.clear()24842485def main():2486    QtCore.QThread.currentThread().setObjectName('MainThread')2487    logging.getLogger().setLevel(logging.DEBUG)2488    app = QtWidgets.QApplication(sys.argv)2489    example = Window(app)2490    example.show()2491    sys.exit(app.exec_())24922493if __name__=='__main__':2494    main()2495```24962497## Шаблоны, которых следует избегать24982499Хотя в предыдущих разделах были описаны способы решения задач, с которыми вы можете столкнуться, стоит упомянуть некоторые шаблоны использования, которые *бесполезны* и в большинстве случаев их следует избегать. Следующие разделы приведены в произвольном порядке.25002501### Многократное открытие одного и того же файла журнала25022503В Windows обычно не получится открыть один и тот же файл несколько раз, так как это приведёт к ошибке «файл используется другим процессом». Однако на платформах POSIX никаких ошибок при многократном открытии одного файла не возникнет. Это может произойти случайно, например:25042505- Добавление файлового обработчика более одного раза со ссылкой на один и тот же файл (например, из-за ошибки копирования/вставки/забыли изменить).2506- Открытие двух файлов, которые выглядят разными (у них разные имена), но на самом деле являются одним и тем же файлом, так как один – символическая ссылка на другой.2507- Порождение процесса (форк), после которого и родительский, и дочерний процесс имеют ссылку на один и тот же файл. Это может происходить, например, при использовании модуля [`multiprocessing`](https://python-all.ru/3.9/library/multiprocessing.html#module-multiprocessing).25082509Многократное открытие файла может *выглядеть* работающим большую часть времени, но на практике может привести к ряду проблем:25102511- Вывод логирования может искажаться, поскольку несколько потоков или процессов пытаются писать в один и тот же файл. Хотя логирование защищает от одновременного использования одного и того же экземпляра обработчика несколькими потоками, такой защиты нет, если одновременную запись пытаются выполнить два разных потока, использующие два разных экземпляра обработчика, которые указывают на один и тот же файл.2512- Попытка удалить файл (например, при ротации файлов) молча завершается неудачей, поскольку на него есть другая ссылка. Это может привести к путанице и потере времени на отладку – записи журнала оказываются в неожиданных местах или теряются полностью.25132514Используйте методы, описанные в [Логирование в один файл из нескольких процессов](https://python-all.ru/3.9/howto/logging-cookbook.html#multiple-processes), чтобы обойти такие проблемы.25152516### Использование логгеров в качестве атрибутов класса или передача их в качестве параметров25172518Хотя могут быть необычные случаи, когда это необходимо, в целом в этом нет смысла, потому что логгеры – синглтоны. Код всегда может получить доступ к нужному экземпляру логгера по имени с помощью `logging.getLogger(name)`, поэтому передавать экземпляры повсюду и хранить их в качестве атрибутов экземпляра бессмысленно. Обратите внимание, что в других языках, таких как Java и C#, логгеры часто являются статическими атрибутами класса. Однако этот шаблон не имеет смысла в Python, где модуль (а не класс) является единицей декомпозиции программного обеспечения.25192520### Добавление обработчиков, отличных от `NullHandler`, к логгеру в библиотеке25212522Настройка логирования путём добавления обработчиков, форматировщиков и фильтров – это ответственность разработчика приложения, а не разработчика библиотеки. Если вы поддерживаете библиотеку, убедитесь, что не добавляете обработчики ни к одному из своих логгеров, кроме экземпляра [`NullHandler`](https://python-all.ru/3.9/library/logging.handlers.html#logging.NullHandler).25232524### Создание большого количества логгеров25252526Логгеры – это синглтоны, которые никогда не освобождаются во время выполнения скрипта, поэтому создание большого количества логгеров приведёт к расходу памяти, которую затем нельзя освободить. Вместо того чтобы создавать логгер для каждого обрабатываемого файла или сетевого соединения, используйте [существующие механизмы](https://python-all.ru/3.9/howto/logging-cookbook.html#context-info) для передачи контекстной информации в ваши журналы и ограничьте создаваемые логгеры теми, которые описывают области вашего приложения (обычно модули, но иногда и с чуть большей детализацией).2527