logging-cookbook.md
1> **Источник:** https://python-all.ru/3.12/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На этой странице собрано несколько рецептов по логированию, которые оказались полезными. Ссылки на учебные и справочные материалы см. в разделе [Другие ресурсы](https://python-all.ru/3.12/howto/logging-cookbook.html#cookbook-ref-links).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.12/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='/tmp/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Обратите внимание, что указанное выше имя файла журнала `/tmp/myapp.log` подразумевает использование стандартного расположения временных файлов в системах POSIX. В Windows может потребоваться выбрать другое имя каталога для журнала – просто убедитесь, что каталог существует и у вас есть права на создание и обновление файлов в нём.251252## Пользовательская обработка уровней253254Иногда может потребоваться немного отойти от стандартной обработки уровней в обработчиках, когда все уровни выше порога обрабатываются одним обработчиком. Для этого нужно использовать фильтры. Рассмотрим сценарий, в котором требуется организовать работу следующим образом:255256- Отправлять сообщения уровня `INFO` и `WARNING` в `sys.stdout`257- Отправлять сообщения уровня `ERROR` и выше в `sys.stderr`258- Отправлять сообщения уровня `DEBUG` и выше в файл `app.log`259260Предположим, вы настраиваете журналирование с помощью следующего JSON:261262```json263{264 "version": 1,265 "disable_existing_loggers": false,266 "formatters": {267 "simple": {268 "format": "%(levelname)-8s - %(message)s"269 }270 },271 "handlers": {272 "stdout": {273 "class": "logging.StreamHandler",274 "level": "INFO",275 "formatter": "simple",276 "stream": "ext://sys.stdout"277 },278 "stderr": {279 "class": "logging.StreamHandler",280 "level": "ERROR",281 "formatter": "simple",282 "stream": "ext://sys.stderr"283 },284 "file": {285 "class": "logging.FileHandler",286 "formatter": "simple",287 "filename": "app.log",288 "mode": "w"289 }290 },291 "root": {292 "level": "DEBUG",293 "handlers": [294 "stderr",295 "stdout",296 "file"297 ]298 }299}300```301302Эта конфигурация делает *почти* то, что нужно, за исключением того, что `sys.stdout` будет показывать сообщения уровня `ERROR` и выше, а также `INFO` и `WARNING` сообщения. Чтобы этого избежать, можно настроить фильтр, исключающий эти сообщения, и добавить его в соответствующий обработчик. Это можно настроить, добавив раздел `filters` параллельно `formatters` и `handlers`:303304```json305{306 "filters": {307 "warnings_and_below": {308 "()" : "__main__.filter_maker",309 "level": "WARNING"310 }311 }312}313```314315и изменив раздел обработчика `stdout`, чтобы добавить его:316317```json318{319 "stdout": {320 "class": "logging.StreamHandler",321 "level": "INFO",322 "formatter": "simple",323 "stream": "ext://sys.stdout",324 "filters": ["warnings_and_below"]325 }326}327```328329Фильтр – это просто функция, поэтому можно определить `filter_maker` (фабричную функцию) следующим образом:330331```python332def filter_maker(level):333 level = getattr(logging, level)334335 def filter(record):336 return record.levelno <= level337338 return filter339```340341Это преобразует переданный строковый аргумент в числовой уровень и возвращает функцию, которая возвращает `True` только в том случае, если уровень переданной записи меньше или равен указанному уровню. Обратите внимание, что в этом примере я определил `filter_maker` в тестовом скрипте `main.py`, который запускаю из командной строки, поэтому его модуль будет `__main__` – отсюда `__main__.filter_maker` в конфигурации фильтра. Вам нужно будет изменить это, если вы определите его в другом модуле.342343После добавления фильтра можно запустить `main.py`, полная версия которого:344345```python346import json347import logging348import logging.config349350CONFIG = '''351{352 "version": 1,353 "disable_existing_loggers": false,354 "formatters": {355 "simple": {356 "format": "%(levelname)-8s - %(message)s"357 }358 },359 "filters": {360 "warnings_and_below": {361 "()" : "__main__.filter_maker",362 "level": "WARNING"363 }364 },365 "handlers": {366 "stdout": {367 "class": "logging.StreamHandler",368 "level": "INFO",369 "formatter": "simple",370 "stream": "ext://sys.stdout",371 "filters": ["warnings_and_below"]372 },373 "stderr": {374 "class": "logging.StreamHandler",375 "level": "ERROR",376 "formatter": "simple",377 "stream": "ext://sys.stderr"378 },379 "file": {380 "class": "logging.FileHandler",381 "formatter": "simple",382 "filename": "app.log",383 "mode": "w"384 }385 },386 "root": {387 "level": "DEBUG",388 "handlers": [389 "stderr",390 "stdout",391 "file"392 ]393 }394}395'''396397def filter_maker(level):398 level = getattr(logging, level)399400 def filter(record):401 return record.levelno <= level402403 return filter404405logging.config.dictConfig(json.loads(CONFIG))406logging.debug('A DEBUG message')407logging.info('An INFO message')408logging.warning('A WARNING message')409logging.error('An ERROR message')410logging.critical('A CRITICAL message')411```412413И после запуска вот так:414415```shell416python main.py 2>stderr.log >stdout.log417```418419Мы видим, что результаты соответствуют ожиданиям:420421```shell422$ more *.log423::::::::::::::424app.log425::::::::::::::426DEBUG - A DEBUG message427INFO - An INFO message428WARNING - A WARNING message429ERROR - An ERROR message430CRITICAL - A CRITICAL message431::::::::::::::432stderr.log433::::::::::::::434ERROR - An ERROR message435CRITICAL - A CRITICAL message436::::::::::::::437stdout.log438::::::::::::::439INFO - An INFO message440WARNING - A WARNING message441```442443## Пример сервера конфигурации444445Вот пример модуля, использующего сервер конфигурации журналирования:446447```python448import logging449import logging.config450import time451import os452453# Прочитать начальный конфигурационный файл.454logging.config.fileConfig('logging.conf')455456# Создать и запустить слушатель на порту 9999.457t = logging.config.listen(9999)458t.start()459460logger = logging.getLogger('simpleExample')461462try:463 # Прокрутить вызовы логирования, чтобы увидеть разницу.464 # Создавать новые конфигурации до нажатия Ctrl+C.465 while True:466 logger.debug('debug message')467 logger.info('info message')468 logger.warning('warn message')469 logger.error('error message')470 logger.critical('critical message')471 time.sleep(5)472except KeyboardInterrupt:473 # очистка474 logging.config.stopListening()475 t.join()476```477478А вот скрипт, который принимает имя файла и отправляет этот файл на сервер, предварив его двоично-закодированной длиной, в качестве новой конфигурации журналирования:479480```python481#!/usr/bin/env python482import socket, sys, struct483484with open(sys.argv[1], 'rb') as f:485 data_to_send = f.read()486487HOST = 'localhost'488PORT = 9999489s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)490print('connecting...')491s.connect((HOST, PORT))492print('sending config...')493s.send(struct.pack('>L', len(data_to_send)))494s.send(data_to_send)495s.close()496print('complete')497```498499## Работа с блокирующими обработчиками500501Иногда нужно, чтобы ваши обработчики логирования выполняли свою работу без блокировки потока, из которого ведётся логирование. Это часто встречается в веб-приложениях, хотя, конечно, бывает и в других сценариях.502503Типичный виновник медленной работы – [`SMTPHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.SMTPHandler): отправка электронной почты может занимать много времени по ряду причин, не зависящих от разработчика (например, из-за плохой работы почтовой или сетевой инфраструктуры). Но почти любой сетевой обработчик может блокировать: даже операция [`SocketHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.SocketHandler) может выполнять DNS-запрос «под капотом», который оказывается слишком медленным (и этот запрос может быть глубоко в коде библиотеки сокетов, ниже уровня Python и вне вашего контроля).504505Одно из решений – использовать двухчастный подход. На первом этапе к логгерам, к которым обращаются из критичных по производительности потоков, следует подключать только [`QueueHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.QueueHandler). Они просто пишут в свою очередь, которую можно настроить на достаточно большую ёмкость или инициализировать без верхнего ограничения размера. Запись в очередь обычно выполняется быстро, хотя в коде желательно перехватывать исключение [`queue.Full`](https://python-all.ru/3.12/library/queue.html#queue.Full) на всякий случай. Если вы – разработчик библиотеки, в коде которой есть критичные по производительности потоки, обязательно задокументируйте это (вместе с рекомендацией подключать к вашим логгерам только `QueueHandlers`) для пользы других разработчиков, которые будут использовать ваш код.506507Вторая часть решения – [`QueueListener`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.QueueListener), который был разработан как аналог [`QueueHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.QueueHandler). [`QueueListener`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.QueueListener) устроен очень просто: ему передаётся очередь и несколько обработчиков, и он запускает внутренний поток, который слушает свою очередь на предмет LogRecords, отправленных из `QueueHandlers` (или любого другого источника `LogRecords`). `LogRecords` извлекаются из очереди и передаются обработчикам для обработки.508509Преимущество отдельного класса [`QueueListener`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.QueueListener) в том, что один его экземпляр может обслуживать несколько `QueueHandlers`. Это более экономит ресурсы, чем, скажем, многопоточные версии существующих классов обработчиков, которые расходовали бы по одному потоку на обработчик без особой пользы.510511Ниже приведён пример использования этих двух классов (импорты опущены):512513```python514que = queue.Queue(-1) # Без ограничения размера.515queue_handler = QueueHandler(que)516handler = logging.StreamHandler()517listener = QueueListener(que, handler)518root = logging.getLogger()519root.addHandler(queue_handler)520formatter = logging.Formatter('%(threadName)s: %(message)s')521handler.setFormatter(formatter)522listener.start()523# Вывод лога будет отображать поток, создавший событие (главный поток), а не внутренний поток,524# отслеживающий внутреннюю очередь.525# Именно это и должно происходить.526# то, что должно произойти.527root.warning('Look out!')528listener.stop()529```530531который при запуске выведет:532533```text534MainThread: Look out!535```536537> **Примечание**538>539> Хотя предыдущее обсуждение не касалось напрямую асинхронного кода, а скорее медленных обработчиков логирования, следует отметить, что при логировании из асинхронного кода сетевые и даже файловые обработчики могут приводить к проблемам (блокировать цикл событий), поскольку часть логирования выполняется внутри [`asyncio`](https://python-all.ru/3.12/library/asyncio.html#module-asyncio). Поэтому, если в приложении используется асинхронный код, лучше всего применять описанный выше подход к логированию, чтобы любой блокирующий код выполнялся только в `QueueListener` потоке.540541Изменено в версии 3.5: До Python 3.5 [`QueueListener`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.QueueListener) всегда передавал каждое полученное из очереди сообщение каждому обработчику, с которыми был инициализирован. (Это объяснялось тем, что предполагалось, что фильтрация по уровню полностью выполняется на стороне наполнения очереди.) Начиная с версии 3.5 это поведение можно изменить, передав именованный аргумент `respect_handler_level=True` конструктору слушателя. Когда это сделано, слушатель сравнивает уровень каждого сообщения с уровнем обработчика и передаёт сообщение обработчику, только если это уместно.542543## Отправка и получение событий логирования по сети544545Допустим, вы хотите отправлять события логирования по сети и обрабатывать их на принимающей стороне. Простой способ – подключить экземпляр [`SocketHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.SocketHandler) к корневому логгеру на отправляющей стороне:546547```python548import logging, logging.handlers549550rootLogger = logging.getLogger('')551rootLogger.setLevel(logging.DEBUG)552socketHandler = logging.handlers.SocketHandler('localhost',553 logging.handlers.DEFAULT_TCP_LOGGING_PORT)554# Не нужно использовать форматтер, так как сокет-обработчик отправляет событие в виде неформатированного пикла.555# неформатированный pickle556rootLogger.addHandler(socketHandler)557558# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...559logging.info('Jackdaws love my big sphinx of quartz.')560561# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:562# приложение:563564logger1 = logging.getLogger('myapp.area1')565logger2 = logging.getLogger('myapp.area2')566567logger1.debug('Quick zephyrs blow, vexing daft Jim.')568logger1.info('How quickly daft jumping zebras vex.')569logger2.warning('Jail zesty vixen who grabbed pay from quack.')570logger2.error('The five boxing wizards jump quickly.')571```572573На принимающей стороне можно настроить приёмник с помощью модуля [`socketserver`](https://python-all.ru/3.12/library/socketserver.html#module-socketserver). Вот простой работающий пример:574575```python576import pickle577import logging578import logging.handlers579import socketserver580import struct581582class LogRecordStreamHandler(socketserver.StreamRequestHandler):583 """Обработчик для потокового запроса логирования.584585 Это по сути записывает запись, используя ту политику логирования, которая настроена локально.586 настроено локально.587 """588589 def handle(self):590 """591 Обрабатывает несколько запросов – каждый ожидается в формате: 4-байтовая длина, затем запись журнала в формате пикл.592 Записывает запись в соответствии с политикой, настроенной локально.593 согласно локально настроенной политике.594 """595 while True:596 chunk = self.connection.recv(4)597 if len(chunk) < 4:598 break599 slen = struct.unpack('>L', chunk)[0]600 chunk = self.connection.recv(slen)601 while len(chunk) < slen:602 chunk = chunk + self.connection.recv(slen - len(chunk))603 obj = self.unPickle(chunk)604 record = logging.makeLogRecord(obj)605 self.handleLogRecord(record)606607 def unPickle(self, data):608 return pickle.loads(data)609610 def handleLogRecord(self, record):611 # Если указано имя, используется именованный логгер, а не тот, что612 # подразумевается записью.613 if self.server.logname is not None:614 name = self.server.logname615 else:616 name = record.name617 logger = logging.getLogger(name)618 # Примечание: КАЖДАЯ запись попадает в журнал. Это связано с тем, что Logger.handle619 # обычно вызывается ПОСЛЕ фильтрации на уровне регистратора. Если требуется620 # выполнять фильтрацию, делайте это на стороне клиента, чтобы не тратить621 # циклы процессора и сетевую пропускную способность!622 logger.handle(record)623624class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):625 """626 Простой приёмник журнала на основе TCP-сокетов, подходящий для тестирования.627 """628629 allow_reuse_address = True630631 def __init__(self, host='localhost',632 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,633 handler=LogRecordStreamHandler):634 socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)635 self.abort = 0636 self.timeout = 1637 self.logname = None638639 def serve_until_stopped(self):640 import select641 abort = 0642 while not abort:643 rd, wr, ex = select.select([self.socket.fileno()],644 [], [],645 self.timeout)646 if rd:647 self.handle_request()648 abort = self.abort649650def main():651 logging.basicConfig(652 format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')653 tcpserver = LogRecordSocketReceiver()654 print('About to start TCP server...')655 tcpserver.serve_until_stopped()656657if __name__ == '__main__':658 main()659```660661Сначала запустите сервер, затем клиент. На стороне клиента в консоль ничего не выводится; на стороне сервера вы должны увидеть что-то вроде:662663```text664About to start TCP server...665 59 root INFO Jackdaws love my big sphinx of quartz.666 59 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim.667 69 myapp.area1 INFO How quickly daft jumping zebras vex.668 69 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack.669 69 myapp.area2 ERROR The five boxing wizards jump quickly.670```671672Обратите внимание, что в некоторых сценариях существуют проблемы безопасности с pickle. Если они вас затрагивают, вы можете использовать альтернативную схему сериализации, переопределив метод [`makePickle()`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.SocketHandler.makePickle) и реализовав свою альтернативу там, а также адаптировав вышеприведённый скрипт для использования вашей альтернативной сериализации.673674### Запуск сокетного слушателя логирования в продакшене675676Для запуска слушателя логирования в продакшене может потребоваться инструмент управления процессами, такой как [Supervisor](https://python-all.ru/3.12/howto/logging-cookbook.html). [Вот Gist](https://python-all.ru/3.12/howto/logging-cookbook.html), который содержит минимальные файлы для запуска описанной выше функциональности с помощью Supervisor. Он состоит из следующих файлов:677678| Файл | Назначение |679| --- | --- |680| `prepare.sh` | Bash-скрипт для подготовки окружения к тестированию |681| `supervisor.conf` | Файл конфигурации Supervisor с записями для слушателя и многопроцессного веб-приложения |682| `ensure_app.sh` | Bash-скрипт для обеспечения работы Supervisor с указанной конфигурацией |683| `log_listener.py` | Программа сокетного слушателя, которая получает события логирования и записывает их в файл |684| `main.py` | Простое веб-приложение, которое выполняет логирование через сокет, подключённый к слушателю |685| `webapp.json` | JSON-файл конфигурации для веб-приложения |686| `client.py` | Python-скрипт для тестирования веб-приложения |687688Веб-приложение использует [Gunicorn](https://python-all.ru/3.12/howto/logging-cookbook.html) – популярный сервер веб-приложений, который запускает несколько рабочих процессов для обработки запросов. Данный пример показывает, как рабочие процессы могут писать в один и тот же файл журнала, не мешая друг другу – все они проходят через сокетный слушатель.689690Чтобы протестировать эти файлы, выполните следующие действия в среде POSIX:6916921. Скачайте [Gist](https://python-all.ru/3.12/howto/logging-cookbook.html) в виде ZIP-архива, используя кнопку Download ZIP.6932. Распакуйте указанные файлы из архива во временный каталог.6943. Во временном каталоге выполните `bash prepare.sh` для подготовки. При этом будут созданы подкаталог `run` для файлов, связанных с Supervisor, и журналов, а также подкаталог `venv` для виртуального окружения, в которое будут установлены `bottle`, `gunicorn` и `supervisor`.6954. Запустите `bash ensure_app.sh`, чтобы убедиться, что Supervisor работает с указанной выше конфигурацией.6965. Запустите `venv/bin/python client.py` для проверки веб-приложения, что приведёт к записи данных в журнал.6976. Проверьте файлы журнала в подкаталоге `run`. Вы должны увидеть самые свежие строки журнала в файлах, соответствующих шаблону `app.log*`. Они не будут в каком-либо определённом порядке, так как были обработаны параллельно разными рабочими процессами недетерминированным образом.6987. Вы можете остановить слушатель и веб-приложение, выполнив `venv/bin/supervisorctl -c supervisor.conf shutdown`.699700Возможно, потребуется подправить файлы конфигурации в маловероятном случае, если настроенные порты конфликтуют с чем-либо ещё в вашей тестовой среде.701702В конфигурации по умолчанию используется TCP-сокет на порту 9020. Вы можете использовать сокет Unix Domain вместо TCP-сокета, выполнив следующее:7037041. В `listener.json` добавьте ключ `socket` с путём к доменному сокету, который вы хотите использовать. Если этот ключ присутствует, слушатель прослушивает соответствующий доменный сокет, а не TCP-сокет (ключ `port` игнорируется).7052. В `webapp.json` измените словарь конфигурации обработчика сокетов так, чтобы значением `host` был путь к доменному сокету, а значение `port` установите в `null`.706707## Добавление контекстной информации в вывод журнала708709Иногда требуется, чтобы вывод журнала содержал контекстную информацию в дополнение к параметрам, переданным в вызове логирования. Например, в сетевом приложении может быть желательно записывать в журнал информацию, специфичную для клиента (например, имя пользователя удалённого клиента или IP-адрес). Хотя для этого можно использовать параметр *extra*, не всегда удобно передавать информацию таким образом. Может возникнуть соблазн создавать экземпляры [`Logger`](https://python-all.ru/3.12/library/logging.html#logging.Logger) для каждого соединения, но это плохая идея, поскольку такие экземпляры не собираются сборщиком мусора. Хотя на практике это не проблема, когда количество экземпляров [`Logger`](https://python-all.ru/3.12/library/logging.html#logging.Logger) зависит от уровня детализации, используемого при логировании приложения, управление ими может стать сложным, если количество экземпляров [`Logger`](https://python-all.ru/3.12/library/logging.html#logging.Logger) станет фактически неограниченным.710711### Использование LoggerAdapter для добавления контекстной информации712713Простой способ передавать контекстную информацию для вывода вместе с информацией о событиях логирования – использовать класс [`LoggerAdapter`](https://python-all.ru/3.12/library/logging.html#logging.LoggerAdapter). Этот класс спроектирован так, чтобы выглядеть как [`Logger`](https://python-all.ru/3.12/library/logging.html#logging.Logger), что позволяет вызывать [`debug()`](https://python-all.ru/3.12/library/logging.html#logging.debug), [`info()`](https://python-all.ru/3.12/library/logging.html#logging.info), [`warning()`](https://python-all.ru/3.12/library/logging.html#logging.warning), [`error()`](https://python-all.ru/3.12/library/logging.html#logging.error), [`exception()`](https://python-all.ru/3.12/library/logging.html#logging.exception), [`critical()`](https://python-all.ru/3.12/library/logging.html#logging.critical) и [`log()`](https://python-all.ru/3.12/library/logging.html#logging.log). Эти методы имеют те же сигнатуры, что и их аналоги в [`Logger`](https://python-all.ru/3.12/library/logging.html#logging.Logger), поэтому экземпляры обоих типов можно использовать взаимозаменяемо.714715При создании экземпляра [`LoggerAdapter`](https://python-all.ru/3.12/library/logging.html#logging.LoggerAdapter) вы передаёте ему экземпляр [`Logger`](https://python-all.ru/3.12/library/logging.html#logging.Logger) и объект, подобный словарю, содержащий вашу контекстную информацию. Когда вы вызываете один из методов логирования на экземпляре [`LoggerAdapter`](https://python-all.ru/3.12/library/logging.html#logging.LoggerAdapter), он делегирует вызов базовому экземпляру [`Logger`](https://python-all.ru/3.12/library/logging.html#logging.Logger), переданному в конструктор, и организует передачу контекстной информации в этом делегированном вызове. Вот фрагмент кода [`LoggerAdapter`](https://python-all.ru/3.12/library/logging.html#logging.LoggerAdapter):716717```python718def debug(self, msg, /, *args, **kwargs):719 """720 Передаёт вызов отладки нижележащему регистратору после добавления721 контекстной информации из данного экземпляра адаптера.722 """723 msg, kwargs = self.process(msg, kwargs)724 self.logger.debug(msg, *args, **kwargs)725```726727Метод [`process()`](https://python-all.ru/3.12/library/logging.html#logging.LoggerAdapter.process) класса [`LoggerAdapter`](https://python-all.ru/3.12/library/logging.html#logging.LoggerAdapter) – это то место, где контекстная информация добавляется в вывод журнала. Ему передаются сообщение и именованные аргументы вызова логирования, а он возвращает (потенциально) изменённые версии для использования в вызове базового регистратора. В реализации по умолчанию этот метод оставляет сообщение без изменений, но вставляет ключ 'extra' в именованные аргументы, значением которого является объект, подобный словарю, переданный конструктору. Конечно, если вы передали именованный аргумент 'extra' в вызове адаптера, он будет молча перезаписан.728729Преимущество использования 'extra' в том, что значения из объекта, подобного словарю, сливаются в \_\_dict\_\_ экземпляра [`LogRecord`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord), что позволяет использовать настроенные строки с экземплярами [`Formatter`](https://python-all.ru/3.12/library/logging.html#logging.Formatter), которые знают о ключах этого объекта. Если вам нужен другой метод, например, добавить контекстную информацию в начало или конец строки сообщения, достаточно создать подкласс [`LoggerAdapter`](https://python-all.ru/3.12/library/logging.html#logging.LoggerAdapter) и переопределить [`process()`](https://python-all.ru/3.12/library/logging.html#logging.LoggerAdapter.process) для нужного поведения. Вот простой пример:730731```python732class CustomAdapter(logging.LoggerAdapter):733 """734 Данный пример адаптера ожидает, что переданный объект, подобный словарю, содержит735 ключ 'connid', значение которого в квадратных скобках добавляется к началу сообщения журнала.736 """737 def process(self, msg, kwargs):738 return '[%s] %s' % (self.extra['connid'], msg), kwargs739```740741который можно использовать так:742743```python744logger = logging.getLogger(__name__)745adapter = CustomAdapter(logger, {'connid': some_conn_id})746```747748Тогда все события, регистрируемые через адаптер, будут содержать значение `some_conn_id`, добавленное в начало сообщений журнала.749750#### Использование объектов, отличных от словарей, для передачи контекстной информации751752Необязательно передавать в [`LoggerAdapter`](https://python-all.ru/3.12/library/logging.html#logging.LoggerAdapter) именно словарь – можно передать экземпляр класса, реализующего `__getitem__` и `__iter__`, чтобы он выглядел как словарь для системы логирования. Это полезно, если нужно генерировать значения динамически (тогда как значения в словаре были бы постоянными).753754### Использование фильтров для добавления контекстной информации755756Вы также можете добавлять контекстную информацию в вывод журнала с помощью определённого пользователем [`Filter`](https://python-all.ru/3.12/library/logging.html#logging.Filter). Экземплярам `Filter` разрешено изменять `LogRecords`, переданный им, включая добавление дополнительных атрибутов, которые затем можно выводить с помощью подходящей форматной строки или, если необходимо, пользовательского [`Formatter`](https://python-all.ru/3.12/library/logging.html#logging.Formatter).757758Например, в веб-приложении обрабатываемый запрос (или, по крайней мере, его интересные части) можно сохранить в потоковой локальной переменной ([`threading.local`](https://python-all.ru/3.12/library/threading.html#threading.local)), а затем из `Filter` получить к ней доступ, чтобы добавить, скажем, информацию из запроса – например, удалённый IP-адрес и имя пользователя – в `LogRecord`, используя имена атрибутов 'ip' и 'user', как в примере с `LoggerAdapter` выше. В этом случае можно использовать ту же форматную строку для получения вывода, аналогичного показанному выше. Вот пример скрипта:759760```python761import logging762from random import choice763764class ContextFilter(logging.Filter):765 """766 Это фильтр, который внедряет контекстную информацию в журнал.767768 Вместо использования реальной контекстной информации в данном примере используются случайные769 данные.770 """771772 USERS = ['jim', 'fred', 'sheila']773 IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']774775 def filter(self, record):776777 record.ip = choice(ContextFilter.IPS)778 record.user = choice(ContextFilter.USERS)779 return True780781if __name__ == '__main__':782 levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)783 logging.basicConfig(level=logging.DEBUG,784 format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')785 a1 = logging.getLogger('a.b.c')786 a2 = logging.getLogger('d.e.f')787788 f = ContextFilter()789 a1.addFilter(f)790 a2.addFilter(f)791 a1.debug('A debug message')792 a1.info('An info message with %s', 'some parameters')793 for x in range(10):794 lvl = choice(levels)795 lvlname = logging.getLevelName(lvl)796 a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')797```798799который при запуске выдаёт примерно следующее:800801```text8022010-09-06 22:38:15,292 a.b.c DEBUG IP: 123.231.231.123 User: fred A debug message8032010-09-06 22:38:15,300 a.b.c INFO IP: 192.168.0.1 User: sheila An info message with some parameters8042010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters8052010-09-06 22:38:15,300 d.e.f ERROR IP: 127.0.0.1 User: jim A message at ERROR level with 2 parameters8062010-09-06 22:38:15,300 d.e.f DEBUG IP: 127.0.0.1 User: sheila A message at DEBUG level with 2 parameters8072010-09-06 22:38:15,300 d.e.f ERROR IP: 123.231.231.123 User: fred A message at ERROR level with 2 parameters8082010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1 User: jim A message at CRITICAL level with 2 parameters8092010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters8102010-09-06 22:38:15,300 d.e.f DEBUG IP: 192.168.0.1 User: jim A message at DEBUG level with 2 parameters8112010-09-06 22:38:15,301 d.e.f ERROR IP: 127.0.0.1 User: sheila A message at ERROR level with 2 parameters8122010-09-06 22:38:15,301 d.e.f DEBUG IP: 123.231.231.123 User: fred A message at DEBUG level with 2 parameters8132010-09-06 22:38:15,301 d.e.f INFO IP: 123.231.231.123 User: fred A message at INFO level with 2 parameters814```815816## Использование `contextvars`817818Начиная с Python 3.7, модуль [`contextvars`](https://python-all.ru/3.12/library/contextvars.html#module-contextvars) предоставляет контекстно-локальное хранилище, которое работает как для [`threading`](https://python-all.ru/3.12/library/threading.html#module-threading), так и для [`asyncio`](https://python-all.ru/3.12/library/asyncio.html#module-asyncio) обработки. Этот тип хранилища может быть в целом предпочтительнее потоковых локальных переменных. Следующий пример показывает, как в многопоточной среде журналы могут наполняться контекстной информацией, например, атрибутами запросов, обрабатываемых веб-приложениями.819820Для иллюстрации предположим, что у вас есть разные веб-приложения, каждое независимо от других, но запущенные в одном процессе Python и использующие общую для них библиотеку. Как каждое из этих приложений может иметь собственный журнал, где все сообщения логирования из библиотеки (и другого кода обработки запросов) направляются в соответствующий файл журнала приложения, а также включают в журнал дополнительную контекстную информацию, такую как IP-адрес клиента, метод HTTP-запроса и имя пользователя?821822Предположим, что библиотеку можно смоделировать следующим кодом:823824```python825# webapplib.py826import logging827import time828829logger = logging.getLogger(__name__)830831def useful():832 # Просто представительное событие, зарегистрированное из библиотеки833 logger.debug('Hello from webapplib!')834 # Просто приостановить выполнение на некоторое время, чтобы дать возможность другим потокам поработать835 time.sleep(0.01)836```837838Мы можем смоделировать несколько веб-приложений с помощью двух простых классов, `Request` и `WebApp`. Они имитируют работу реальных многопоточных веб-приложений – каждый запрос обрабатывается отдельным потоком:839840```python841# main.py842import argparse843from contextvars import ContextVar844import logging845import os846from random import choice847import threading848import webapplib849850logger = logging.getLogger(__name__)851root = logging.getLogger()852root.setLevel(logging.DEBUG)853854class Request:855 """856 Простой фиктивный класс запроса, который просто хранит фиктивные метод HTTP-запроса,857 IP-адрес клиента и имя пользователя клиента858 """859 def __init__(self, method, ip, user):860 self.method = method861 self.ip = ip862 self.user = user863864# Фиктивный набор запросов, который будет использоваться в симуляции – мы будем просто выбирать865# из этого списка случайным образом. Обратите внимание, что все GET-запросы приходят с адресов 192.168.2.XXX866# адресов, тогда как POST-запросы – с адресов 192.16.3.XXX. В примере запросов представлены три пользователя867# представлены в примере запросов.868869REQUESTS = [870 Request('GET', '192.168.2.20', 'jim'),871 Request('POST', '192.168.3.20', 'fred'),872 Request('GET', '192.168.2.21', 'sheila'),873 Request('POST', '192.168.3.21', 'jim'),874 Request('GET', '192.168.2.22', 'fred'),875 Request('POST', '192.168.3.22', 'sheila'),876]877878# Обратите внимание, что строка форматирования содержит ссылки на контекстную информацию запроса879# такую как HTTP-метод, IP-адрес клиента и имя пользователя880881formatter = logging.Formatter('%(threadName)-11s %(appName)s %(name)-9s %(user)-6s %(ip)s %(method)-4s %(message)s')882883# Создаём контекстные переменные. Они будут заполнены в начале обработки запроса884# и использоваться в журналировании, которое выполняется в ходе этой обработки885886ctx_request = ContextVar('request')887ctx_appname = ContextVar('appname')888889class InjectingFilter(logging.Filter):890 """891 Фильтр, который внедряет в журналы контекстно-зависимую информацию и гарантирует,892 что в его журнал включается только информация для конкретного веб-приложения893 """894 def __init__(self, app):895 self.app = app896897 def filter(self, record):898 request = ctx_request.get()899 record.method = request.method900 record.ip = request.ip901 record.user = request.user902 record.appName = appName = ctx_appname.get()903 return appName == self.app.name904905class WebApp:906 """907 Фиктивный класс веб-приложения, который имеет собственный обработчик и фильтр для908 журнала, специфичного для веб-приложения.909 """910 def __init__(self, name):911 self.name = name912 handler = logging.FileHandler(name + '.log', 'w')913 f = InjectingFilter(self)914 handler.setFormatter(formatter)915 handler.addFilter(f)916 root.addHandler(handler)917 self.num_requests = 0918919 def process_request(self, request):920 """921 Это фиктивный метод обработки запроса. Он вызывается для922 отдельный поток для каждого запроса. Сохраняем информацию контекста в923 контекстные переменные перед тем, как делать что-либо ещё.924 """925 ctx_request.set(request)926 ctx_appname.set(self.name)927 self.num_requests += 1928 logger.debug('Request processing started')929 webapplib.useful()930 logger.debug('Request processing finished')931932def main():933 fn = os.path.splitext(os.path.basename(__file__))[0]934 adhf = argparse.ArgumentDefaultsHelpFormatter935 ap = argparse.ArgumentParser(formatter_class=adhf, prog=fn,936 description='Simulate a couple of web '937 'applications handling some '938 'requests, showing how request '939 'context can be used to '940 'populate logs')941 aa = ap.add_argument942 aa('--count', '-c', type=int, default=100, help='How many requests to simulate')943 options = ap.parse_args()944945 # Создаём фиктивные веб-приложения и помещаем их в список, из которого будем выбирать946 # случайным образом.947 app1 = WebApp('app1')948 app2 = WebApp('app2')949 apps = [app1, app2]950 threads = []951 # Добавляем общий обработчик, который будет перехватывать все события.952 handler = logging.FileHandler('app.log', 'w')953 handler.setFormatter(formatter)954 root.addHandler(handler)955956 # Генерируем вызовы для обработки запросов.957 for i in range(options.count):958 try:959 # Выбираем случайное приложение и запрос для него.960 app = choice(apps)961 request = choice(REQUESTS)962 # Обрабатываем запрос в его собственном потоке.963 t = threading.Thread(target=app.process_request, args=(request,))964 threads.append(t)965 t.start()966 except KeyboardInterrupt:967 break968969 # Ждём завершения потоков.970 for t in threads:971 t.join()972973 for app in apps:974 print('%s processed %s requests' % (app.name, app.num_requests))975976if __name__ == '__main__':977 main()978```979980Если запустить приведённый выше код, вы обнаружите, что примерно половина запросов попадает в `app1.log`, а остальные – в `app2.log`, и все запросы регистрируются в `app.log`. Каждый журнал, специфичный для веб-приложения, будет содержать только записи для этого приложения, а информация о запросе будет отображаться в журнале согласованно (т.е. информация каждого фиктивного запроса всегда будет появляться вместе в одной строке журнала). Это иллюстрируется следующим выводом оболочки:981982```shell983~/logging-contextual-webapp$ python main.py984app1 processed 51 requests985app2 processed 49 requests986~/logging-contextual-webapp$ wc -l *.log987 153 app1.log988 147 app2.log989 300 app.log990 600 total991~/logging-contextual-webapp$ head -3 app1.log992Thread-3 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started993Thread-3 (process_request) app1 webapplib jim 192.168.3.21 POST Hello from webapplib!994Thread-5 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started995~/logging-contextual-webapp$ head -3 app2.log996Thread-1 (process_request) app2 __main__ sheila 192.168.2.21 GET Request processing started997Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET Hello from webapplib!998Thread-2 (process_request) app2 __main__ jim 192.168.2.20 GET Request processing started999~/logging-contextual-webapp$ head app.log1000Thread-1 (process_request) app2 __main__ sheila 192.168.2.21 GET Request processing started1001Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET Hello from webapplib!1002Thread-2 (process_request) app2 __main__ jim 192.168.2.20 GET Request processing started1003Thread-3 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1004Thread-2 (process_request) app2 webapplib jim 192.168.2.20 GET Hello from webapplib!1005Thread-3 (process_request) app1 webapplib jim 192.168.3.21 POST Hello from webapplib!1006Thread-4 (process_request) app2 __main__ fred 192.168.2.22 GET Request processing started1007Thread-5 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1008Thread-4 (process_request) app2 webapplib fred 192.168.2.22 GET Hello from webapplib!1009Thread-6 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1010~/logging-contextual-webapp$ grep app1 app1.log | wc -l10111531012~/logging-contextual-webapp$ grep app2 app2.log | wc -l10131471014~/logging-contextual-webapp$ grep app1 app.log | wc -l10151531016~/logging-contextual-webapp$ grep app2 app.log | wc -l10171471018```10191020## Добавление контекстной информации в обработчиках10211022Каждый [`Handler`](https://python-all.ru/3.12/library/logging.html#logging.Handler) имеет собственную цепочку фильтров. Если нужно добавить контекстную информацию в [`LogRecord`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord) без её утечки в другие обработчики, можно использовать фильтр, возвращающий новый [`LogRecord`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord) вместо изменения исходного на месте, как показано в следующем скрипте:10231024```python1025import copy1026import logging10271028def filter(record: logging.LogRecord):1029 record = copy.copy(record)1030 record.user = 'jim'1031 return record10321033if __name__ == '__main__':1034 logger = logging.getLogger()1035 logger.setLevel(logging.INFO)1036 handler = logging.StreamHandler()1037 formatter = logging.Formatter('%(message)s from %(user)-8s')1038 handler.setFormatter(formatter)1039 handler.addFilter(filter)1040 logger.addHandler(handler)10411042 logger.info('A log message')1043```10441045## Ведение журнала в один файл из нескольких процессов10461047Хотя модуль logging является потокобезопасным и запись в один файл из нескольких потоков в одном процессе *поддерживается*, запись в один файл из *нескольких процессов* *не* поддерживается, поскольку в Python нет стандартного способа сериализовать доступ к одному файлу из нескольких процессов. Если нужно вести журнал в один файл из нескольких процессов, один из способов – сделать так, чтобы все процессы записывали данные в [`SocketHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.SocketHandler), а отдельный процесс реализовывал сокет-сервер, который читает из сокета и записывает в файл. (Если хотите, можно выделить один поток в одном из существующих процессов для выполнения этой функции.) [В этом разделе](https://python-all.ru/3.12/howto/logging-cookbook.html#network-logging) подробно описывается данный подход и приводится рабочий приёмник сокета, который можно использовать как отправную точку для адаптации в своих приложениях.10481049Вы также можете написать собственный обработчик, который использует класс [`Lock`](https://python-all.ru/3.12/library/multiprocessing.html#multiprocessing.Lock) из модуля [`multiprocessing`](https://python-all.ru/3.12/library/multiprocessing.html#module-multiprocessing) для сериализации доступа к файлу из ваших процессов. Существующие [`FileHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.FileHandler) и подклассы в настоящее время не используют [`multiprocessing`](https://python-all.ru/3.12/library/multiprocessing.html#module-multiprocessing), хотя в будущем они могут это сделать. Обратите внимание, что в настоящее время модуль [`multiprocessing`](https://python-all.ru/3.12/library/multiprocessing.html#module-multiprocessing) не обеспечивает рабочую функциональность блокировки на всех платформах (см. [https://bugs.python.org/issue3770](https://python-all.ru/3.12/howto/logging-cookbook.html)).10501051В качестве альтернативы можно использовать `Queue` и [`QueueHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.QueueHandler) для отправки всех событий журналирования одному из процессов в вашем многопроцессном приложении. В следующем примере сценария показано, как это сделать; в примере отдельный процесс-слушатель ожидает события, отправленные другими процессами, и регистрирует их в соответствии со своей собственной конфигурацией журналирования. Хотя пример демонстрирует лишь один из способов (например, вместо отдельного процесса-слушателя можно использовать поток-слушатель – реализация будет аналогичной), он позволяет задать полностью разные конфигурации журналирования для слушателя и остальных процессов в вашем приложении и может быть использован как основа для кода, отвечающего вашим конкретным требованиям:10521053```python1054# Вам понадобятся эти импорты в вашем коде.1055import logging1056import logging.handlers1057import multiprocessing10581059# Следующие две строки импорта только для этой демонстрации.1060from random import choice, random1061import time10621063#1064# Поскольку нужно задать настройки логирования для слушателя и рабочих процессов, функции1065# слушателя и рабочего процесса принимают параметр configurer – вызываемый объект для1066# настройки логирования этого процесса. Эти функции также получают очередь, которую1067# используют для взаимодействия.1068#1069# На практике слушателя можно настроить как угодно, но заметьте: в этом простом1070# примере слушатель не применяет логику уровней или фильтров к полученным записям.1071# На практике эту логику, вероятно, стоит вынести в рабочие процессы, чтобы не1072# пересылать между процессами события, которые всё равно будут отфильтрованы.1073#1074# Размер файлов при ротации намеренно сделан небольшим, чтобы результат был хорошо виден.1075def listener_configurer():1076 root = logging.getLogger()1077 h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)1078 f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')1079 h.setFormatter(f)1080 root.addHandler(h)10811082# Это главный цикл процесса-слушателя: ждём события логирования1083# (LogRecords) в очереди и обрабатываем их; завершаем работу, когда получаем None вместо1084# LogRecord.1085def listener_process(queue, configurer):1086 configurer()1087 while True:1088 try:1089 record = queue.get()1090 if record is None: # Отправляем это как сигнал завершения, чтобы слушатель остановился.1091 break1092 logger = logging.getLogger(record.name)1093 logger.handle(record) # Никакой логики уровней и фильтров – просто делаем дело!1094 except Exception:1095 import sys, traceback1096 print('Whoops! Problem:', file=sys.stderr)1097 traceback.print_exc(file=sys.stderr)10981099# Массивы для случайного выбора в этой демонстрации.11001101LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,1102 logging.ERROR, logging.CRITICAL]11031104LOGGERS = ['a.b.c', 'd.e.f']11051106MESSAGES = [1107 'Random message #1',1108 'Random message #2',1109 'Random message #3',1110]11111112# Настройка рабочего процесса выполняется в начале его работы.1113# Обратите внимание: в Windows нельзя полагаться на семантику fork, поэтому каждый процесс1114# будет выполнять код настройки логирования при запуске.1115def worker_configurer(queue):1116 h = logging.handlers.QueueHandler(queue) # Нужен только один обработчик.1117 root = logging.getLogger()1118 root.addHandler(h)1119 # Отправляем все сообщения для демонстрации; никакой другой логики уровней или фильтров.1120 root.setLevel(logging.DEBUG)11211122# Это главный цикл рабочего процесса, который просто логирует десять событий с1123# случайные задержки перед завершением.1124# Сообщения print нужны лишь для того, чтобы было видно, что программа работает.1125def worker_process(queue, configurer):1126 configurer(queue)1127 name = multiprocessing.current_process().name1128 print('Worker started: %s' % name)1129 for i in range(10):1130 time.sleep(random())1131 logger = logging.getLogger(choice(LOGGERS))1132 level = choice(LEVELS)1133 message = choice(MESSAGES)1134 logger.log(level, message)1135 print('Worker finished: %s' % name)11361137# Здесь организуется демонстрация. Создать очередь, создать и запустить1138# слушатель, создать десять рабочих процессов и запустить их, дождаться их завершения,1139# затем отправить None в очередь, чтобы сообщить слушателю о завершении.1140def main():1141 queue = multiprocessing.Queue(-1)1142 listener = multiprocessing.Process(target=listener_process,1143 args=(queue, listener_configurer))1144 listener.start()1145 workers = []1146 for i in range(10):1147 worker = multiprocessing.Process(target=worker_process,1148 args=(queue, worker_configurer))1149 workers.append(worker)1150 worker.start()1151 for w in workers:1152 w.join()1153 queue.put_nowait(None)1154 listener.join()11551156if __name__ == '__main__':1157 main()1158```11591160Вариант приведённого выше сценария оставляет ведение журнала в главном процессе, в отдельном потоке:11611162```python1163import logging1164import logging.config1165import logging.handlers1166from multiprocessing import Process, Queue1167import random1168import threading1169import time11701171def logger_thread(q):1172 while True:1173 record = q.get()1174 if record is None:1175 break1176 logger = logging.getLogger(record.name)1177 logger.handle(record)11781179def worker_process(q):1180 qh = logging.handlers.QueueHandler(q)1181 root = logging.getLogger()1182 root.setLevel(logging.DEBUG)1183 root.addHandler(qh)1184 levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1185 logging.CRITICAL]1186 loggers = ['foo', 'foo.bar', 'foo.bar.baz',1187 'spam', 'spam.ham', 'spam.ham.eggs']1188 for i in range(100):1189 lvl = random.choice(levels)1190 logger = logging.getLogger(random.choice(loggers))1191 logger.log(lvl, 'Message no. %d', i)11921193if __name__ == '__main__':1194 q = Queue()1195 d = {1196 'version': 1,1197 'formatters': {1198 'detailed': {1199 'class': 'logging.Formatter',1200 'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1201 }1202 },1203 'handlers': {1204 'console': {1205 'class': 'logging.StreamHandler',1206 'level': 'INFO',1207 },1208 'file': {1209 'class': 'logging.FileHandler',1210 'filename': 'mplog.log',1211 'mode': 'w',1212 'formatter': 'detailed',1213 },1214 'foofile': {1215 'class': 'logging.FileHandler',1216 'filename': 'mplog-foo.log',1217 'mode': 'w',1218 'formatter': 'detailed',1219 },1220 'errors': {1221 'class': 'logging.FileHandler',1222 'filename': 'mplog-errors.log',1223 'mode': 'w',1224 'level': 'ERROR',1225 'formatter': 'detailed',1226 },1227 },1228 'loggers': {1229 'foo': {1230 'handlers': ['foofile']1231 }1232 },1233 'root': {1234 'level': 'DEBUG',1235 'handlers': ['console', 'file', 'errors']1236 },1237 }1238 workers = []1239 for i in range(5):1240 wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))1241 workers.append(wp)1242 wp.start()1243 logging.config.dictConfig(d)1244 lp = threading.Thread(target=logger_thread, args=(q,))1245 lp.start()1246 # На этом этапе главный процесс может заняться своей полезной работой1247 # Когда он с этим закончит, он может дождаться завершения рабочих процессов...1248 for wp in workers:1249 wp.join()1250 # А теперь указать потоку журналирования завершиться1251 q.put(None)1252 lp.join()1253```12541255Этот вариант показывает, как можно, например, применить конфигурацию для определённых регистраторов – например, регистратор `foo` имеет специальный обработчик, который сохраняет все события подсистемы `foo` в файл `mplog-foo.log`. Это будет использовано механизмом журналирования в главном процессе (даже если события журналирования генерируются в рабочих процессах) для направления сообщений к соответствующим местам назначения.12561257### Использование concurrent.futures.ProcessPoolExecutor12581259Если вы хотите использовать [`concurrent.futures.ProcessPoolExecutor`](https://python-all.ru/3.12/library/concurrent.futures.html#concurrent.futures.ProcessPoolExecutor) для запуска рабочих процессов, необходимо создать очередь немного иначе. Вместо12601261```python1262queue = multiprocessing.Queue(-1)1263```12641265следует использовать12661267```python1268queue = multiprocessing.Manager().Queue(-1) # также работает с примерами выше1269```12701271и затем можно заменить создание рабочего процесса с этого:12721273```python1274workers = []1275for i in range(10):1276 worker = multiprocessing.Process(target=worker_process,1277 args=(queue, worker_configurer))1278 workers.append(worker)1279 worker.start()1280for w in workers:1281 w.join()1282```12831284на это (не забудьте сначала импортировать [`concurrent.futures`](https://python-all.ru/3.12/library/concurrent.futures.html#module-concurrent.futures)):12851286```python1287with concurrent.futures.ProcessPoolExecutor(max_workers=10) as executor:1288 for i in range(10):1289 executor.submit(worker_process, queue, worker_configurer)1290```12911292### Развертывание веб-приложений с использованием Gunicorn и uWSGI12931294При развертывании веб-приложений с использованием [Gunicorn](https://python-all.ru/3.12/howto/logging-cookbook.html) или [uWSGI](https://python-all.ru/3.12/howto/logging-cookbook.html) (или аналогичных) создается несколько рабочих процессов для обработки клиентских запросов. В таких средах избегайте создания обработчиков, основанных на файлах, непосредственно в вашем веб-приложении. Вместо этого используйте [`SocketHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.SocketHandler) для логирования из веб-приложения в слушатель в отдельном процессе. Это можно настроить с помощью инструмента управления процессами, такого как Supervisor – см. [Запуск слушателя сокета логирования в производственной среде](https://python-all.ru/3.12/howto/logging-cookbook.html#running-a-logging-socket-listener-in-production) для получения дополнительной информации.12951296## Использование ротации файлов12971298Иногда требуется позволить файлу журнала расти до определённого размера, затем открыть новый файл и вести запись в него. Может потребоваться сохранять определённое количество таких файлов, и когда будет создано заданное число файлов, выполнять ротацию, чтобы и количество, и размер файлов оставались в заданных границах. Для такого сценария использования пакет logging предоставляет [`RotatingFileHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.RotatingFileHandler):12991300```python1301import glob1302import logging1303import logging.handlers13041305LOG_FILENAME = 'logging_rotatingfile_example.out'13061307# Настроить конкретный регистратор с нужным уровнем вывода1308my_logger = logging.getLogger('MyLogger')1309my_logger.setLevel(logging.DEBUG)13101311# Добавить обработчик сообщений журнала в регистратор1312handler = logging.handlers.RotatingFileHandler(1313 LOG_FILENAME, maxBytes=20, backupCount=5)13141315my_logger.addHandler(handler)13161317# Записать несколько сообщений1318for i in range(20):1319 my_logger.debug('i = %d' % i)13201321# Посмотреть, какие файлы созданы1322logfiles = glob.glob('%s*' % LOG_FILENAME)13231324for filename in logfiles:1325 print(filename)1326```13271328В результате должно получиться 6 отдельных файлов, каждый из которых содержит часть истории журнала приложения:13291330```text1331logging_rotatingfile_example.out1332logging_rotatingfile_example.out.11333logging_rotatingfile_example.out.21334logging_rotatingfile_example.out.31335logging_rotatingfile_example.out.41336logging_rotatingfile_example.out.51337```13381339Самый свежий файл всегда называется `logging_rotatingfile_example.out`, и каждый раз при достижении ограничения по размеру он переименовывается с суффиксом `.1`. Каждый из существующих резервных файлов переименовывается с увеличением суффикса (`.1` становится `.2` и т.д.), а файл `.6` удаляется.13401341Разумеется, в этом примере размер файла журнала установлен слишком маленьким для наглядности. В реальности нужно установить *maxBytes* в подходящее значение.13421343## Использование альтернативных стилей форматирования13441345Когда журналирование было добавлено в стандартную библиотеку Python, единственным способом форматирования сообщений с переменным содержимым было использование %-форматирования. С тех пор в Python появились два новых подхода к форматированию: [`string.Template`](https://python-all.ru/3.12/library/string.html#string.Template) (добавлен в Python 2.4) и [`str.format()`](https://python-all.ru/3.12/library/stdtypes.html#str.format) (добавлен в Python 2.6).13461347Начиная с версии 3.2, модуль logging предоставляет улучшенную поддержку этих двух дополнительных стилей форматирования. Класс [`Formatter`](https://python-all.ru/3.12/library/logging.html#logging.Formatter) был расширен: добавлен дополнительный необязательный именованный параметр `style`. По умолчанию он равен `'%'`, но возможны также значения `'{'` и `'$'`, соответствующие двум другим стилям форматирования. Обратная совместимость сохраняется по умолчанию (как и следовало ожидать), но при явном указании параметра style появляется возможность задавать строки формата, работающие с [`str.format()`](https://python-all.ru/3.12/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.12/library/string.html#string.Template). Вот пример сеанса работы в консоли, демонстрирующий возможности:13481349```pycon1350>>> import logging1351>>> root = logging.getLogger()1352>>> root.setLevel(logging.DEBUG)1353>>> handler = logging.StreamHandler()1354>>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}',1355... style='{')1356>>> handler.setFormatter(bf)1357>>> root.addHandler(handler)1358>>> logger = logging.getLogger('foo.bar')1359>>> logger.debug('This is a DEBUG message')13602010-10-28 15:11:55,341 foo.bar DEBUG This is a DEBUG message1361>>> logger.critical('This is a CRITICAL message')13622010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message1363>>> df = logging.Formatter('$asctime $name ${levelname} $message',1364... style='$')1365>>> handler.setFormatter(df)1366>>> logger.debug('This is a DEBUG message')13672010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message1368>>> logger.critical('This is a CRITICAL message')13692010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message1370>>>1371```13721373Обратите внимание: форматирование сообщений журнала для конечного вывода в файлы совершенно не зависит от того, как конструируется отдельное сообщение. Оно по-прежнему может использовать %-форматирование, как показано ниже:13741375```python1376>>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')13772010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message1378>>>1379```13801381Вызовы функций журналирования (`logger.debug()`, `logger.info()` и т.д.) принимают только позиционные параметры для самого сообщения журнала; именованные параметры используются только для определения параметров обработки вызова (например, именованный параметр `exc_info` указывает, что нужно записать информацию о трассировке стека, или именованный параметр `extra` – добавить дополнительный контекст в журнал). Поэтому невозможно напрямую использовать синтаксис [`str.format()`](https://python-all.ru/3.12/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.12/library/string.html#string.Template) при вызовах, поскольку внутри пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Изменить это без нарушения обратной совместимости нельзя, так как все существующие вызовы logging в существующем коде используют %-формат строк.13821383Однако существует способ использовать {}- и $-форматирование для построения отдельных сообщений журнала. Напомним, что в качестве строки формата сообщения можно использовать произвольный объект, и пакет logging вызовет у этого объекта `str()` для получения фактической строки формата. Рассмотрим следующие два класса:13841385```python1386class BraceMessage:1387 def __init__(self, fmt, /, *args, **kwargs):1388 self.fmt = fmt1389 self.args = args1390 self.kwargs = kwargs13911392 def __str__(self):1393 return self.fmt.format(*self.args, **self.kwargs)13941395class DollarMessage:1396 def __init__(self, fmt, /, **kwargs):1397 self.fmt = fmt1398 self.kwargs = kwargs13991400 def __str__(self):1401 from string import Template1402 return Template(self.fmt).substitute(**self.kwargs)1403```14041405Любой из этих классов можно использовать вместо строки формата, чтобы разрешить применение {}- или $-форматирования для построения фактической части «message», которая появляется в отформатированном выводе журнала вместо «%(message)s», «{message}» или «$message». Это немного громоздко – использовать имена классов каждый раз при журналировании, но вполне приемлемо, если применить псевдоним, например \_\_ (двойное подчеркивание – не путать с \_, одинарным подчеркиванием, используемым как синоним/псевдоним для [`gettext.gettext()`](https://python-all.ru/3.12/library/gettext.html#gettext.gettext) или его аналогов).14061407Вышеуказанные классы не входят в состав Python, но их легко скопировать и вставить в свой код. Их можно использовать следующим образом (предполагая, что они объявлены в модуле с именем `wherever`):14081409```pycon1410>>> from wherever import BraceMessage as __1411>>> print(__('Message with {0} {name}', 2, name='placeholders'))1412Message with 2 placeholders1413>>> class Point: pass1414...1415>>> p = Point()1416>>> p.x = 0.51417>>> p.y = 0.51418>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})',1419... point=p))1420Message with coordinates: (0.50, 0.50)1421>>> from wherever import DollarMessage as __1422>>> print(__('Message with $num $what', num=2, what='placeholders'))1423Message with 2 placeholders1424>>>1425```14261427Хотя в приведённых выше примерах используется `print()` для демонстрации работы форматирования, в реальности для ведения журнала с помощью этого подхода следует использовать `logger.debug()` или аналогичную функцию.14281429Стоит отметить, что этот подход не приводит к существенному снижению производительности: собственно форматирование происходит не в момент вызова журналирования, а когда (и если) сообщение действительно должно быть выведено в журнал обработчиком. Так что единственная необычная деталь, которая может вызвать затруднение, – это то, что круглые скобки охватывают строку формата вместе с аргументами, а не только строку формата. Это объясняется тем, что запись \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов `XXXMessage`.14301431Если хотите, можно использовать [`LoggerAdapter`](https://python-all.ru/3.12/library/logging.html#logging.LoggerAdapter) для достижения аналогичного эффекта, как в следующем примере:14321433```python1434import logging14351436class Message:1437 def __init__(self, fmt, args):1438 self.fmt = fmt1439 self.args = args14401441 def __str__(self):1442 return self.fmt.format(*self.args)14431444class StyleAdapter(logging.LoggerAdapter):1445 def log(self, level, msg, /, *args, stacklevel=1, **kwargs):1446 if self.isEnabledFor(level):1447 msg, kwargs = self.process(msg, kwargs)1448 self.logger.log(level, Message(msg, args), **kwargs,1449 stacklevel=stacklevel+1)14501451logger = StyleAdapter(logging.getLogger(__name__))14521453def main():1454 logger.debug('Hello, {}', 'world!')14551456if __name__ == '__main__':1457 logging.basicConfig(level=logging.DEBUG)1458 main()1459```14601461Приведённый выше сценарий должен записать в журнал сообщение `Hello, world!` при запуске с Python 3.8 или новее.14621463## Настройка `LogRecord`14641465Каждое событие журналирования представлено экземпляром [`LogRecord`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord). Когда событие регистрируется и не отфильтровывается по уровню регистратора, создаётся [`LogRecord`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord), заполняется информацией о событии и затем передаётся обработчикам для этого регистратора (и его предков, вплоть до регистратора, в котором дальнейшее распространение по иерархии отключено). До Python 3.2 было только два места, где выполнялось это создание:14661467- [`Logger.makeRecord()`](https://python-all.ru/3.12/library/logging.html#logging.Logger.makeRecord), который вызывается в обычном процессе регистрации события. Он напрямую вызывал [`LogRecord`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord) для создания экземпляра.1468- [`makeLogRecord()`](https://python-all.ru/3.12/library/logging.html#logging.makeLogRecord), которая вызывается со словарем, содержащим атрибуты для добавления в LogRecord. Обычно она вызывается, когда подходящий словарь был получен по сети (например, в виде pickle через [`SocketHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.SocketHandler) или в формате JSON через [`HTTPHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.HTTPHandler)).14691470Обычно это означало, что если требуется выполнить какие-либо специальные действия с [`LogRecord`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord), приходилось делать одно из следующего.14711472- Создать собственный подкласс [`Logger`](https://python-all.ru/3.12/library/logging.html#logging.Logger), который переопределяет [`Logger.makeRecord()`](https://python-all.ru/3.12/library/logging.html#logging.Logger.makeRecord), и установить его с помощью [`setLoggerClass()`](https://python-all.ru/3.12/library/logging.html#logging.setLoggerClass) до того, как будут созданы какие-либо логгеры, которые вас интересуют.1473- Добавить [`Filter`](https://python-all.ru/3.12/library/logging.html#logging.Filter) к логгеру или обработчику, который выполняет необходимые специальные манипуляции при вызове его метода [`filter()`](https://python-all.ru/3.12/library/logging.html#logging.Filter.filter).14741475Первый подход был бы несколько громоздким в сценарии, где (скажем) несколько разных библиотек хотели бы делать разные вещи. Каждая попыталась бы установить свой собственный подкласс [`Logger`](https://python-all.ru/3.12/library/logging.html#logging.Logger), и та, которая сделала это последней, победила бы.14761477Второй подход достаточно хорошо работает во многих случаях, но не позволяет, например, использовать специализированный подкласс [`LogRecord`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord). Разработчики библиотек могут установить подходящий фильтр на своих логгерах, но им приходилось бы помнить об этом каждый раз, когда они добавляют новый логгер (что они делают, просто добавляя новые пакеты или модули и выполняя14781479```python1480logger = logging.getLogger(__name__)1481```14821483на уровне модуля). Вероятно, это одна из тех вещей, о которых нужно помнить. Разработчики также могли бы добавить фильтр к [`NullHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.NullHandler), прикрепленному к их корневому логгеру, но он не будет вызываться, если разработчик приложения прикрепит обработчик к логгеру библиотеки нижнего уровня – так что вывод от этого обработчика не будет отражать намерений разработчика библиотеки.14841485В Python 3.2 и новее создание [`LogRecord`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord) осуществляется через фабрику, которую можно указать. Фабрика – это просто вызываемый объект, который можно установить с помощью [`setLogRecordFactory()`](https://python-all.ru/3.12/library/logging.html#logging.setLogRecordFactory) и запросить с помощью [`getLogRecordFactory()`](https://python-all.ru/3.12/library/logging.html#logging.getLogRecordFactory). Фабрика вызывается с той же сигнатурой, что и конструктор [`LogRecord`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord), поскольку [`LogRecord`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord) является значением по умолчанию для фабрики.14861487Этот подход позволяет пользовательской фабрике контролировать все аспекты создания LogRecord. Например, можно вернуть подкласс или просто добавить несколько дополнительных атрибутов к записи после ее создания, используя шаблон, подобный следующему:14881489```python1490old_factory = logging.getLogRecordFactory()14911492def record_factory(*args, **kwargs):1493 record = old_factory(*args, **kwargs)1494 record.custom_attribute = 0xdecafbad1495 return record14961497logging.setLogRecordFactory(record_factory)1498```14991500Этот шаблон позволяет разным библиотекам объединять фабрики в цепочку, и пока они не перезаписывают атрибуты друг друга или случайно не перезаписывают стандартные атрибуты, никаких сюрпризов быть не должно. Однако следует иметь в виду, что каждое звено цепочки добавляет накладные расходы во время выполнения ко всем операциям логирования, и эту технику следует использовать только тогда, когда использование [`Filter`](https://python-all.ru/3.12/library/logging.html#logging.Filter) не дает желаемого результата.15011502## Создание подклассов QueueHandler и QueueListener – пример с ZeroMQ15031504### Подкласс `QueueHandler`15051506Можно использовать подкласс [`QueueHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.QueueHandler) для отправки сообщений в очереди других типов, например, в сокет ZeroMQ «publish». В приведенном ниже примере сокет создается отдельно и передается обработчику (в качестве его «очереди»):15071508```python1509import zmq # с использованием pyzmq, привязки Python к ZeroMQ1510import json # для переносимой сериализации записей15111512ctx = zmq.Context()1513sock = zmq.Socket(ctx, zmq.PUB) # или zmq.PUSH, или другое подходящее значение1514sock.bind('tcp://*:5556') # или где угодно15151516class ZeroMQSocketHandler(QueueHandler):1517 def enqueue(self, record):1518 self.queue.send_json(record.__dict__)15191520handler = ZeroMQSocketHandler(sock)1521```15221523Конечно, есть и другие способы организации этого, например, передача данных, необходимых обработчику для создания сокета:15241525```python1526class ZeroMQSocketHandler(QueueHandler):1527 def __init__(self, uri, socktype=zmq.PUB, ctx=None):1528 self.ctx = ctx or zmq.Context()1529 socket = zmq.Socket(self.ctx, socktype)1530 socket.bind(uri)1531 super().__init__(socket)15321533 def enqueue(self, record):1534 self.queue.send_json(record.__dict__)15351536 def close(self):1537 self.queue.close()1538```15391540### Подкласс `QueueListener`15411542Можно также создать подкласс [`QueueListener`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.QueueListener) для получения сообщений из очередей других типов, например, из сокета ZeroMQ «subscribe». Вот пример:15431544```python1545class ZeroMQSocketListener(QueueListener):1546 def __init__(self, uri, /, *handlers, **kwargs):1547 self.ctx = kwargs.get('ctx') or zmq.Context()1548 socket = zmq.Socket(self.ctx, zmq.SUB)1549 socket.setsockopt_string(zmq.SUBSCRIBE, '') # подписаться на всё1550 socket.connect(uri)1551 super().__init__(socket, *handlers, **kwargs)15521553 def dequeue(self):1554 msg = self.queue.recv_json()1555 return logging.makeLogRecord(msg)1556```15571558## Создание подклассов QueueHandler и QueueListener – пример с `pynng`15591560Подобно предыдущему разделу, можно реализовать прослушиватель и обработчик с помощью [pynng](https://python-all.ru/3.12/howto/logging-cookbook.html), который является привязкой Python к [NNG](https://python-all.ru/3.12/howto/logging-cookbook.html), позиционируемой как духовный преемник ZeroMQ. Следующие фрагменты кода иллюстрируют это – их можно протестировать в среде, где установлен `pynng`. Для разнообразия сначала приводим прослушиватель.15611562### Подкласс `QueueListener`15631564```python1565# listener.py1566import json1567import logging1568import logging.handlers15691570import pynng15711572DEFAULT_ADDR = "tcp://localhost:13232"15731574interrupted = False15751576class NNGSocketListener(logging.handlers.QueueListener):15771578 def __init__(self, uri, /, *handlers, **kwargs):1579 # Установить тайм-аут для возможности прерывания и открыть1580 # сокет подписчика1581 socket = pynng.Sub0(listen=uri, recv_timeout=500)1582 # Подписка b'' соответствует всем темам1583 topics = kwargs.pop('topics', None) or b''1584 socket.subscribe(topics)1585 # Используем сокет как очередь1586 super().__init__(socket, *handlers, **kwargs)15871588 def dequeue(self, block):1589 data = None1590 # Продолжать цикл, пока не прерван и не получены данные через1591 # сокет1592 while not interrupted:1593 try:1594 data = self.queue.recv(block=block)1595 break1596 except pynng.Timeout:1597 pass1598 except pynng.Closed: # иногда происходит при нажатии Ctrl-C1599 break1600 if data is None:1601 return None1602 # Получить событие журнала, отправленное издателем1603 event = json.loads(data.decode('utf-8'))1604 return logging.makeLogRecord(event)16051606 def enqueue_sentinel(self):1607 # Не используется в этой реализации, так как сокет на самом деле не является1608 # очередь1609 pass16101611logging.getLogger('pynng').propagate = False1612listener = NNGSocketListener(DEFAULT_ADDR, logging.StreamHandler(), topics=b'')1613listener.start()1614print('Press Ctrl-C to stop.')1615try:1616 while True:1617 pass1618except KeyboardInterrupt:1619 interrupted = True1620finally:1621 listener.stop()1622```16231624### Подкласс `QueueHandler`16251626```python1627# sender.py1628import json1629import logging1630import logging.handlers1631import time1632import random16331634import pynng16351636DEFAULT_ADDR = "tcp://localhost:13232"16371638class NNGSocketHandler(logging.handlers.QueueHandler):16391640 def __init__(self, uri):1641 socket = pynng.Pub0(dial=uri, send_timeout=500)1642 super().__init__(socket)16431644 def enqueue(self, record):1645 # Отправить запись в виде JSON с кодировкой UTF-81646 d = dict(record.__dict__)1647 data = json.dumps(d)1648 self.queue.send(data.encode('utf-8'))16491650 def close(self):1651 self.queue.close()16521653logging.getLogger('pynng').propagate = False1654handler = NNGSocketHandler(DEFAULT_ADDR)1655# Убедиться, что идентификатор процесса присутствует в выводе1656logging.basicConfig(level=logging.DEBUG,1657 handlers=[logging.StreamHandler(), handler],1658 format='%(levelname)-8s %(name)10s %(process)6s %(message)s')1659levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1660 logging.CRITICAL)1661logger_names = ('myapp', 'myapp.lib1', 'myapp.lib2')1662msgno = 11663while True:1664 # Просто случайным образом выбирать несколько регистраторов и уровней и вести запись1665 level = random.choice(levels)1666 logger = logging.getLogger(random.choice(logger_names))1667 logger.log(level, 'Message no. %5d' % msgno)1668 msgno += 11669 delay = random.random() * 2 + 0.51670 time.sleep(delay)1671```16721673Можно выполнить два указанных выше фрагмента в отдельных командных оболочках. Если запустить прослушиватель в одной оболочке, а отправителя – в двух отдельных оболочках, должно получиться что-то вроде следующего. В первой оболочке отправителя:16741675```console1676$ python sender.py1677DEBUG myapp 613 Message no. 11678WARNING myapp.lib2 613 Message no. 21679CRITICAL myapp.lib2 613 Message no. 31680WARNING myapp.lib2 613 Message no. 41681CRITICAL myapp.lib1 613 Message no. 51682DEBUG myapp 613 Message no. 61683CRITICAL myapp.lib1 613 Message no. 71684INFO myapp.lib1 613 Message no. 81685(and so on)1686```16871688Во второй оболочке отправителя:16891690```console1691$ python sender.py1692INFO myapp.lib2 657 Message no. 11693CRITICAL myapp.lib2 657 Message no. 21694CRITICAL myapp 657 Message no. 31695CRITICAL myapp.lib1 657 Message no. 41696INFO myapp.lib1 657 Message no. 51697WARNING myapp.lib2 657 Message no. 61698CRITICAL myapp 657 Message no. 71699DEBUG myapp.lib1 657 Message no. 81700(and so on)1701```17021703В оболочке прослушивателя:17041705```console1706$ python listener.py1707Press Ctrl-C to stop.1708DEBUG myapp 613 Message no. 11709WARNING myapp.lib2 613 Message no. 21710INFO myapp.lib2 657 Message no. 11711CRITICAL myapp.lib2 613 Message no. 31712CRITICAL myapp.lib2 657 Message no. 21713CRITICAL myapp 657 Message no. 31714WARNING myapp.lib2 613 Message no. 41715CRITICAL myapp.lib1 613 Message no. 51716CRITICAL myapp.lib1 657 Message no. 41717INFO myapp.lib1 657 Message no. 51718DEBUG myapp 613 Message no. 61719WARNING myapp.lib2 657 Message no. 61720CRITICAL myapp 657 Message no. 71721CRITICAL myapp.lib1 613 Message no. 71722INFO myapp.lib1 613 Message no. 81723DEBUG myapp.lib1 657 Message no. 81724(and so on)1725```17261727Как видно, записи журнала от двух процессов-отправителей перемежаются в выводе прослушивателя.17281729## Пример конфигурации на основе словаря17301731Ниже приведен пример словаря конфигурации логирования – он взят из [документации проекта Django](https://python-all.ru/3.12/howto/logging-cookbook.html). Этот словарь передается в [`dictConfig()`](https://python-all.ru/3.12/library/logging.config.html#logging.config.dictConfig) для применения конфигурации:17321733```python1734LOGGING = {1735 'version': 1,1736 'disable_existing_loggers': False,1737 'formatters': {1738 'verbose': {1739 'format': '{levelname} {asctime} {module} {process:d} {thread:d} {message}',1740 'style': '{',1741 },1742 'simple': {1743 'format': '{levelname} {message}',1744 'style': '{',1745 },1746 },1747 'filters': {1748 'special': {1749 '()': 'project.logging.SpecialFilter',1750 'foo': 'bar',1751 },1752 },1753 'handlers': {1754 'console': {1755 'level': 'INFO',1756 'class': 'logging.StreamHandler',1757 'formatter': 'simple',1758 },1759 'mail_admins': {1760 'level': 'ERROR',1761 'class': 'django.utils.log.AdminEmailHandler',1762 'filters': ['special']1763 }1764 },1765 'loggers': {1766 'django': {1767 'handlers': ['console'],1768 'propagate': True,1769 },1770 'django.request': {1771 'handlers': ['mail_admins'],1772 'level': 'ERROR',1773 'propagate': False,1774 },1775 'myproject.custom': {1776 'handlers': ['console', 'mail_admins'],1777 'level': 'INFO',1778 'filters': ['special']1779 }1780 }1781}1782```17831784Для получения дополнительной информации об этой конфигурации можно обратиться к [соответствующему разделу](https://python-all.ru/3.12/howto/logging-cookbook.html) документации Django.17851786## Использование ротатора и средства именования для настройки обработки ротации журналов17871788Пример того, как можно определить именователя и ротатора, приведен в следующем исполняемом скрипте, который показывает сжатие gzip файла журнала:17891790```python1791import gzip1792import logging1793import logging.handlers1794import os1795import shutil17961797def namer(name):1798 return name + ".gz"17991800def rotator(source, dest):1801 with open(source, 'rb') as f_in:1802 with gzip.open(dest, 'wb') as f_out:1803 shutil.copyfileobj(f_in, f_out)1804 os.remove(source)18051806rh = logging.handlers.RotatingFileHandler('rotated.log', maxBytes=128, backupCount=5)1807rh.rotator = rotator1808rh.namer = namer18091810root = logging.getLogger()1811root.setLevel(logging.INFO)1812root.addHandler(rh)1813f = logging.Formatter('%(asctime)s %(message)s')1814rh.setFormatter(f)1815for i in range(1000):1816 root.info(f'Message no. {i + 1}')1817```18181819После запуска будут созданы шесть новых файлов, пять из которых сжаты:18201821```console1822$ ls rotated.log*1823rotated.log rotated.log.2.gz rotated.log.4.gz1824rotated.log.1.gz rotated.log.3.gz rotated.log.5.gz1825$ zcat rotated.log.1.gz18262023-01-20 02:28:17,767 Message no. 99618272023-01-20 02:28:17,767 Message no. 99718282023-01-20 02:28:17,767 Message no. 9981829```18301831## Более сложный пример с многопроцессностью18321833Следующий рабочий пример показывает, как можно использовать логирование с многопроцессностью с помощью файлов конфигурации. Конфигурации довольно просты, но служат иллюстрацией того, как можно реализовать более сложные в реальном сценарии многопроцессной обработки.18341835В примере главный процесс порождает процесс-слушатель и несколько рабочих процессов. Каждый из главного процесса, слушателя и рабочих имеет три отдельные конфигурации (все рабочие используют одну и ту же конфигурацию). Видно ведение журнала в главном процессе, как рабочие пишут в QueueHandler, а слушатель реализует QueueListener и более сложную конфигурацию ведения журнала, и организует отправку событий, полученных через очередь, обработчикам, указанным в конфигурации. Обратите внимание, что эти конфигурации чисто иллюстративные, но этот пример можно адаптировать под свой сценарий.18361837Вот скрипт – строки документации и комментарии, надеюсь, поясняют, как он работает:18381839```python1840import logging1841import logging.config1842import logging.handlers1843from multiprocessing import Process, Queue, Event, current_process1844import os1845import random1846import time18471848class MyHandler:1849 """1850 Простой обработчик для событий логирования. Он выполняется в процессе-слушателе и1851 распределяет события по логгерам на основе имени в полученной записи,1852 которые затем передаются системой логирования обработчикам,1853 настроенным для этих логгеров.1854 """18551856 def handle(self, record):1857 if record.name == "root":1858 logger = logging.getLogger()1859 else:1860 logger = logging.getLogger(record.name)18611862 if logger.isEnabledFor(record.levelno):1863 # Имя процесса преобразуется только для того, чтобы показать, что это слушатель1864 # выполняет логирование в файлы и консоль.1865 record.processName = '%s (for %s)' % (current_process().name, record.processName)1866 logger.handle(record)18671868def listener_process(q, stop_event, config):1869 """1870 Это можно было бы сделать в главном процессе, но сделано в отдельном1871 процессе для наглядности.18721873 Это инициализирует логирование согласно указанной конфигурации1874 запускает слушатель и ожидает сигнала от главного процесса о завершении1875 через событие. Затем слушатель останавливается, и процесс завершается.1876 """1877 logging.config.dictConfig(config)1878 listener = logging.handlers.QueueListener(q, MyHandler())1879 listener.start()1880 if os.name == 'posix':1881 # В POSIX логгер setup уже был настроен в1882 # родительском процессе, но должен был быть отключён после вызова1883 # dictConfig.1884 # В Windows, поскольку fork не используется, логгер setup не будет1885 # существовать в дочернем процессе, поэтому он будет создан, и сообщение1886 # появится – отсюда и конструкция "if posix".1887 logger = logging.getLogger('setup')1888 logger.critical('Should not appear, because of disabled logger ...')1889 stop_event.wait()1890 listener.stop()18911892def worker_process(config):1893 """1894 Некоторое количество таких процессов порождается для иллюстрации. На1895 практике это могла бы быть разнородная группа процессов, а не1896 идентичные друг другу.18971898 Это инициализирует логирование согласно указанной конфигурации1899 и записывает сотню сообщений со случайными уровнями в случайно выбранные1900 логгеры.19011902 Добавлена небольшая задержка, чтобы дать другим процессам шанс выполниться. Это1903 не является строго необходимым, но позволяет немного перемешать вывод от разных1904 процессов больше, чем если бы её не было.1905 """1906 logging.config.dictConfig(config)1907 levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1908 logging.CRITICAL]1909 loggers = ['foo', 'foo.bar', 'foo.bar.baz',1910 'spam', 'spam.ham', 'spam.ham.eggs']1911 if os.name == 'posix':1912 # В POSIX логгер setup уже был настроен в1913 # родительском процессе, но должен был быть отключён после вызова1914 # dictConfig.1915 # В Windows, поскольку fork не используется, логгер setup не будет1916 # существовать в дочернем процессе, поэтому он будет создан, и сообщение1917 # появится – отсюда и конструкция "if posix".1918 logger = logging.getLogger('setup')1919 logger.critical('Should not appear, because of disabled logger ...')1920 for i in range(100):1921 lvl = random.choice(levels)1922 logger = logging.getLogger(random.choice(loggers))1923 logger.log(lvl, 'Message no. %d', i)1924 time.sleep(0.01)19251926def main():1927 q = Queue()1928 # Главный процесс получает простую конфигурацию, которая выводит информацию в консоль.1929 config_initial = {1930 'version': 1,1931 'handlers': {1932 'console': {1933 'class': 'logging.StreamHandler',1934 'level': 'INFO'1935 }1936 },1937 'root': {1938 'handlers': ['console'],1939 'level': 'DEBUG'1940 }1941 }1942 # Конфигурация рабочего процесса представляет собой QueueHandler, прикреплённый к1943 # корневому логгеру, что позволяет отправлять все сообщения в очередь.1944 # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1945 # родительском процессе. Это необходимо в POSIX, потому что логгер будет1946 # присутствовать в дочернем процессе после вызова fork().1947 config_worker = {1948 'version': 1,1949 'disable_existing_loggers': True,1950 'handlers': {1951 'queue': {1952 'class': 'logging.handlers.QueueHandler',1953 'queue': q1954 }1955 },1956 'root': {1957 'handlers': ['queue'],1958 'level': 'DEBUG'1959 }1960 }1961 # Конфигурация процесса-слушателя показывает, что вся гибкость1962 # конфигурации логирования доступна для отправки событий обработчикам так, как1963 # требуется.1964 # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1965 # родительском процессе. Это необходимо в POSIX, потому что логгер будет1966 # присутствовать в дочернем процессе после вызова fork().1967 config_listener = {1968 'version': 1,1969 'disable_existing_loggers': True,1970 'formatters': {1971 'detailed': {1972 'class': 'logging.Formatter',1973 'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1974 },1975 'simple': {1976 'class': 'logging.Formatter',1977 'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1978 }1979 },1980 'handlers': {1981 'console': {1982 'class': 'logging.StreamHandler',1983 'formatter': 'simple',1984 'level': 'INFO'1985 },1986 'file': {1987 'class': 'logging.FileHandler',1988 'filename': 'mplog.log',1989 'mode': 'w',1990 'formatter': 'detailed'1991 },1992 'foofile': {1993 'class': 'logging.FileHandler',1994 'filename': 'mplog-foo.log',1995 'mode': 'w',1996 'formatter': 'detailed'1997 },1998 'errors': {1999 'class': 'logging.FileHandler',2000 'filename': 'mplog-errors.log',2001 'mode': 'w',2002 'formatter': 'detailed',2003 'level': 'ERROR'2004 }2005 },2006 'loggers': {2007 'foo': {2008 'handlers': ['foofile']2009 }2010 },2011 'root': {2012 'handlers': ['console', 'file', 'errors'],2013 'level': 'DEBUG'2014 }2015 }2016 # Записываем несколько начальных событий, просто чтобы показать, что логирование в родительском процессе работает2017 # нормально.2018 logging.config.dictConfig(config_initial)2019 logger = logging.getLogger('setup')2020 logger.info('About to create workers ...')2021 workers = []2022 for i in range(5):2023 wp = Process(target=worker_process, name='worker %d' % (i + 1),2024 args=(config_worker,))2025 workers.append(wp)2026 wp.start()2027 logger.info('Started worker: %s', wp.name)2028 logger.info('About to create listener ...')2029 stop_event = Event()2030 lp = Process(target=listener_process, name='listener',2031 args=(q, stop_event, config_listener))2032 lp.start()2033 logger.info('Started listener')2034 # Теперь ожидаем завершения работы рабочих процессов.2035 for wp in workers:2036 wp.join()2037 # Все рабочие процессы завершены, теперь можно остановить прослушивание.2038 # Логирование в родительском процессе всё ещё работает нормально.2039 logger.info('Telling listener to stop ...')2040 stop_event.set()2041 lp.join()2042 logger.info('All done.')20432044if __name__ == '__main__':2045 main()2046```20472048## Вставка BOM в сообщения, отправляемые в SysLogHandler20492050[**RFC 5424**](https://python-all.ru/3.12/howto/logging-cookbook.html) требует, чтобы сообщение Unicode отправлялось демону syslog в виде набора байтов, имеющего следующую структуру: необязательный чисто ASCII-компонент, за которым следует метка порядка байтов UTF-8 (BOM), а затем Unicode, закодированный в UTF-8. (См. [**соответствующий раздел спецификации**](https://python-all.ru/3.12/howto/logging-cookbook.html).)20512052В Python 3.1 в [`SysLogHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.SysLogHandler) был добавлен код для вставки BOM в сообщение, но, к сожалению, он был реализован некорректно: BOM появлялся в начале сообщения и, следовательно, не допускал наличия чисто ASCII-компонента перед ним.20532054Поскольку такое поведение ошибочно, некорректный код вставки BOM удаляется из Python 3.2.4 и более поздних версий. Однако он не заменяется, и если требуется создавать сообщения, соответствующие [**RFC 5424**](https://python-all.ru/3.12/howto/logging-cookbook.html), которые включают BOM, необязательную чисто ASCII-последовательность перед ним и произвольный Unicode после него, закодированный в UTF-8, то необходимо сделать следующее:205520561. Необходимо присоединить экземпляр [`Formatter`](https://python-all.ru/3.12/library/logging.html#logging.Formatter) к экземпляру [`SysLogHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.SysLogHandler), указав строку формата, например:20572058 ```python2059 'ASCII section\ufeffUnicode section'2060 ```20612062 Кодовая точка Unicode U+FEFF при кодировании в UTF-8 будет представлена как метка порядка байтов UTF-8 – строка байтов `b'\xef\xbb\xbf'`.20632. ASCII-часть следует заменить на любые подходящие заполнители, но необходимо следить, чтобы данные, которые появляются там после подстановки, всегда были в ASCII (таким образом, они останутся без изменений после кодирования UTF-8).20643. Unicode-часть следует заменить на любые заполнители; если данные после подстановки содержат символы за пределами диапазона ASCII, это нормально – они будут закодированы в UTF-8.20652066Отформатированное сообщение *будет* закодировано в UTF-8 с помощью `SysLogHandler`. Если следовать приведённым выше правилам, можно создавать сообщения, соответствующие [**RFC 5424**](https://python-all.ru/3.12/howto/logging-cookbook.html). Если этого не делать, модуль logging может не жаловаться, но сообщения не будут соответствовать RFC 5424, и демон syslog может выражать недовольство.20672068## Реализация структурированного ведения журнала20692070Хотя большинство сообщений журнала предназначены для чтения человеком и поэтому не предназначены для машинного разбора, могут возникнуть ситуации, когда требуется выводить сообщения в структурированном формате, *который* может быть разобран программой (без необходимости в сложных регулярных выражениях). Это легко достигается с помощью пакета logging. Существует несколько способов, но ниже приведён простой подход, использующий JSON для сериализации события в машиночитаемом виде.20712072```python2073import json2074import logging20752076class StructuredMessage:2077 def __init__(self, message, /, **kwargs):2078 self.message = message2079 self.kwargs = kwargs20802081 def __str__(self):2082 return '%s >>> %s' % (self.message, json.dumps(self.kwargs))20832084_ = StructuredMessage # необязательно, для улучшения читаемости20852086logging.basicConfig(level=logging.INFO, format='%(message)s')2087logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))2088```20892090Если запустить приведённый выше скрипт, он выведет:20912092```text2093message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}2094```20952096Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.20972098Если требуется более специализированная обработка, можно использовать пользовательский кодировщик JSON, как в следующем полном примере:20992100```python2101import json2102import logging21032104class Encoder(json.JSONEncoder):2105 def default(self, o):2106 if isinstance(o, set):2107 return tuple(o)2108 elif isinstance(o, str):2109 return o.encode('unicode_escape').decode('ascii')2110 return super().default(o)21112112class StructuredMessage:2113 def __init__(self, message, /, **kwargs):2114 self.message = message2115 self.kwargs = kwargs21162117 def __str__(self):2118 s = Encoder().encode(self.kwargs)2119 return '%s >>> %s' % (self.message, s)21202121_ = StructuredMessage # необязательно, для улучшения читаемости21222123def main():2124 logging.basicConfig(level=logging.INFO, format='%(message)s')2125 logging.info(_('message 1', set_value={1, 2, 3}, snowman='\u2603'))21262127if __name__ == '__main__':2128 main()2129```21302131При запуске приведённого выше скрипта он выведет:21322133```text2134message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}2135```21362137Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.21382139## Настройка обработчиков с помощью [`dictConfig()`](https://python-all.ru/3.12/library/logging.config.html#logging.config.dictConfig)21402141Иногда требуется настроить обработчики логирования особым образом, и при использовании [`dictConfig()`](https://python-all.ru/3.12/library/logging.config.html#logging.config.dictConfig) это можно сделать без создания подклассов. Например, может потребоваться установить владельца файла журнала. В POSIX это легко сделать с помощью [`shutil.chown()`](https://python-all.ru/3.12/library/shutil.html#shutil.chown), но файловые обработчики в стандартной библиотеке не предоставляют встроенной поддержки. Можно настроить создание обработчика с помощью обычной функции, такой как:21422143```python2144def owned_file_handler(filename, mode='a', encoding=None, owner=None):2145 if owner:2146 if not os.path.exists(filename):2147 open(filename, 'a').close()2148 shutil.chown(filename, *owner)2149 return logging.FileHandler(filename, mode, encoding)2150```21512152Затем в конфигурации логирования, передаваемой в [`dictConfig()`](https://python-all.ru/3.12/library/logging.config.html#logging.config.dictConfig), можно указать, что обработчик должен быть создан вызовом этой функции:21532154```python2155LOGGING = {2156 'version': 1,2157 'disable_existing_loggers': False,2158 'formatters': {2159 'default': {2160 'format': '%(asctime)s %(levelname)s %(name)s %(message)s'2161 },2162 },2163 'handlers': {2164 'file':{2165 # Значения ниже извлекаются из этого словаря и2166 # используются для создания обработчика, установки его уровня и2167 # его форматтера.2168 '()': owned_file_handler,2169 'level':'DEBUG',2170 'formatter': 'default',2171 # Значения ниже передаются вызываемому объекту-создателю обработчика2172 # в качестве именованных аргументов.2173 'owner': ['pulse', 'pulse'],2174 'filename': 'chowntest.log',2175 'mode': 'w',2176 'encoding': 'utf-8',2177 },2178 },2179 'root': {2180 'handlers': ['file'],2181 'level': 'DEBUG',2182 },2183}2184```21852186В этом примере для иллюстрации права владения устанавливаются с использованием пользователя и группы `pulse`. Собирая всё вместе в рабочий скрипт, `chowntest.py`:21872188```python2189import logging, logging.config, os, shutil21902191def owned_file_handler(filename, mode='a', encoding=None, owner=None):2192 if owner:2193 if not os.path.exists(filename):2194 open(filename, 'a').close()2195 shutil.chown(filename, *owner)2196 return logging.FileHandler(filename, mode, encoding)21972198LOGGING = {2199 'version': 1,2200 'disable_existing_loggers': False,2201 'formatters': {2202 'default': {2203 'format': '%(asctime)s %(levelname)s %(name)s %(message)s'2204 },2205 },2206 'handlers': {2207 'file':{2208 # Значения ниже извлекаются из этого словаря и2209 # используются для создания обработчика, установки его уровня и2210 # его форматтера.2211 '()': owned_file_handler,2212 'level':'DEBUG',2213 'formatter': 'default',2214 # Значения ниже передаются вызываемому объекту-создателю обработчика2215 # в качестве именованных аргументов.2216 'owner': ['pulse', 'pulse'],2217 'filename': 'chowntest.log',2218 'mode': 'w',2219 'encoding': 'utf-8',2220 },2221 },2222 'root': {2223 'handlers': ['file'],2224 'level': 'DEBUG',2225 },2226}22272228logging.config.dictConfig(LOGGING)2229logger = logging.getLogger('mylogger')2230logger.debug('A debug message')2231```22322233Для запуска, вероятно, потребуется выполнить от имени `root`:22342235```console2236$ sudo python3.3 chowntest.py2237$ cat chowntest.log22382013-11-05 09:34:51,128 DEBUG mylogger A debug message2239$ ls -l chowntest.log2240-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log2241```22422243Обратите внимание, что в этом примере используется Python 3.3, потому что в нём появился [`shutil.chown()`](https://python-all.ru/3.12/library/shutil.html#shutil.chown). Этот подход должен работать с любой версией Python, поддерживающей [`dictConfig()`](https://python-all.ru/3.12/library/logging.config.html#logging.config.dictConfig) – а именно Python 2.7, 3.2 или новее. В версиях до 3.3 потребовалось бы реализовать фактическую смену владельца, например, с помощью [`os.chown()`](https://python-all.ru/3.12/library/os.html#os.chown).22442245На практике функция создания обработчика может находиться в служебном модуле где-нибудь в вашем проекте. Вместо строки в конфигурации:22462247```python2248'()': owned_file_handler,2249```22502251можно использовать, например:22522253```python2254'()': 'ext://project.util.owned_file_handler',2255```22562257где `project.util` можно заменить на фактическое имя пакета, в котором находится функция. В приведённом рабочем скрипте должно сработать использование `'ext://__main__.owned_file_handler'`. Здесь фактический вызываемый объект разрешается с помощью [`dictConfig()`](https://python-all.ru/3.12/library/logging.config.html#logging.config.dictConfig) из спецификации `ext://`.22582259Этот пример, надеюсь, также показывает, как можно реализовать другие типы изменений файлов – например, установку определённых битов разрешений POSIX – аналогичным образом, с помощью [`os.chmod()`](https://python-all.ru/3.12/library/os.html#os.chmod).22602261Разумеется, этот подход можно распространить и на другие типы обработчиков, помимо [`FileHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.FileHandler) – например, на один из вращающихся файловых обработчиков или на совершенно другой тип обработчика.22622263## Использование определённых стилей форматирования во всём приложении22642265В Python 3.2 у [`Formatter`](https://python-all.ru/3.12/library/logging.html#logging.Formatter) появился именованный параметр `style`, который, хотя по умолчанию для обратной совместимости он равен `%`, позволяет указать `{` или `$` для поддержки подходов к форматированию, поддерживаемых [`str.format()`](https://python-all.ru/3.12/library/stdtypes.html#str.format) и [`string.Template`](https://python-all.ru/3.12/library/string.html#string.Template). Обратите внимание, что это управляет форматированием сообщений журнала для окончательного вывода в журнал и совершенно не зависит от того, как конструируется отдельное сообщение журнала.22662267Вызовы логирования ([`debug()`](https://python-all.ru/3.12/library/logging.html#logging.Logger.debug), [`info()`](https://python-all.ru/3.12/library/logging.html#logging.Logger.info) и т.д.) принимают только позиционные параметры для самого сообщения журнала, а именованные параметры используются только для определения параметров обработки вызова (например, именованный параметр `exc_info` для указания, что нужно записывать информацию о трассировке, или именованный параметр `extra` для указания дополнительной контекстной информации, добавляемой в журнал). Таким образом, нельзя напрямую выполнять вызовы логирования с использованием синтаксиса [`str.format()`](https://python-all.ru/3.12/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.12/library/string.html#string.Template), потому что внутри пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Изменить это без нарушения обратной совместимости было бы невозможно, поскольку все существующие вызовы логирования в коде используют строки с %-форматированием.22682269Высказывались предложения связывать стили форматирования с конкретными регистраторами, но этот подход также сталкивается с проблемами обратной совместимости, поскольку любой существующий код может использовать данное имя регистратора и %-форматирование.22702271Чтобы логирование работало совместимо между любыми сторонними библиотеками и вашим кодом, решения о форматировании необходимо принимать на уровне отдельного вызова логирования. Это открывает несколько способов, которыми можно реализовать альтернативные стили форматирования.22722273### Использование фабрик LogRecord22742275В Python 3.2, вместе с упомянутыми выше изменениями [`Formatter`](https://python-all.ru/3.12/library/logging.html#logging.Formatter), пакет logging получил возможность позволять пользователям устанавливать свои собственные подклассы [`LogRecord`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord) с помощью функции [`setLogRecordFactory()`](https://python-all.ru/3.12/library/logging.html#logging.setLogRecordFactory). Вы можете использовать это, чтобы установить свой собственный подкласс [`LogRecord`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord), который делает правильные вещи, переопределяя метод [`getMessage()`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord.getMessage). В реализации базового класса этого метода происходит форматирование `msg % args`, и именно здесь можно подставить альтернативное форматирование; однако следует быть осторожным, чтобы поддерживать все стили форматирования и разрешить %-форматирование по умолчанию для обеспечения совместимости с другим кодом. Также следует позаботиться о вызове `str(self.msg)`, как это делает базовая реализация.22762277Обратитесь к справочной документации по [`setLogRecordFactory()`](https://python-all.ru/3.12/library/logging.html#logging.setLogRecordFactory) и [`LogRecord`](https://python-all.ru/3.12/library/logging.html#logging.LogRecord) для получения дополнительной информации.22782279### Использование пользовательских объектов сообщений22802281Есть еще один, возможно, более простой способ использовать {}- и $-форматирование для построения отдельных сообщений лога. Вы, возможно, помните (из раздела [Использование произвольных объектов в качестве сообщений](https://python-all.ru/3.12/howto/logging.html#arbitrary-object-messages)), что при логировании можно использовать произвольный объект в качестве строки формата сообщения, и пакет logging вызовет [`str()`](https://python-all.ru/3.12/library/stdtypes.html#str) для этого объекта, чтобы получить фактическую строку формата. Рассмотрим следующие два класса:22822283```python2284class BraceMessage:2285 def __init__(self, fmt, /, *args, **kwargs):2286 self.fmt = fmt2287 self.args = args2288 self.kwargs = kwargs22892290 def __str__(self):2291 return self.fmt.format(*self.args, **self.kwargs)22922293class DollarMessage:2294 def __init__(self, fmt, /, **kwargs):2295 self.fmt = fmt2296 self.kwargs = kwargs22972298 def __str__(self):2299 from string import Template2300 return Template(self.fmt).substitute(**self.kwargs)2301```23022303Любой из них можно использовать вместо строки формата, чтобы разрешить {}- или $-форматирование для построения фактической части «message», которая появляется в форматированном выводе лога вместо «%(message)s», «{message}» или «$message». Если вам кажется неудобным использовать имена классов каждый раз при логировании, вы можете сделать это более приятным, используя псевдоним, такой как `M` или `_` для сообщения (или, возможно, `__`, если вы используете `_` для локализации).23042305Примеры этого подхода приведены ниже. Во-первых, форматирование с помощью [`str.format()`](https://python-all.ru/3.12/library/stdtypes.html#str.format):23062307```python2308>>> __ = BraceMessage2309>>> print(__('Message with {0} {1}', 2, 'placeholders'))2310Message with 2 placeholders2311>>> class Point: pass2312...2313>>> p = Point()2314>>> p.x = 0.52315>>> p.y = 0.52316>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))2317Message with coordinates: (0.50, 0.50)2318```23192320Во-вторых, форматирование с помощью [`string.Template`](https://python-all.ru/3.12/library/string.html#string.Template):23212322```python2323>>> __ = DollarMessage2324>>> print(__('Message with $num $what', num=2, what='placeholders'))2325Message with 2 placeholders2326>>>2327```23282329Стоит отметить, что при таком подходе вы не платите значительных потерь производительности: фактическое форматирование происходит не при вызове логирования, а когда (и если) сообщение лога действительно должно быть выведено в лог обработчиком. Так что единственная необычная вещь, которая может вас сбить с толку, это то, что круглые скобки ставятся вокруг строки формата и аргументов, а не только вокруг строки формата. Это потому, что нотация \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов `XXXMessage`, показанных выше.23302331## Настройка фильтров с помощью [`dictConfig()`](https://python-all.ru/3.12/library/logging.config.html#logging.config.dictConfig)23322333*Можно* настраивать фильтры с помощью [`dictConfig()`](https://python-all.ru/3.12/library/logging.config.html#logging.config.dictConfig), хотя с первого взгляда может быть неочевидно, как это сделать (поэтому и дан этот рецепт). Поскольку [`Filter`](https://python-all.ru/3.12/library/logging.html#logging.Filter) – единственный класс фильтра, включенный в стандартную библиотеку, и вряд ли он удовлетворит многие требования (он присутствует только как базовый класс), вам, как правило, потребуется определить свой собственный подкласс [`Filter`](https://python-all.ru/3.12/library/logging.html#logging.Filter) с переопределенным методом [`filter()`](https://python-all.ru/3.12/library/logging.html#logging.Filter.filter). Для этого укажите ключ `()` в словаре конфигурации для фильтра, указав вызываемый объект, который будет использоваться для создания фильтра (класс – наиболее очевидный вариант, но вы можете предоставить любой вызываемый объект, возвращающий экземпляр [`Filter`](https://python-all.ru/3.12/library/logging.html#logging.Filter)). Вот полный пример:23342335```python2336import logging2337import logging.config2338import sys23392340class MyFilter(logging.Filter):2341 def __init__(self, param=None):2342 self.param = param23432344 def filter(self, record):2345 if self.param is None:2346 allow = True2347 else:2348 allow = self.param not in record.msg2349 if allow:2350 record.msg = 'changed: ' + record.msg2351 return allow23522353LOGGING = {2354 'version': 1,2355 'filters': {2356 'myfilter': {2357 '()': MyFilter,2358 'param': 'noshow',2359 }2360 },2361 'handlers': {2362 'console': {2363 'class': 'logging.StreamHandler',2364 'filters': ['myfilter']2365 }2366 },2367 'root': {2368 'level': 'DEBUG',2369 'handlers': ['console']2370 },2371}23722373if __name__ == '__main__':2374 logging.config.dictConfig(LOGGING)2375 logging.debug('hello')2376 logging.debug('hello - noshow')2377```23782379Этот пример показывает, как можно передавать конфигурационные данные вызываемому объекту, который создает экземпляр, в виде именованных параметров. При запуске приведенный выше скрипт выведет:23802381```text2382changed: hello2383```23842385что показывает, что фильтр работает в соответствии с настройками.23862387Несколько дополнительных моментов, на которые стоит обратить внимание:23882389- Если вы не можете сослаться на вызываемый объект напрямую в конфигурации (например, если он находится в другом модуле, и вы не можете импортировать его напрямую в том месте, где находится словарь конфигурации), вы можете использовать форму `ext://...`, как описано в разделе [Доступ к внешним объектам](https://python-all.ru/3.12/library/logging.config.html#logging-config-dict-externalobj). Например, в приведенном выше примере можно было использовать текст `'ext://__main__.MyFilter'` вместо `MyFilter`.2390- Помимо фильтров, этот метод также можно использовать для настройки пользовательских обработчиков и форматтеров. Смотрите раздел [Пользовательские объекты](https://python-all.ru/3.12/library/logging.config.html#logging-config-dict-userdef) для получения дополнительной информации о том, как logging поддерживает использование пользовательских объектов в своей конфигурации, а также см. другой рецепт из этой книги рецептов [Настройка обработчиков с помощью dictConfig()](https://python-all.ru/3.12/howto/logging-cookbook.html#custom-handlers) выше.23912392## Настраиваемое форматирование исключений23932394Могут возникнуть ситуации, когда вы захотите настроить форматирование исключений – для примера, предположим, вы хотите ровно одну строку на каждое событие лога, даже если присутствует информация об исключении. Вы можете сделать это с помощью пользовательского класса форматтера, как показано в следующем примере:23952396```python2397import logging23982399class OneLineExceptionFormatter(logging.Formatter):2400 def formatException(self, exc_info):2401 """2402 Форматировать исключение так, чтобы оно выводилось одной строкой.2403 """2404 result = super().formatException(exc_info)2405 return repr(result) # или форматировать одной строкой по своему усмотрению24062407 def format(self, record):2408 s = super().format(record)2409 if record.exc_text:2410 s = s.replace('\n', '') + '|'2411 return s24122413def configure_logging():2414 fh = logging.FileHandler('output.txt', 'w')2415 f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',2416 '%d/%m/%Y %H:%M:%S')2417 fh.setFormatter(f)2418 root = logging.getLogger()2419 root.setLevel(logging.DEBUG)2420 root.addHandler(fh)24212422def main():2423 configure_logging()2424 logging.info('Sample message')2425 try:2426 x = 1 / 02427 except ZeroDivisionError as e:2428 logging.exception('ZeroDivisionError: %s', e)24292430if __name__ == '__main__':2431 main()2432```24332434При запуске это создает файл ровно с двумя строками:24352436```text243728/01/2015 07:21:23|INFO|Sample message|243828/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'|2439```24402441Хотя описанный выше подход упрощен, он показывает путь к тому, как можно форматировать информацию об исключениях по своему вкусу. Модуль [`traceback`](https://python-all.ru/3.12/library/traceback.html#module-traceback) может быть полезен для более специализированных нужд.24422443## Озвучивание сообщений лога24442445Могут быть ситуации, когда желательно выводить сообщения лога в звуковом, а не визуальном формате. Это легко сделать, если в вашей системе доступна функция преобразования текста в речь (TTS), даже если у нее нет привязки к Python. Большинство TTS-систем имеют программу командной строки, которую можно запустить, и ее можно вызвать из обработчика с помощью [`subprocess`](https://python-all.ru/3.12/library/subprocess.html#module-subprocess). Здесь предполагается, что программы командной строки TTS не будут ожидать взаимодействия с пользователем или занимать много времени для завершения, и что частота сообщений лога не будет настолько высокой, чтобы перегружать пользователя сообщениями, и что допустимо проговаривать сообщения по одному, а не одновременно. В приведенном ниже примере реализации ожидается, пока одно сообщение не будет произнесено, прежде чем обрабатывать следующее, и это может заставить другие обработчики ждать. Вот короткий пример, демонстрирующий подход, который предполагает, что доступен TTS-пакет `espeak`:24462447```python2448import logging2449import subprocess2450import sys24512452class TTSHandler(logging.Handler):2453 def emit(self, record):2454 msg = self.format(record)2455 # Говорить медленно женским английским голосом.2456 cmd = ['espeak', '-s150', '-ven+f3', msg]2457 p = subprocess.Popen(cmd, stdout=subprocess.PIPE,2458 stderr=subprocess.STDOUT)2459 # дождаться завершения программы2460 p.communicate()24612462def configure_logging():2463 h = TTSHandler()2464 root = logging.getLogger()2465 root.addHandler(h)2466 # стандартный форматтер просто возвращает сообщение2467 root.setLevel(logging.DEBUG)24682469def main():2470 logging.info('Hello')2471 logging.debug('Goodbye')24722473if __name__ == '__main__':2474 configure_logging()2475 sys.exit(main())2476```24772478При запуске этот скрипт должен сказать «Hello», а затем «Goodbye» женским голосом.24792480Описанный выше подход, конечно, можно адаптировать для других TTS-систем и даже для других систем, которые могут обрабатывать сообщения через внешние программы, запускаемые из командной строки.24812482## Буферизация сообщений лога и условный вывод24832484Могут возникнуть ситуации, когда вы хотите записывать сообщения во временную область и выводить их только при наступлении определенного условия. Например, вы можете начать запись отладочных событий в функции, и если функция завершится без ошибок, вы не захотите засорять лог собранной отладочной информацией, но если возникнет ошибка, вы захотите вывести всю отладочную информацию вместе с ошибкой.24852486Вот пример, показывающий, как это можно сделать с помощью декоратора для ваших функций, где вы хотите, чтобы логирование вело себя таким образом. Он использует [`logging.handlers.MemoryHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.MemoryHandler), который позволяет буферизовать зарегистрированные события до наступления некоторого условия, после чего буферизованные события `flushed` – передаются другому обработчику (обработчику `target`) для обработки. По умолчанию `MemoryHandler` сбрасывается, когда его буфер заполняется или встречается событие, уровень которого больше или равен указанному порогу. Вы можете использовать этот рецепт с более специализированным подклассом `MemoryHandler`, если хотите настроить поведение сброса.24872488Пример скрипта содержит простую функцию `foo`, которая просто перебирает все уровни логирования, записывая в `sys.stderr` информацию о том, какой уровень будет использоваться, а затем регистрирует сообщение на этом уровне. Вы можете передать параметр в `foo`, который, если равен true, будет регистрировать на уровнях ERROR и CRITICAL – в противном случае он регистрирует только на уровнях DEBUG, INFO и WARNING.24892490Скрипт просто настраивает декорирование `foo` декоратором, который будет выполнять необходимое условное логирование. Декоратор принимает регистратор в качестве параметра и подключает обработчик памяти на время вызова декорированной функции. Декоратор можно дополнительно параметризовать с помощью целевого обработчика, уровня, при котором должен происходить сброс, и емкости буфера (количество буферизируемых записей). По умолчанию они равны [`StreamHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.StreamHandler), который пишет в `sys.stderr`, `logging.ERROR` и `100` соответственно.24912492Вот скрипт:24932494```python2495import logging2496from logging.handlers import MemoryHandler2497import sys24982499logger = logging.getLogger(__name__)2500logger.addHandler(logging.NullHandler())25012502def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):2503 if target_handler is None:2504 target_handler = logging.StreamHandler()2505 if flush_level is None:2506 flush_level = logging.ERROR2507 if capacity is None:2508 capacity = 1002509 handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)25102511 def decorator(fn):2512 def wrapper(*args, **kwargs):2513 logger.addHandler(handler)2514 try:2515 return fn(*args, **kwargs)2516 except Exception:2517 logger.exception('call failed')2518 raise2519 finally:2520 super(MemoryHandler, handler).flush()2521 logger.removeHandler(handler)2522 return wrapper25232524 return decorator25252526def write_line(s):2527 sys.stderr.write('%s\n' % s)25282529def foo(fail=False):2530 write_line('about to log at DEBUG ...')2531 logger.debug('Actually logged at DEBUG')2532 write_line('about to log at INFO ...')2533 logger.info('Actually logged at INFO')2534 write_line('about to log at WARNING ...')2535 logger.warning('Actually logged at WARNING')2536 if fail:2537 write_line('about to log at ERROR ...')2538 logger.error('Actually logged at ERROR')2539 write_line('about to log at CRITICAL ...')2540 logger.critical('Actually logged at CRITICAL')2541 return fail25422543decorated_foo = log_if_errors(logger)(foo)25442545if __name__ == '__main__':2546 logger.setLevel(logging.DEBUG)2547 write_line('Calling undecorated foo with False')2548 assert not foo(False)2549 write_line('Calling undecorated foo with True')2550 assert foo(True)2551 write_line('Calling decorated foo with False')2552 assert not decorated_foo(False)2553 write_line('Calling decorated foo with True')2554 assert decorated_foo(True)2555```25562557При запуске этого скрипта отобразится следующий вывод:25582559```text2560Calling undecorated foo with False2561about to log at DEBUG ...2562about to log at INFO ...2563about to log at WARNING ...2564Calling undecorated foo with True2565about to log at DEBUG ...2566about to log at INFO ...2567about to log at WARNING ...2568about to log at ERROR ...2569about to log at CRITICAL ...2570Calling decorated foo with False2571about to log at DEBUG ...2572about to log at INFO ...2573about to log at WARNING ...2574Calling decorated foo with True2575about to log at DEBUG ...2576about to log at INFO ...2577about to log at WARNING ...2578about to log at ERROR ...2579Actually logged at DEBUG2580Actually logged at INFO2581Actually logged at WARNING2582Actually logged at ERROR2583about to log at CRITICAL ...2584Actually logged at CRITICAL2585```25862587Как видно, фактический вывод журнала происходит только при регистрации события, уровень которого ERROR или выше, но в этом случае также регистрируются все предыдущие события с более низкими уровнями.25882589Конечно, можно использовать обычные средства декорирования:25902591```python2592@log_if_errors(logger)2593def foo(fail=False):2594 ...2595```25962597## Отправка сообщений журнала по электронной почте с буферизацией25982599Чтобы проиллюстрировать, как можно отправлять сообщения журнала по электронной почте, так чтобы заданное количество сообщений отправлялось за одно письмо, можно создать подкласс [`BufferingHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.BufferingHandler). В приведённом ниже примере, который можно адаптировать под свои нужды, предоставляется простая тестовая обвязка, позволяющая запустить скрипт с аргументами командной строки, указывающими, что обычно необходимо для отправки через SMTP. (Запустите загруженный скрипт с аргументом `-h`, чтобы увидеть обязательные и необязательные аргументы.)26002601```python2602import logging2603import logging.handlers2604import smtplib26052606class BufferingSMTPHandler(logging.handlers.BufferingHandler):2607 def __init__(self, mailhost, port, username, password, fromaddr, toaddrs,2608 subject, capacity):2609 logging.handlers.BufferingHandler.__init__(self, capacity)2610 self.mailhost = mailhost2611 self.mailport = port2612 self.username = username2613 self.password = password2614 self.fromaddr = fromaddr2615 if isinstance(toaddrs, str):2616 toaddrs = [toaddrs]2617 self.toaddrs = toaddrs2618 self.subject = subject2619 self.setFormatter(logging.Formatter("%(asctime)s %(levelname)-5s %(message)s"))26202621 def flush(self):2622 if len(self.buffer) > 0:2623 try:2624 smtp = smtplib.SMTP(self.mailhost, self.mailport)2625 smtp.starttls()2626 smtp.login(self.username, self.password)2627 msg = "From: %s\r\nTo: %s\r\nSubject: %s\r\n\r\n" % (self.fromaddr, ','.join(self.toaddrs), self.subject)2628 for record in self.buffer:2629 s = self.format(record)2630 msg = msg + s + "\r\n"2631 smtp.sendmail(self.fromaddr, self.toaddrs, msg)2632 smtp.quit()2633 except Exception:2634 if logging.raiseExceptions:2635 raise2636 self.buffer = []26372638if __name__ == '__main__':2639 import argparse26402641 ap = argparse.ArgumentParser()2642 aa = ap.add_argument2643 aa('host', metavar='HOST', help='SMTP server')2644 aa('--port', '-p', type=int, default=587, help='SMTP port')2645 aa('user', metavar='USER', help='SMTP username')2646 aa('password', metavar='PASSWORD', help='SMTP password')2647 aa('to', metavar='TO', help='Addressee for emails')2648 aa('sender', metavar='SENDER', help='Sender email address')2649 aa('--subject', '-s',2650 default='Test Logging email from Python logging module (buffering)',2651 help='Subject of email')2652 options = ap.parse_args()2653 logger = logging.getLogger()2654 logger.setLevel(logging.DEBUG)2655 h = BufferingSMTPHandler(options.host, options.port, options.user,2656 options.password, options.sender,2657 options.to, options.subject, 10)2658 logger.addHandler(h)2659 for i in range(102):2660 logger.info("Info index = %d", i)2661 h.flush()2662 h.close()2663```26642665Если запустить этот скрипт и SMTP-сервер настроен правильно, то будет отправлено одиннадцать писем указанному адресату. Первые десять писем будут содержать по десять сообщений журнала, а одиннадцатое – два сообщения. В сумме получается 102 сообщения, как указано в скрипте.26662667## Форматирование времени с использованием UTC (GMT) через конфигурацию26682669Иногда требуется форматировать время в UTC, что можно сделать с помощью класса `UTCFormatter`, показанного ниже:26702671```python2672import logging2673import time26742675class UTCFormatter(logging.Formatter):2676 converter = time.gmtime2677```26782679и затем можно использовать `UTCFormatter` в своём коде вместо [`Formatter`](https://python-all.ru/3.12/library/logging.html#logging.Formatter). Если требуется сделать это через конфигурацию, можно воспользоваться API [`dictConfig()`](https://python-all.ru/3.12/library/logging.config.html#logging.config.dictConfig), как показано в следующем полном примере:26802681```python2682import logging2683import logging.config2684import time26852686class UTCFormatter(logging.Formatter):2687 converter = time.gmtime26882689LOGGING = {2690 'version': 1,2691 'disable_existing_loggers': False,2692 'formatters': {2693 'utc': {2694 '()': UTCFormatter,2695 'format': '%(asctime)s %(message)s',2696 },2697 'local': {2698 'format': '%(asctime)s %(message)s',2699 }2700 },2701 'handlers': {2702 'console1': {2703 'class': 'logging.StreamHandler',2704 'formatter': 'utc',2705 },2706 'console2': {2707 'class': 'logging.StreamHandler',2708 'formatter': 'local',2709 },2710 },2711 'root': {2712 'handlers': ['console1', 'console2'],2713 }2714}27152716if __name__ == '__main__':2717 logging.config.dictConfig(LOGGING)2718 logging.warning('The local time is %s', time.asctime())2719```27202721При запуске этого скрипта он должен вывести примерно следующее:27222723```text27242015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 201527252015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 20152726```27272728показывая, как время форматируется как в местном времени, так и в UTC, по одному для каждого обработчика.27292730## Использование контекстного менеджера для выборочного журналирования27312732Бывают ситуации, когда полезно временно изменить конфигурацию журналирования, а затем вернуть её обратно после выполнения каких-то действий. Для этого контекстный менеджер – самый очевидный способ сохранить и восстановить контекст журналирования. Вот простой пример такого контекстного менеджера, который позволяет по желанию изменить уровень журналирования и добавить обработчик журнала исключительно в области действия контекстного менеджера:27332734```python2735import logging2736import sys27372738class LoggingContext:2739 def __init__(self, logger, level=None, handler=None, close=True):2740 self.logger = logger2741 self.level = level2742 self.handler = handler2743 self.close = close27442745 def __enter__(self):2746 if self.level is not None:2747 self.old_level = self.logger.level2748 self.logger.setLevel(self.level)2749 if self.handler:2750 self.logger.addHandler(self.handler)27512752 def __exit__(self, et, ev, tb):2753 if self.level is not None:2754 self.logger.setLevel(self.old_level)2755 if self.handler:2756 self.logger.removeHandler(self.handler)2757 if self.handler and self.close:2758 self.handler.close()2759 # неявный возврат None => не подавлять исключения2760```27612762Если указать значение уровня, уровень регистратора устанавливается на это значение в области действия блока with, охватываемого контекстным менеджером. Если указать обработчик, он добавляется к регистратору при входе в блок и удаляется при выходе из блока. Также можно попросить менеджер закрыть обработчик при выходе из блока – это можно сделать, если обработчик больше не нужен.27632764Чтобы проиллюстрировать, как это работает, можно добавить следующий блок кода к предыдущему:27652766```python2767if __name__ == '__main__':2768 logger = logging.getLogger('foo')2769 logger.addHandler(logging.StreamHandler())2770 logger.setLevel(logging.INFO)2771 logger.info('1. This should appear just once on stderr.')2772 logger.debug('2. This should not appear.')2773 with LoggingContext(logger, level=logging.DEBUG):2774 logger.debug('3. This should appear once on stderr.')2775 logger.debug('4. This should not appear.')2776 h = logging.StreamHandler(sys.stdout)2777 with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):2778 logger.debug('5. This should appear twice - once on stderr and once on stdout.')2779 logger.info('6. This should appear just once on stderr.')2780 logger.debug('7. This should not appear.')2781```27822783Изначально устанавливаем уровень регистратора равным `INFO`, поэтому сообщение №1 отображается, а сообщение №2 – нет. Затем временно меняем уровень на `DEBUG` в следующем блоке `with`, и сообщение №3 отображается. После выхода из блока уровень регистратора восстанавливается до `INFO`, поэтому сообщение №4 не отображается. В следующем блоке `with` снова устанавливаем уровень `DEBUG`, но также добавляем обработчик, записывающий в `sys.stdout`. Таким образом, сообщение №5 отображается дважды на консоли (один раз через `stderr` и один раз через `stdout`). После завершения оператора `with` состояние возвращается к исходному, поэтому сообщение №6 отображается (как сообщение №1), а сообщение №7 – нет (как сообщение №2).27842785Если запустить полученный скрипт, результат будет следующим:27862787```console2788$ python logctx.py27891. This should appear just once on stderr.27903. This should appear once on stderr.27915. This should appear twice - once on stderr and once on stdout.27925. This should appear twice - once on stderr and once on stdout.27936. This should appear just once on stderr.2794```27952796Если запустить его снова, но перенаправить `stderr` в `/dev/null`, мы увидим следующее, что является единственным сообщением, записанным в `stdout`:27972798```console2799$ python logctx.py 2>/dev/null28005. This should appear twice - once on stderr and once on stdout.2801```28022803Ещё раз, но перенаправляя `stdout` в `/dev/null`, получаем:28042805```console2806$ python logctx.py >/dev/null28071. This should appear just once on stderr.28083. This should appear once on stderr.28095. This should appear twice - once on stderr and once on stdout.28106. This should appear just once on stderr.2811```28122813В этом случае сообщение №5, выведенное в `stdout`, не отображается, как и ожидалось.28142815Разумеется, описанный подход можно обобщить, например, для временного подключения фильтров журналирования. Обратите внимание, что приведённый выше код работает как в Python 2, так и в Python 3.28162817## Шаблон для запуска CLI-приложения28182819Вот пример, показывающий, как можно:28202821- Использовать уровень журналирования на основе аргументов командной строки2822- Перенаправлять вызовы к нескольким подкомандам в отдельных файлах, все с журналированием на одном уровне согласованным образом2823- Использовать простую минимальную конфигурацию28242825Предположим, у нас есть приложение командной строки, которое останавливает, запускает или перезапускает некоторые службы. Для иллюстрации это может быть организовано в виде файла `app.py`, который является главным скриптом приложения, с отдельными командами, реализованными в `start.py`, `stop.py` и `restart.py`. Предположим также, что мы хотим управлять степенью подробности вывода приложения через аргумент командной строки с значением по умолчанию `logging.INFO`. Вот один из способов, как мог бы быть написан `app.py`:28262827```python2828import argparse2829import importlib2830import logging2831import os2832import sys28332834def main(args=None):2835 scriptname = os.path.basename(__file__)2836 parser = argparse.ArgumentParser(scriptname)2837 levels = ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')2838 parser.add_argument('--log-level', default='INFO', choices=levels)2839 subparsers = parser.add_subparsers(dest='command',2840 help='Available commands:')2841 start_cmd = subparsers.add_parser('start', help='Start a service')2842 start_cmd.add_argument('name', metavar='NAME',2843 help='Name of service to start')2844 stop_cmd = subparsers.add_parser('stop',2845 help='Stop one or more services')2846 stop_cmd.add_argument('names', metavar='NAME', nargs='+',2847 help='Name of service to stop')2848 restart_cmd = subparsers.add_parser('restart',2849 help='Restart one or more services')2850 restart_cmd.add_argument('names', metavar='NAME', nargs='+',2851 help='Name of service to restart')2852 options = parser.parse_args()2853 # весь код для отправки команд мог бы быть в этом файле. Для целей2854 # только в целях иллюстрации каждая команда реализована в отдельном модуле.2855 try:2856 mod = importlib.import_module(options.command)2857 cmd = getattr(mod, 'command')2858 except (ImportError, AttributeError):2859 print('Unable to find the code for command \'%s\'' % options.command)2860 return 12861 # Здесь можно было бы сделать по-хитрому и загрузить конфигурацию из файла или словаря2862 logging.basicConfig(level=options.log_level,2863 format='%(levelname)s %(name)s %(message)s')2864 cmd(options)28652866if __name__ == '__main__':2867 sys.exit(main())2868```28692870А команды `start`, `stop` и `restart` могут быть реализованы в отдельных модулях, например, для запуска:28712872```python2873# start.py2874import logging28752876logger = logging.getLogger(__name__)28772878def command(options):2879 logger.debug('About to start %s', options.name)2880 # здесь происходит фактическая обработка команды...2881 logger.info('Started the \'%s\' service.', options.name)2882```28832884и аналогично для остановки:28852886```python2887# stop.py2888import logging28892890logger = logging.getLogger(__name__)28912892def command(options):2893 n = len(options.names)2894 if n == 1:2895 plural = ''2896 services = '\'%s\'' % options.names[0]2897 else:2898 plural = 's'2899 services = ', '.join('\'%s\'' % name for name in options.names)2900 i = services.rfind(', ')2901 services = services[:i] + ' and ' + services[i + 2:]2902 logger.debug('About to stop %s', services)2903 # здесь происходит фактическая обработка команды...2904 logger.info('Stopped the %s service%s.', services, plural)2905```29062907и аналогично для перезапуска:29082909```python2910# restart.py2911import logging29122913logger = logging.getLogger(__name__)29142915def command(options):2916 n = len(options.names)2917 if n == 1:2918 plural = ''2919 services = '\'%s\'' % options.names[0]2920 else:2921 plural = 's'2922 services = ', '.join('\'%s\'' % name for name in options.names)2923 i = services.rfind(', ')2924 services = services[:i] + ' and ' + services[i + 2:]2925 logger.debug('About to restart %s', services)2926 # здесь происходит фактическая обработка команды...2927 logger.info('Restarted the %s service%s.', services, plural)2928```29292930Если запустить это приложение с уровнем журналирования по умолчанию, мы получим примерно такой вывод:29312932```console2933$ python app.py start foo2934INFO start Started the 'foo' service.29352936$ python app.py stop foo bar2937INFO stop Stopped the 'foo' and 'bar' services.29382939$ python app.py restart foo bar baz2940INFO restart Restarted the 'foo', 'bar' and 'baz' services.2941```29422943Первое слово – уровень журналирования, а второе – имя модуля или пакета, в котором было зарегистрировано событие.29442945Если изменить уровень журналирования, можно изменить объём информации, отправляемой в журнал. Например, чтобы получить больше информации:29462947```console2948$ python app.py --log-level DEBUG start foo2949DEBUG start About to start foo2950INFO start Started the 'foo' service.29512952$ python app.py --log-level DEBUG stop foo bar2953DEBUG stop About to stop 'foo' and 'bar'2954INFO stop Stopped the 'foo' and 'bar' services.29552956$ python app.py --log-level DEBUG restart foo bar baz2957DEBUG restart About to restart 'foo', 'bar' and 'baz'2958INFO restart Restarted the 'foo', 'bar' and 'baz' services.2959```29602961А если нужно меньше:29622963```console2964$ python app.py --log-level WARNING start foo2965$ python app.py --log-level WARNING stop foo bar2966$ python app.py --log-level WARNING restart foo bar baz2967```29682969В этом случае команды ничего не выводят в консоль, поскольку ни одно сообщение уровня `WARNING` и выше ими не записывается.29702971## Графический интерфейс Qt для журналирования29722973Время от времени возникает вопрос о том, как вести журналирование в приложении с графическим интерфейсом. Фреймворк [Qt](https://python-all.ru/3.12/howto/logging-cookbook.html) – популярный кроссплатформенный инструмент для создания UI, имеющий привязки к Python через библиотеки [PySide2](https://python-all.ru/3.12/howto/logging-cookbook.html) или [PyQt5](https://python-all.ru/3.12/howto/logging-cookbook.html).29742975В следующем примере показано, как выполнять журналирование в графический интерфейс Qt. Он представляет простой класс `QtHandler`, который принимает вызываемый объект – слот главного потока, обновляющий GUI. Также создаётся рабочий поток, чтобы продемонстрировать возможность журналирования как из самого интерфейса (через кнопку для ручной записи), так и из фонового рабочего потока (который в данном случае просто выводит сообщения со случайными уровнями и случайными короткими задержками).29762977Рабочий поток реализован с помощью класса `QThread` из Qt, а не модуля [`threading`](https://python-all.ru/3.12/library/threading.html#module-threading), поскольку бывают ситуации, когда необходимо использовать `QThread`, который обеспечивает лучшую интеграцию с другими компонентами `Qt`.29782979Код должен работать с последними версиями `PySide6`, `PyQt6`, `PySide2` или `PyQt5`. Вы сможете адаптировать этот подход для более ранних версий Qt. Обратитесь к комментариям в примере кода за более подробной информацией.29802981```python2982import datetime2983import logging2984import random2985import sys2986import time29872988# Обработка небольших различий между разными пакетами Qt2989try:2990 from PySide6 import QtCore, QtGui, QtWidgets2991 Signal = QtCore.Signal2992 Slot = QtCore.Slot2993except ImportError:2994 try:2995 from PyQt6 import QtCore, QtGui, QtWidgets2996 Signal = QtCore.pyqtSignal2997 Slot = QtCore.pyqtSlot2998 except ImportError:2999 try:3000 from PySide2 import QtCore, QtGui, QtWidgets3001 Signal = QtCore.Signal3002 Slot = QtCore.Slot3003 except ImportError:3004 from PyQt5 import QtCore, QtGui, QtWidgets3005 Signal = QtCore.pyqtSignal3006 Slot = QtCore.pyqtSlot30073008logger = logging.getLogger(__name__)30093010#3011# Сигналы должны содержаться в QObject или подклассе, чтобы корректно3012# инициализироваться.3013#3014class Signaller(QtCore.QObject):3015 signal = Signal(str, logging.LogRecord)30163017#3018# Вывод в графический интерфейс Qt должен происходить только в главном потоке. Поэтому данный3019# обработчик спроектирован так, чтобы принимать функцию-слот, настроенную на выполнение в главном3020# потоке. В этом примере функция принимает строковый аргумент, который является3021# отформатированным сообщением лога, и запись лога, которая его породила. Отформатированная3022# строка – это просто удобство; можно отформатировать строку для вывода любым способом3023# в самой функции-слоте.3024#3025# Функцию-слот можно настроить на любые нужные обновления GUI. Обработчик3026# не знает и не заботится о конкретных элементах интерфейса.3027#3028class QtHandler(logging.Handler):3029 def __init__(self, slotfunc, *args, **kwargs):3030 super().__init__(*args, **kwargs)3031 self.signaller = Signaller()3032 self.signaller.signal.connect(slotfunc)30333034 def emit(self, record):3035 s = self.format(record)3036 self.signaller.signal.emit(s, record)30373038#3039# В этом примере используются QThreads, что означает, что потоки на уровне Python3040# называются как-то вроде "Dummy-1". Функция ниже получает имя Qt3041# текущего потока.3042#3043def ctname():3044 return QtCore.QThread.currentThread().objectName()30453046#3047# Используется для генерации случайных уровней для логирования.3048#3049LEVELS = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,3050 logging.CRITICAL)30513052#3053# Этот класс-воркер представляет работу, выполняемую в потоке, отдельном от3054# главного потока. Поток запускается на выполнение работы по нажатию кнопки,3055# которая соединяется со слотом в воркере.3056#3057# Поскольку значение threadName по умолчанию в LogRecord не очень полезно, мы добавляем3058# qThreadName, содержащий имя QThread, вычисленное выше, и передаём это3059# значение в словаре "extra", который используется для обновления LogRecord с помощью3060# имя QThread.3061#3062# Этот пример рабочего просто выводит сообщения последовательно, перемежая их случайными задержками порядка нескольких секунд.3063# Позволяет потоку выполняться до прерывания. Это обеспечивает достаточно чистую остановку потока.3064#3065class Worker(QtCore.QObject):3066 @Slot()3067 def start(self):3068 extra = {'qThreadName': ctname() }3069 logger.debug('Started work', extra=extra)3070 i = 13071 # Реализует простой пользовательский интерфейс для этого примера из кулинарной книги. Он содержит:3072 # * Окно текстового редактора только для чтения, которое содержит форматированные сообщения журнала3073 while not QtCore.QThread.currentThread().isInterruptionRequested():3074 delay = 0.5 + random.random() * 23075 time.sleep(delay)3076 try:3077 if random.random() < 0.1:3078 raise ValueError('Exception raised: %d' % i)3079 else:3080 level = random.choice(LEVELS)3081 logger.log(level, 'Message after delay of %3.1f: %d', delay, i, extra=extra)3082 except ValueError as e:3083 logger.exception('Failed: %s', e, extra=extra)3084 i += 130853086#3087# * Кнопка запуска работы и записи в журнал в отдельном потоке3088#3089# * Кнопка записи чего-либо из основного потока3090# * Кнопка очистки окна журнала3091# Устанавливает моноширинный шрифт, принятый по умолчанию на платформе3092# для Qt63093#3094class Window(QtWidgets.QWidget):30953096 COLORS = {3097 logging.DEBUG: 'black',3098 logging.INFO: 'blue',3099 logging.WARNING: 'orange',3100 logging.ERROR: 'red',3101 logging.CRITICAL: 'purple',3102 }31033104 def __init__(self, app):3105 super().__init__()3106 self.app = app3107 self.textedit = te = QtWidgets.QPlainTextEdit(self)3108 # Устанавливает моноширинный шрифт по умолчанию для платформы3109 f = QtGui.QFont('nosuchfont')3110 if hasattr(f, 'Monospace'):3111 f.setStyleHint(f.Monospace)3112 else:3113 f.setStyleHint(f.StyleHint.Monospace) # для Qt63114 te.setFont(f)3115 te.setReadOnly(True)3116 PB = QtWidgets.QPushButton3117 self.work_button = PB('Start background work', self)3118 self.log_button = PB('Log a message at a random level', self)3119 self.clear_button = PB('Clear log window', self)3120 self.handler = h = QtHandler(self.update_status)3121 # Размещает все виджеты3122 fs = '%(asctime)s %(qThreadName)-12s %(levelname)-8s %(message)s'3123 formatter = logging.Formatter(fs)3124 h.setFormatter(formatter)3125 logger.addHandler(h)3126 # Подключает слоты и сигналы, не относящиеся к рабочему3127 app.aboutToQuit.connect(self.force_quit)31283129 # Запускает новый рабочий поток и подключает слоты для рабочего3130 layout = QtWidgets.QVBoxLayout(self)3131 layout.addWidget(te)3132 layout.addWidget(self.work_button)3133 layout.addWidget(self.log_button)3134 layout.addWidget(self.clear_button)3135 self.setFixedSize(900, 400)31363137 # После запуска кнопка должна быть отключена3138 self.log_button.clicked.connect(self.manual_update)3139 self.clear_button.clicked.connect(self.clear_display)31403141 # Запустить новый рабочий поток и подключить слоты для рабочего3142 self.start_thread()3143 self.work_button.clicked.connect(self.worker.start)3144 # Это запустит цикл событий в рабочем потоке3145 self.work_button.clicked.connect(lambda : self.work_button.setEnabled(False))31463147 def start_thread(self):3148 self.worker = Worker()3149 self.worker_thread = QtCore.QThread()3150 self.worker.setObjectName('Worker')3151 self.worker_thread.setObjectName('WorkerThread') # Просто скажите рабочему остановиться, затем скажите ему выйти и дождитесь этого3152 self.worker.moveToThread(self.worker_thread)3153 # Для использования при закрытии окна3154 self.worker_thread.start()31553156 def kill_thread(self):3157 # Функции ниже обновляют интерфейс и выполняются в основном потоке, поскольку слоты настроены именно там3158 # Эта функция использует переданное форматированное сообщение, но также использует информацию из записи, чтобы отформатировать сообщение подходящим цветом в соответствии с его серьёзностью (уровнем).3159 self.worker_thread.requestInterruption()3160 if self.worker_thread.isRunning():3161 self.worker_thread.quit()3162 self.worker_thread.wait()3163 else:3164 print('worker has already exited.')31653166 def force_quit(self):3167 # Для использования при закрытии окна3168 if self.worker_thread.isRunning():3169 self.kill_thread()31703171 # Функции ниже обновляют пользовательский интерфейс и выполняются в главном потоке, потому что3172 # здесь настраиваются слоты31733174 @Slot(str, logging.LogRecord)3175 def update_status(self, status, record):3176 color = self.COLORS.get(record.levelno, 'black')3177 s = '<pre><font color="%s">%s</font></pre>' % (color, status)3178 self.textedit.appendHtml(s)31793180 @Slot()3181 def manual_update(self):3182 # Эта функция использует переданное форматированное сообщение, а также использует3183 # информацию из записи для форматирования сообщения в подходящий3184 # цвет в соответствии с его серьёзностью (уровнем).3185 level = random.choice(LEVELS)3186 extra = {'qThreadName': ctname() }3187 logger.log(level, 'Manually logged!', extra=extra)31883189 @Slot()3190 def clear_display(self):3191 self.textedit.clear()31923193def main():3194 QtCore.QThread.currentThread().setObjectName('MainThread')3195 logging.getLogger().setLevel(logging.DEBUG)3196 app = QtWidgets.QApplication(sys.argv)3197 example = Window(app)3198 example.show()3199 if hasattr(app, 'exec'):3200 rc = app.exec()3201 else:3202 rc = app.exec_()3203 sys.exit(rc)32043205if __name__=='__main__':3206 main()3207```32083209## Журналирование в syslog с поддержкой RFC 542432103211Хотя [**RFC 5424**](https://python-all.ru/3.12/howto/logging-cookbook.html) датируется 2009 годом, большинство syslog-серверов по умолчанию настроены на использование более старого [**RFC 3164**](https://python-all.ru/3.12/howto/logging-cookbook.html), который появился в 2001 году. Когда `logging` был добавлен в Python в 2003 году, он поддерживал более ранний (и единственный на тот момент) протокол. После появления RFC5424, поскольку он не получил широкого распространения в syslog-серверах, функциональность [`SysLogHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.handlers.SysLogHandler) не была обновлена.32123213RFC 5424 содержит полезные возможности, такие как поддержка структурированных данных. Если необходимо вести журналирование на syslog-сервер с поддержкой этого протокола, это можно сделать с помощью подкласса обработчика, который выглядит примерно так:32143215```python3216import datetime3217import logging.handlers3218import re3219import socket3220import time32213222class SysLogHandler5424(logging.handlers.SysLogHandler):32233224 tz_offset = re.compile(r'([+-]\d{2})(\d{2})$')3225 escaped = re.compile(r'([\]"\\])')32263227 def __init__(self, *args, **kwargs):3228 self.msgid = kwargs.pop('msgid', None)3229 self.appname = kwargs.pop('appname', None)3230 super().__init__(*args, **kwargs)32313232 def format(self, record):3233 version = 13234 asctime = datetime.datetime.fromtimestamp(record.created).isoformat()3235 m = self.tz_offset.match(time.strftime('%z'))3236 has_offset = False3237 if m and time.timezone:3238 hrs, mins = m.groups()3239 if int(hrs) or int(mins):3240 has_offset = True3241 if not has_offset:3242 asctime += 'Z'3243 else:3244 asctime += f'{hrs}:{mins}'3245 try:3246 hostname = socket.gethostname()3247 except Exception:3248 hostname = '-'3249 appname = self.appname or '-'3250 procid = record.process3251 msgid = '-'3252 msg = super().format(record)3253 sdata = '-'3254 if hasattr(record, 'structured_data'):3255 sd = record.structured_data3256 # Это должен быть словарь, где ключи – SD-ID, а значение –3257 # словарь, отображающий PARAM-NAME на PARAM-VALUE (обратитесь к RFC, чтобы узнать, что эти3258 # означают)3259 # Здесь нет проверки ошибок – это только для иллюстрации, и вы3260 # можете адаптировать этот код для использования в производственных средах3261 parts = []32623263 def replacer(m):3264 g = m.groups()3265 return '\\' + g[0]32663267 for sdid, dv in sd.items():3268 part = f'[{sdid}'3269 for k, v in dv.items():3270 s = str(v)3271 s = self.escaped.sub(replacer, s)3272 part += f' {k}="{s}"'3273 part += ']'3274 parts.append(part)3275 sdata = ''.join(parts)3276 return f'{version} {asctime} {hostname} {appname} {procid} {msgid} {sdata} {msg}'3277```32783279Чтобы полностью разобраться в приведённом коде, потребуется знакомство с RFC 5424. Возможно, ваши потребности будут несколько иными (например, в способе передачи структурированных данных в журнал). Тем не менее, приведённый код можно адаптировать под конкретные нужды. С таким обработчиком структурированные данные передаются, например, так:32803281```python3282sd = {3283 'foo@12345': {'bar': 'baz', 'baz': 'bozz', 'fizz': r'buzz'},3284 'foo@54321': {'rab': 'baz', 'zab': 'bozz', 'zzif': r'buzz'}3285}3286extra = {'structured_data': sd}3287i = 13288logger.debug('Message %d', i, extra=extra)3289```32903291## Как использовать объект Logger как выходной поток32923293Иногда возникает необходимость взаимодействовать со сторонним API, который ожидает объект, подобный файлу, для записи, но при этом нужно перенаправить вывод API в журнал. Это можно сделать с помощью класса, который оборачивает объект Logger, предоставляя файлоподобный интерфейс. Вот короткий скрипт, иллюстрирующий такой класс:32943295```python3296import logging32973298class LoggerWriter:3299 def __init__(self, logger, level):3300 self.logger = logger3301 self.level = level33023303 def write(self, message):3304 if message != '\n': # избегайте печати пустых строк, если хотите3305 self.logger.log(self.level, message)33063307 def flush(self):3308 # на самом деле ничего не делает, но может ожидаться от файлоподобного3309 # объекта – так что опционально в зависимости от вашей ситуации3310 pass33113312 def close(self):3313 # на самом деле ничего не делает, но может ожидаться от файлоподобного3314 # объекта – так что опционально в зависимости от вашей ситуации. Возможно, вы захотите3315 # установить флаг, чтобы последующие вызовы write вызывали исключение3316 pass33173318def main():3319 logging.basicConfig(level=logging.DEBUG)3320 logger = logging.getLogger('demo')3321 info_fp = LoggerWriter(logger, logging.INFO)3322 debug_fp = LoggerWriter(logger, logging.DEBUG)3323 print('An INFO message', file=info_fp)3324 print('A DEBUG message', file=debug_fp)33253326if __name__ == "__main__":3327 main()3328```33293330При запуске этот скрипт выводит33313332```text3333INFO:demo:An INFO message3334DEBUG:demo:A DEBUG message3335```33363337Можно также использовать `LoggerWriter` для перенаправления `sys.stdout` и `sys.stderr`, сделав примерно так:33383339```python3340import sys33413342sys.stdout = LoggerWriter(logger, logging.INFO)3343sys.stderr = LoggerWriter(logger, logging.WARNING)3344```33453346Это следует делать *после* настройки журналирования под свои нужды. В приведённом выше примере вызов [`basicConfig()`](https://python-all.ru/3.12/library/logging.html#logging.basicConfig) делает это (используя значение `sys.stderr` *до* того, как оно будет перезаписано экземпляром `LoggerWriter`). В результате получится примерно такой вывод:33473348```pycon3349>>> print('Foo')3350INFO:demo:Foo3351>>> print('Bar', file=sys.stderr)3352WARNING:demo:Bar3353>>>3354```33553356Разумеется, приведённые выше примеры показывают вывод в формате, используемом [`basicConfig()`](https://python-all.ru/3.12/library/logging.html#logging.basicConfig), но при настройке журналирования можно использовать другой форматтер.33573358Обратите внимание, что при такой схеме вы в значительной степени зависите от буферизации и порядка вызовов write, которые перехватываете. Например, при определении `LoggerWriter` выше, если есть такой фрагмент кода:33593360```python3361sys.stderr = LoggerWriter(logger, logging.WARNING)33621 / 03363```33643365то запуск скрипта даёт33663367```text3368WARNING:demo:Traceback (most recent call last):33693370WARNING:demo: File "/home/runner/cookbook-loggerwriter/test.py", line 53, in <module>33713372WARNING:demo:3373WARNING:demo:main()3374WARNING:demo: File "/home/runner/cookbook-loggerwriter/test.py", line 49, in main33753376WARNING:demo:3377WARNING:demo:1 / 03378WARNING:demo:ZeroDivisionError3379WARNING:demo::3380WARNING:demo:division by zero3381```33823383Как видите, такой вывод неидеален. Это происходит потому, что код, который пишет в `sys.stderr`, выполняет несколько записей, и каждая из них приводит к отдельной строке в журнале (например, три последние строки выше). Чтобы обойти эту проблему, нужно буферизовать данные и выводить строки журнала только при появлении символов новой строки. Давайте используем немного улучшенную реализацию `LoggerWriter`:33843385```python3386class BufferingLoggerWriter(LoggerWriter):3387 def __init__(self, logger, level):3388 super().__init__(logger, level)3389 self.buffer = ''33903391 def write(self, message):3392 if '\n' not in message:3393 self.buffer += message3394 else:3395 parts = message.split('\n')3396 if self.buffer:3397 s = self.buffer + parts.pop(0)3398 self.logger.log(self.level, s)3399 self.buffer = parts.pop()3400 for part in parts:3401 self.logger.log(self.level, part)3402```34033404Этот код просто буферизует данные до появления символа новой строки, после чего записывает полные строки. С таким подходом вывод становится лучше:34053406```text3407WARNING:demo:Traceback (most recent call last):3408WARNING:demo: File "/home/runner/cookbook-loggerwriter/main.py", line 55, in <module>3409WARNING:demo: main()3410WARNING:demo: File "/home/runner/cookbook-loggerwriter/main.py", line 52, in main3411WARNING:demo: 1/03412WARNING:demo:ZeroDivisionError: division by zero3413```34143415## Шаблоны, которых следует избегать34163417Хотя в предыдущих разделах были описаны способы решения задач, с которыми вы можете столкнуться, стоит упомянуть некоторые шаблоны использования, которые *бесполезны* и в большинстве случаев их следует избегать. Следующие разделы приведены в произвольном порядке.34183419### Многократное открытие одного и того же файла журнала34203421В Windows обычно не получится открыть один и тот же файл несколько раз, так как это приведёт к ошибке «файл используется другим процессом». Однако на платформах POSIX никаких ошибок при многократном открытии одного файла не возникнет. Это может произойти случайно, например:34223423- Добавление файлового обработчика более одного раза со ссылкой на один и тот же файл (например, из-за ошибки копирования/вставки/забыли изменить).3424- Открытие двух файлов, которые выглядят разными (у них разные имена), но на самом деле являются одним и тем же файлом, так как один – символическая ссылка на другой.3425- Порождение процесса (форк), после которого и родительский, и дочерний процесс имеют ссылку на один и тот же файл. Это может происходить, например, при использовании модуля [`multiprocessing`](https://python-all.ru/3.12/library/multiprocessing.html#module-multiprocessing).34263427Многократное открытие файла может *выглядеть* работающим большую часть времени, но на практике может привести к ряду проблем:34283429- Вывод логирования может искажаться, поскольку несколько потоков или процессов пытаются писать в один и тот же файл. Хотя логирование защищает от одновременного использования одного и того же экземпляра обработчика несколькими потоками, такой защиты нет, если одновременную запись пытаются выполнить два разных потока, использующие два разных экземпляра обработчика, которые указывают на один и тот же файл.3430- Попытка удалить файл (например, во время ротации) молча завершается неудачей, потому что есть другая ссылка на него. Это может привести к путанице и потере времени на отладку – записи журнала оказываются в неожиданных местах или полностью теряются. Или файл, который должен был быть перемещён, остаётся на месте и неожиданно растёт в размерах, несмотря на то что ротация по размеру якобы настроена.34313432Используйте методы, описанные в [Логирование в один файл из нескольких процессов](https://python-all.ru/3.12/howto/logging-cookbook.html#multiple-processes), чтобы обойти такие проблемы.34333434### Использование логгеров в качестве атрибутов класса или передача их в качестве параметров34353436Хотя могут быть необычные случаи, когда это необходимо, в целом в этом нет смысла, потому что логгеры – синглтоны. Код всегда может получить доступ к нужному экземпляру логгера по имени с помощью `logging.getLogger(name)`, поэтому передавать экземпляры повсюду и хранить их в качестве атрибутов экземпляра бессмысленно. Обратите внимание, что в других языках, таких как Java и C#, логгеры часто являются статическими атрибутами класса. Однако этот шаблон не имеет смысла в Python, где модуль (а не класс) является единицей декомпозиции программного обеспечения.34373438### Добавление обработчиков, отличных от [`NullHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.NullHandler), к логгеру в библиотеке34393440Настройка логирования путём добавления обработчиков, форматировщиков и фильтров – это ответственность разработчика приложения, а не разработчика библиотеки. Если вы поддерживаете библиотеку, убедитесь, что не добавляете обработчики ни к одному из своих логгеров, кроме экземпляра [`NullHandler`](https://python-all.ru/3.12/library/logging.handlers.html#logging.NullHandler).34413442### Создание большого количества логгеров34433444Логгеры – это синглтоны, которые никогда не освобождаются во время выполнения скрипта, поэтому создание большого количества логгеров приведёт к расходу памяти, которую затем нельзя освободить. Вместо того чтобы создавать логгер для каждого обрабатываемого файла или сетевого соединения, используйте [существующие механизмы](https://python-all.ru/3.12/howto/logging-cookbook.html#context-info) для передачи контекстной информации в ваши журналы и ограничьте создаваемые логгеры теми, которые описывают области вашего приложения (обычно модули, но иногда и с чуть большей детализацией).34453446## Другие ресурсы34473448> **См. также**3449>3450> **Модуль [`logging`](https://python-all.ru/3.12/library/logging.html#module-logging)**3451>3452> Справочник API для модуля logging.3453>3454> **Модуль [`logging.config`](https://python-all.ru/3.12/library/logging.config.html#module-logging.config)**3455>3456> API конфигурации для модуля logging.3457>3458> **Модуль [`logging.handlers`](https://python-all.ru/3.12/library/logging.handlers.html#module-logging.handlers)**3459>3460> Полезные обработчики, входящие в состав модуля logging.3461>3462> [Базовое руководство](https://python-all.ru/3.12/howto/logging.html#logging-basic-tutorial)3463>3464> [Продвинутое руководство](https://python-all.ru/3.12/howto/logging.html#logging-advanced-tutorial)3465