logging-cookbook.md
1> **Источник:** https://python-all.ru/3.14/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.14/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.14/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.14/library/logging.handlers.html#logging.handlers.SMTPHandler): отправка электронной почты может занимать много времени по ряду причин, не зависящих от разработчика (например, из-за плохой работы почтовой или сетевой инфраструктуры). Но почти любой сетевой обработчик может блокировать: даже операция [`SocketHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.SocketHandler) может выполнять DNS-запрос «под капотом», который оказывается слишком медленным (и этот запрос может быть глубоко в коде библиотеки сокетов, ниже уровня Python и вне вашего контроля).504505Одно из решений – использовать двухчастный подход. На первом этапе к логгерам, к которым обращаются из критичных по производительности потоков, следует подключать только [`QueueHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.QueueHandler). Они просто пишут в свою очередь, которую можно настроить на достаточно большую ёмкость или инициализировать без верхнего ограничения размера. Запись в очередь обычно выполняется быстро, хотя в коде желательно перехватывать исключение [`queue.Full`](https://python-all.ru/3.14/library/queue.html#queue.Full) на всякий случай. Если вы – разработчик библиотеки, в коде которой есть критичные по производительности потоки, обязательно задокументируйте это (вместе с рекомендацией подключать к вашим логгерам только `QueueHandlers`) для пользы других разработчиков, которые будут использовать ваш код.506507Вторая часть решения – [`QueueListener`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.QueueListener), который был разработан как аналог [`QueueHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.QueueHandler). `QueueListener` устроен очень просто: ему передаётся очередь и несколько обработчиков, и он запускает внутренний поток, который слушает свою очередь на предмет LogRecords, отправленных из `QueueHandlers` (или любого другого источника `LogRecords`). `LogRecords` извлекаются из очереди и передаются обработчикам для обработки.508509Преимущество отдельного класса [`QueueListener`](https://python-all.ru/3.14/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.14/library/asyncio.html#module-asyncio). Поэтому, если в приложении используется асинхронный код, лучше всего применять описанный выше подход к логированию, чтобы любой блокирующий код выполнялся только в `QueueListener` потоке.540541Изменено в версии 3.5: До Python 3.5 [`QueueListener`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.QueueListener) всегда передавал каждое полученное из очереди сообщение каждому обработчику, с которыми был инициализирован. (Это объяснялось тем, что предполагалось, что фильтрация по уровню полностью выполняется на стороне наполнения очереди.) Начиная с версии 3.5 это поведение можно изменить, передав именованный аргумент `respect_handler_level=True` конструктору слушателя. Когда это сделано, слушатель сравнивает уровень каждого сообщения с уровнем обработчика и передаёт сообщение обработчику, только если это уместно.542543Изменено в версии 3.14: [`QueueListener`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.QueueListener) можно запускать (и останавливать) через оператор [`with`](https://python-all.ru/3.14/reference/compound_stmts.html#with). Например:544545```python546with QueueListener(que, handler) as listener:547 # Слушатель очереди автоматически запускается при входе в блок 'with'.548 # когда входим в блок 'with'.549 pass550# Слушатель очереди автоматически останавливается при выходе из блока 'with'.551# когда выходим из блока 'with'.552```553554## Отправка и получение событий логирования по сети555556Допустим, вы хотите отправлять события логирования по сети и обрабатывать их на принимающей стороне. Простой способ – подключить экземпляр [`SocketHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.SocketHandler) к корневому логгеру на отправляющей стороне:557558```python559import logging, logging.handlers560561rootLogger = logging.getLogger()562rootLogger.setLevel(logging.DEBUG)563socketHandler = logging.handlers.SocketHandler('localhost',564 logging.handlers.DEFAULT_TCP_LOGGING_PORT)565# Не нужно использовать форматтер, так как сокет-обработчик отправляет событие в виде неформатированного пикла.566# неформатированный pickle567rootLogger.addHandler(socketHandler)568569# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...570logging.info('Jackdaws love my big sphinx of quartz.')571572# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:573# приложение:574575logger1 = logging.getLogger('myapp.area1')576logger2 = logging.getLogger('myapp.area2')577578logger1.debug('Quick zephyrs blow, vexing daft Jim.')579logger1.info('How quickly daft jumping zebras vex.')580logger2.warning('Jail zesty vixen who grabbed pay from quack.')581logger2.error('The five boxing wizards jump quickly.')582```583584На принимающей стороне можно настроить приёмник с помощью модуля [`socketserver`](https://python-all.ru/3.14/library/socketserver.html#module-socketserver). Вот простой работающий пример:585586```python587import pickle588import logging589import logging.handlers590import socketserver591import struct592593class LogRecordStreamHandler(socketserver.StreamRequestHandler):594 """Обработчик для потокового запроса логирования.595596 Это по сути записывает запись, используя ту политику логирования, которая настроена локально.597 настроено локально.598 """599600 def handle(self):601 """602 Обрабатывает несколько запросов – каждый ожидается в формате: 4-байтовая длина, затем запись журнала в формате пикл.603 Записывает запись в соответствии с политикой, настроенной локально.604 согласно локально настроенной политике.605 """606 while True:607 chunk = self.connection.recv(4)608 if len(chunk) < 4:609 break610 slen = struct.unpack('>L', chunk)[0]611 chunk = self.connection.recv(slen)612 while len(chunk) < slen:613 chunk = chunk + self.connection.recv(slen - len(chunk))614 obj = self.unPickle(chunk)615 record = logging.makeLogRecord(obj)616 self.handleLogRecord(record)617618 def unPickle(self, data):619 return pickle.loads(data)620621 def handleLogRecord(self, record):622 # Если указано имя, используется именованный логгер, а не тот, что623 # подразумевается записью.624 if self.server.logname is not None:625 name = self.server.logname626 else:627 name = record.name628 logger = logging.getLogger(name)629 # Примечание: КАЖДАЯ запись попадает в журнал. Это связано с тем, что Logger.handle630 # обычно вызывается ПОСЛЕ фильтрации на уровне регистратора. Если требуется631 # выполнять фильтрацию, делайте это на стороне клиента, чтобы не тратить632 # циклы процессора и сетевую пропускную способность!633 logger.handle(record)634635class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):636 """637 Простой приёмник журнала на основе TCP-сокетов, подходящий для тестирования.638 """639640 allow_reuse_address = True641642 def __init__(self, host='localhost',643 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,644 handler=LogRecordStreamHandler):645 socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)646 self.abort = 0647 self.timeout = 1648 self.logname = None649650 def serve_until_stopped(self):651 import select652 abort = 0653 while not abort:654 rd, wr, ex = select.select([self.socket.fileno()],655 [], [],656 self.timeout)657 if rd:658 self.handle_request()659 abort = self.abort660661def main():662 logging.basicConfig(663 format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')664 tcpserver = LogRecordSocketReceiver()665 print('About to start TCP server...')666 tcpserver.serve_until_stopped()667668if __name__ == '__main__':669 main()670```671672Сначала запустите сервер, затем клиент. На стороне клиента в консоль ничего не выводится; на стороне сервера вы должны увидеть что-то вроде:673674```text675About to start TCP server...676 59 root INFO Jackdaws love my big sphinx of quartz.677 59 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim.678 69 myapp.area1 INFO How quickly daft jumping zebras vex.679 69 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack.680 69 myapp.area2 ERROR The five boxing wizards jump quickly.681```682683Обратите внимание, что в некоторых сценариях существуют проблемы безопасности с pickle. Если они вас затрагивают, вы можете использовать альтернативную схему сериализации, переопределив метод [`makePickle()`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.SocketHandler.makePickle) и реализовав свою альтернативу там, а также адаптировав вышеприведённый скрипт для использования вашей альтернативной сериализации.684685### Запуск сокетного слушателя логирования в продакшене686687Для запуска слушателя логирования в продакшене может потребоваться инструмент управления процессами, такой как [Supervisor](https://python-all.ru/3.14/howto/logging-cookbook.html). [Вот Gist](https://python-all.ru/3.14/howto/logging-cookbook.html), который содержит минимальные файлы для запуска описанной выше функциональности с помощью Supervisor. Он состоит из следующих файлов:688689| Файл | Назначение |690| --- | --- |691| `prepare.sh` | Bash-скрипт для подготовки окружения к тестированию |692| `supervisor.conf` | Файл конфигурации Supervisor с записями для слушателя и многопроцессного веб-приложения |693| `ensure_app.sh` | Bash-скрипт для обеспечения работы Supervisor с указанной конфигурацией |694| `log_listener.py` | Программа сокетного слушателя, которая получает события логирования и записывает их в файл |695| `main.py` | Простое веб-приложение, которое выполняет логирование через сокет, подключённый к слушателю |696| `webapp.json` | JSON-файл конфигурации для веб-приложения |697| `client.py` | Python-скрипт для тестирования веб-приложения |698699Веб-приложение использует [Gunicorn](https://python-all.ru/3.14/howto/logging-cookbook.html) – популярный сервер веб-приложений, который запускает несколько рабочих процессов для обработки запросов. Данный пример показывает, как рабочие процессы могут писать в один и тот же файл журнала, не мешая друг другу – все они проходят через сокетный слушатель.700701Чтобы протестировать эти файлы, выполните следующие действия в среде POSIX:7027031. Скачайте [Gist](https://python-all.ru/3.14/howto/logging-cookbook.html) в виде ZIP-архива, используя кнопку Download ZIP.7042. Распакуйте указанные файлы из архива во временный каталог.7053. Во временном каталоге выполните `bash prepare.sh` для подготовки. При этом будут созданы подкаталог `run` для файлов, связанных с Supervisor, и журналов, а также подкаталог `venv` для виртуального окружения, в которое будут установлены `bottle`, `gunicorn` и `supervisor`.7064. Запустите `bash ensure_app.sh`, чтобы убедиться, что Supervisor работает с указанной выше конфигурацией.7075. Запустите `venv/bin/python client.py` для проверки веб-приложения, что приведёт к записи данных в журнал.7086. Проверьте файлы журнала в подкаталоге `run`. Вы должны увидеть самые свежие строки журнала в файлах, соответствующих шаблону `app.log*`. Они не будут в каком-либо определённом порядке, так как были обработаны параллельно разными рабочими процессами недетерминированным образом.7097. Вы можете остановить слушатель и веб-приложение, выполнив `venv/bin/supervisorctl -c supervisor.conf shutdown`.710711Возможно, потребуется подправить файлы конфигурации в маловероятном случае, если настроенные порты конфликтуют с чем-либо ещё в вашей тестовой среде.712713В конфигурации по умолчанию используется TCP-сокет на порту 9020. Вы можете использовать сокет Unix Domain вместо TCP-сокета, выполнив следующее:7147151. В `listener.json` добавьте ключ `socket` с путём к доменному сокету, который вы хотите использовать. Если этот ключ присутствует, слушатель прослушивает соответствующий доменный сокет, а не TCP-сокет (ключ `port` игнорируется).7162. В `webapp.json` измените словарь конфигурации обработчика сокетов так, чтобы значением `host` был путь к доменному сокету, а значение `port` установите в `null`.717718## Добавление контекстной информации в вывод журнала719720Иногда требуется, чтобы вывод журнала содержал контекстную информацию в дополнение к параметрам, переданным в вызове логирования. Например, в сетевом приложении может быть желательно записывать в журнал информацию, специфичную для клиента (например, имя пользователя удалённого клиента или IP-адрес). Хотя для этого можно использовать параметр *extra*, не всегда удобно передавать информацию таким образом. Может возникнуть соблазн создавать экземпляры [`Logger`](https://python-all.ru/3.14/library/logging.html#logging.Logger) для каждого соединения, но это плохая идея, поскольку такие экземпляры не собираются сборщиком мусора. Хотя на практике это не проблема, когда количество экземпляров `Logger` зависит от уровня детализации, используемого при логировании приложения, управление ими может стать сложным, если количество экземпляров `Logger` станет фактически неограниченным.721722### Использование LoggerAdapter для добавления контекстной информации723724Простой способ передавать контекстную информацию для вывода вместе с информацией о событиях логирования – использовать класс [`LoggerAdapter`](https://python-all.ru/3.14/library/logging.html#logging.LoggerAdapter). Этот класс спроектирован так, чтобы выглядеть как [`Logger`](https://python-all.ru/3.14/library/logging.html#logging.Logger), что позволяет вызывать [`debug()`](https://python-all.ru/3.14/library/logging.html#logging.debug), [`info()`](https://python-all.ru/3.14/library/logging.html#logging.info), [`warning()`](https://python-all.ru/3.14/library/logging.html#logging.warning), [`error()`](https://python-all.ru/3.14/library/logging.html#logging.error), [`exception()`](https://python-all.ru/3.14/library/logging.html#logging.exception), [`critical()`](https://python-all.ru/3.14/library/logging.html#logging.critical) и [`log()`](https://python-all.ru/3.14/library/logging.html#logging.log). Эти методы имеют те же сигнатуры, что и их аналоги в `Logger`, поэтому экземпляры обоих типов можно использовать взаимозаменяемо.725726При создании экземпляра [`LoggerAdapter`](https://python-all.ru/3.14/library/logging.html#logging.LoggerAdapter) вы передаёте ему экземпляр [`Logger`](https://python-all.ru/3.14/library/logging.html#logging.Logger) и объект, подобный словарю, содержащий вашу контекстную информацию. Когда вы вызываете один из методов логирования на экземпляре `LoggerAdapter`, он делегирует вызов базовому экземпляру `Logger`, переданному в конструктор, и организует передачу контекстной информации в этом делегированном вызове. Вот фрагмент кода `LoggerAdapter`:727728```python729def debug(self, msg, /, *args, **kwargs):730 """731 Передаёт вызов отладки нижележащему регистратору после добавления732 контекстной информации из данного экземпляра адаптера.733 """734 msg, kwargs = self.process(msg, kwargs)735 self.logger.debug(msg, *args, **kwargs)736```737738Метод [`process()`](https://python-all.ru/3.14/library/logging.html#logging.LoggerAdapter.process) класса [`LoggerAdapter`](https://python-all.ru/3.14/library/logging.html#logging.LoggerAdapter) – это то место, где контекстная информация добавляется в вывод журнала. Ему передаются сообщение и именованные аргументы вызова логирования, а он возвращает (потенциально) изменённые версии для использования в вызове базового регистратора. В реализации по умолчанию этот метод оставляет сообщение без изменений, но вставляет ключ 'extra' в именованные аргументы, значением которого является объект, подобный словарю, переданный конструктору. Конечно, если вы передали именованный аргумент 'extra' в вызове адаптера, он будет молча перезаписан.739740Преимущество использования 'extra' в том, что значения из объекта, подобного словарю, сливаются в \_\_dict\_\_ экземпляра [`LogRecord`](https://python-all.ru/3.14/library/logging.html#logging.LogRecord), что позволяет использовать настроенные строки с экземплярами [`Formatter`](https://python-all.ru/3.14/library/logging.html#logging.Formatter), которые знают о ключах этого объекта. Если вам нужен другой метод, например, добавить контекстную информацию в начало или конец строки сообщения, достаточно создать подкласс [`LoggerAdapter`](https://python-all.ru/3.14/library/logging.html#logging.LoggerAdapter) и переопределить [`process()`](https://python-all.ru/3.14/library/logging.html#logging.LoggerAdapter.process) для нужного поведения. Вот простой пример:741742```python743class CustomAdapter(logging.LoggerAdapter):744 """745 Данный пример адаптера ожидает, что переданный объект, подобный словарю, содержит746 ключ 'connid', значение которого в квадратных скобках добавляется к началу сообщения журнала.747 """748 def process(self, msg, kwargs):749 return '[%s] %s' % (self.extra['connid'], msg), kwargs750```751752который можно использовать так:753754```python755logger = logging.getLogger(__name__)756adapter = CustomAdapter(logger, {'connid': some_conn_id})757```758759Тогда все события, регистрируемые через адаптер, будут содержать значение `some_conn_id`, добавленное в начало сообщений журнала.760761#### Использование объектов, отличных от словарей, для передачи контекстной информации762763Необязательно передавать в [`LoggerAdapter`](https://python-all.ru/3.14/library/logging.html#logging.LoggerAdapter) именно словарь – можно передать экземпляр класса, реализующего `__getitem__` и `__iter__`, чтобы он выглядел как словарь для системы логирования. Это полезно, если нужно генерировать значения динамически (тогда как значения в словаре были бы постоянными).764765### Использование фильтров для добавления контекстной информации766767Вы также можете добавлять контекстную информацию в вывод журнала с помощью определённого пользователем [`Filter`](https://python-all.ru/3.14/library/logging.html#logging.Filter). Экземплярам `Filter` разрешено изменять `LogRecords`, переданный им, включая добавление дополнительных атрибутов, которые затем можно выводить с помощью подходящей форматной строки или, если необходимо, пользовательского [`Formatter`](https://python-all.ru/3.14/library/logging.html#logging.Formatter).768769Например, в веб-приложении обрабатываемый запрос (или, по крайней мере, его интересные части) можно сохранить в потоковой локальной переменной ([`threading.local`](https://python-all.ru/3.14/library/threading.html#threading.local)), а затем из `Filter` получить к ней доступ, чтобы добавить, скажем, информацию из запроса – например, удалённый IP-адрес и имя пользователя – в `LogRecord`, используя имена атрибутов 'ip' и 'user', как в примере с `LoggerAdapter` выше. В этом случае можно использовать ту же форматную строку для получения вывода, аналогичного показанному выше. Вот пример скрипта:770771```python772import logging773from random import choice774775class ContextFilter(logging.Filter):776 """777 Это фильтр, который внедряет контекстную информацию в журнал.778779 Вместо использования реальной контекстной информации в данном примере используются случайные780 данные.781 """782783 USERS = ['jim', 'fred', 'sheila']784 IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']785786 def filter(self, record):787788 record.ip = choice(ContextFilter.IPS)789 record.user = choice(ContextFilter.USERS)790 return True791792if __name__ == '__main__':793 levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)794 logging.basicConfig(level=logging.DEBUG,795 format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')796 a1 = logging.getLogger('a.b.c')797 a2 = logging.getLogger('d.e.f')798799 f = ContextFilter()800 a1.addFilter(f)801 a2.addFilter(f)802 a1.debug('A debug message')803 a1.info('An info message with %s', 'some parameters')804 for x in range(10):805 lvl = choice(levels)806 lvlname = logging.getLevelName(lvl)807 a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')808```809810который при запуске выдаёт примерно следующее:811812```text8132010-09-06 22:38:15,292 a.b.c DEBUG IP: 123.231.231.123 User: fred A debug message8142010-09-06 22:38:15,300 a.b.c INFO IP: 192.168.0.1 User: sheila An info message with some parameters8152010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters8162010-09-06 22:38:15,300 d.e.f ERROR IP: 127.0.0.1 User: jim A message at ERROR level with 2 parameters8172010-09-06 22:38:15,300 d.e.f DEBUG IP: 127.0.0.1 User: sheila A message at DEBUG level with 2 parameters8182010-09-06 22:38:15,300 d.e.f ERROR IP: 123.231.231.123 User: fred A message at ERROR level with 2 parameters8192010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1 User: jim A message at CRITICAL level with 2 parameters8202010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters8212010-09-06 22:38:15,300 d.e.f DEBUG IP: 192.168.0.1 User: jim A message at DEBUG level with 2 parameters8222010-09-06 22:38:15,301 d.e.f ERROR IP: 127.0.0.1 User: sheila A message at ERROR level with 2 parameters8232010-09-06 22:38:15,301 d.e.f DEBUG IP: 123.231.231.123 User: fred A message at DEBUG level with 2 parameters8242010-09-06 22:38:15,301 d.e.f INFO IP: 123.231.231.123 User: fred A message at INFO level with 2 parameters825```826827## Использование `contextvars`828829Начиная с Python 3.7, модуль [`contextvars`](https://python-all.ru/3.14/library/contextvars.html#module-contextvars) предоставляет контекстно-локальное хранилище, которое работает как для [`threading`](https://python-all.ru/3.14/library/threading.html#module-threading), так и для [`asyncio`](https://python-all.ru/3.14/library/asyncio.html#module-asyncio) обработки. Этот тип хранилища может быть в целом предпочтительнее потоковых локальных переменных. Следующий пример показывает, как в многопоточной среде журналы могут наполняться контекстной информацией, например, атрибутами запросов, обрабатываемых веб-приложениями.830831Для иллюстрации предположим, что у вас есть разные веб-приложения, каждое независимо от других, но запущенные в одном процессе Python и использующие общую для них библиотеку. Как каждое из этих приложений может иметь собственный журнал, где все сообщения логирования из библиотеки (и другого кода обработки запросов) направляются в соответствующий файл журнала приложения, а также включают в журнал дополнительную контекстную информацию, такую как IP-адрес клиента, метод HTTP-запроса и имя пользователя?832833Предположим, что библиотеку можно смоделировать следующим кодом:834835```python836# webapplib.py837import logging838import time839840logger = logging.getLogger(__name__)841842def useful():843 # Просто представительное событие, зарегистрированное из библиотеки844 logger.debug('Hello from webapplib!')845 # Просто приостановить выполнение на некоторое время, чтобы дать возможность другим потокам поработать846 time.sleep(0.01)847```848849Мы можем смоделировать несколько веб-приложений с помощью двух простых классов, `Request` и `WebApp`. Они имитируют работу реальных многопоточных веб-приложений – каждый запрос обрабатывается отдельным потоком:850851```python852# main.py853import argparse854from contextvars import ContextVar855import logging856import os857from random import choice858import threading859import webapplib860861logger = logging.getLogger(__name__)862root = logging.getLogger()863root.setLevel(logging.DEBUG)864865class Request:866 """867 Простой фиктивный класс запроса, который просто хранит фиктивные метод HTTP-запроса,868 IP-адрес клиента и имя пользователя клиента869 """870 def __init__(self, method, ip, user):871 self.method = method872 self.ip = ip873 self.user = user874875# Фиктивный набор запросов, который будет использоваться в симуляции – мы будем просто выбирать876# из этого списка случайным образом. Обратите внимание, что все GET-запросы приходят с адресов 192.168.2.XXX877# адресов, тогда как POST-запросы – с адресов 192.16.3.XXX. В примере запросов представлены три пользователя878# представлены в примере запросов.879880REQUESTS = [881 Request('GET', '192.168.2.20', 'jim'),882 Request('POST', '192.168.3.20', 'fred'),883 Request('GET', '192.168.2.21', 'sheila'),884 Request('POST', '192.168.3.21', 'jim'),885 Request('GET', '192.168.2.22', 'fred'),886 Request('POST', '192.168.3.22', 'sheila'),887]888889# Обратите внимание, что строка форматирования содержит ссылки на контекстную информацию запроса890# такую как HTTP-метод, IP-адрес клиента и имя пользователя891892formatter = logging.Formatter('%(threadName)-11s %(appName)s %(name)-9s %(user)-6s %(ip)s %(method)-4s %(message)s')893894# Создаём контекстные переменные. Они будут заполнены в начале обработки запроса895# и использоваться в журналировании, которое выполняется в ходе этой обработки896897ctx_request = ContextVar('request')898ctx_appname = ContextVar('appname')899900class InjectingFilter(logging.Filter):901 """902 Фильтр, который внедряет в журналы контекстно-зависимую информацию и гарантирует,903 что в его журнал включается только информация для конкретного веб-приложения904 """905 def __init__(self, app):906 self.app = app907908 def filter(self, record):909 request = ctx_request.get()910 record.method = request.method911 record.ip = request.ip912 record.user = request.user913 record.appName = appName = ctx_appname.get()914 return appName == self.app.name915916class WebApp:917 """918 Фиктивный класс веб-приложения, который имеет собственный обработчик и фильтр для919 журнала, специфичного для веб-приложения.920 """921 def __init__(self, name):922 self.name = name923 handler = logging.FileHandler(name + '.log', 'w')924 f = InjectingFilter(self)925 handler.setFormatter(formatter)926 handler.addFilter(f)927 root.addHandler(handler)928 self.num_requests = 0929930 def process_request(self, request):931 """932 Это фиктивный метод обработки запроса. Он вызывается для933 отдельный поток для каждого запроса. Сохраняем информацию контекста в934 контекстные переменные перед тем, как делать что-либо ещё.935 """936 ctx_request.set(request)937 ctx_appname.set(self.name)938 self.num_requests += 1939 logger.debug('Request processing started')940 webapplib.useful()941 logger.debug('Request processing finished')942943def main():944 fn = os.path.splitext(os.path.basename(__file__))[0]945 adhf = argparse.ArgumentDefaultsHelpFormatter946 ap = argparse.ArgumentParser(formatter_class=adhf, prog=fn,947 description='Simulate a couple of web '948 'applications handling some '949 'requests, showing how request '950 'context can be used to '951 'populate logs')952 aa = ap.add_argument953 aa('--count', '-c', type=int, default=100, help='How many requests to simulate')954 options = ap.parse_args()955956 # Создаём фиктивные веб-приложения и помещаем их в список, из которого будем выбирать957 # случайным образом.958 app1 = WebApp('app1')959 app2 = WebApp('app2')960 apps = [app1, app2]961 threads = []962 # Добавляем общий обработчик, который будет перехватывать все события.963 handler = logging.FileHandler('app.log', 'w')964 handler.setFormatter(formatter)965 root.addHandler(handler)966967 # Генерируем вызовы для обработки запросов.968 for i in range(options.count):969 try:970 # Выбираем случайное приложение и запрос для него.971 app = choice(apps)972 request = choice(REQUESTS)973 # Обрабатываем запрос в его собственном потоке.974 t = threading.Thread(target=app.process_request, args=(request,))975 threads.append(t)976 t.start()977 except KeyboardInterrupt:978 break979980 # Ждём завершения потоков.981 for t in threads:982 t.join()983984 for app in apps:985 print('%s processed %s requests' % (app.name, app.num_requests))986987if __name__ == '__main__':988 main()989```990991Если запустить приведённый выше код, вы обнаружите, что примерно половина запросов попадает в `app1.log`, а остальные – в `app2.log`, и все запросы регистрируются в `app.log`. Каждый журнал, специфичный для веб-приложения, будет содержать только записи для этого приложения, а информация о запросе будет отображаться в журнале согласованно (т.е. информация каждого фиктивного запроса всегда будет появляться вместе в одной строке журнала). Это иллюстрируется следующим выводом оболочки:992993```shell994~/logging-contextual-webapp$ python main.py995app1 processed 51 requests996app2 processed 49 requests997~/logging-contextual-webapp$ wc -l *.log998 153 app1.log999 147 app2.log1000 300 app.log1001 600 total1002~/logging-contextual-webapp$ head -3 app1.log1003Thread-3 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1004Thread-3 (process_request) app1 webapplib jim 192.168.3.21 POST Hello from webapplib!1005Thread-5 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1006~/logging-contextual-webapp$ head -3 app2.log1007Thread-1 (process_request) app2 __main__ sheila 192.168.2.21 GET Request processing started1008Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET Hello from webapplib!1009Thread-2 (process_request) app2 __main__ jim 192.168.2.20 GET Request processing started1010~/logging-contextual-webapp$ head app.log1011Thread-1 (process_request) app2 __main__ sheila 192.168.2.21 GET Request processing started1012Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET Hello from webapplib!1013Thread-2 (process_request) app2 __main__ jim 192.168.2.20 GET Request processing started1014Thread-3 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1015Thread-2 (process_request) app2 webapplib jim 192.168.2.20 GET Hello from webapplib!1016Thread-3 (process_request) app1 webapplib jim 192.168.3.21 POST Hello from webapplib!1017Thread-4 (process_request) app2 __main__ fred 192.168.2.22 GET Request processing started1018Thread-5 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1019Thread-4 (process_request) app2 webapplib fred 192.168.2.22 GET Hello from webapplib!1020Thread-6 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1021~/logging-contextual-webapp$ grep app1 app1.log | wc -l10221531023~/logging-contextual-webapp$ grep app2 app2.log | wc -l10241471025~/logging-contextual-webapp$ grep app1 app.log | wc -l10261531027~/logging-contextual-webapp$ grep app2 app.log | wc -l10281471029```10301031## Добавление контекстной информации в обработчиках10321033Каждый [`Handler`](https://python-all.ru/3.14/library/logging.html#logging.Handler) имеет собственную цепочку фильтров. Если нужно добавить контекстную информацию в [`LogRecord`](https://python-all.ru/3.14/library/logging.html#logging.LogRecord) без её утечки в другие обработчики, можно использовать фильтр, возвращающий новый `LogRecord` вместо изменения исходного на месте, как показано в следующем скрипте:10341035```python1036import copy1037import logging10381039def filter(record: logging.LogRecord):1040 record = copy.copy(record)1041 record.user = 'jim'1042 return record10431044if __name__ == '__main__':1045 logger = logging.getLogger()1046 logger.setLevel(logging.INFO)1047 handler = logging.StreamHandler()1048 formatter = logging.Formatter('%(message)s from %(user)-8s')1049 handler.setFormatter(formatter)1050 handler.addFilter(filter)1051 logger.addHandler(handler)10521053 logger.info('A log message')1054```10551056## Ведение журнала в один файл из нескольких процессов10571058Хотя модуль logging является потокобезопасным и запись в один файл из нескольких потоков в одном процессе *поддерживается*, запись в один файл из *нескольких процессов* *не* поддерживается, поскольку в Python нет стандартного способа сериализовать доступ к одному файлу из нескольких процессов. Если нужно вести журнал в один файл из нескольких процессов, один из способов – сделать так, чтобы все процессы записывали данные в [`SocketHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.SocketHandler), а отдельный процесс реализовывал сокет-сервер, который читает из сокета и записывает в файл. (Если хотите, можно выделить один поток в одном из существующих процессов для выполнения этой функции.) [В этом разделе](https://python-all.ru/3.14/howto/logging-cookbook.html#network-logging) подробно описывается данный подход и приводится рабочий приёмник сокета, который можно использовать как отправную точку для адаптации в своих приложениях.10591060Вы также можете написать собственный обработчик, который использует класс [`Lock`](https://python-all.ru/3.14/library/multiprocessing.html#multiprocessing.Lock) из модуля [`multiprocessing`](https://python-all.ru/3.14/library/multiprocessing.html#module-multiprocessing) для сериализации доступа к файлу из ваших процессов. Стандартные библиотечные [`FileHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.FileHandler) и их подклассы не используют `multiprocessing`.10611062В качестве альтернативы можно использовать `Queue` и [`QueueHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.QueueHandler) для отправки всех событий журналирования одному из процессов в вашем многопроцессном приложении. В следующем примере сценария показано, как это сделать; в примере отдельный процесс-слушатель ожидает события, отправленные другими процессами, и регистрирует их в соответствии со своей собственной конфигурацией журналирования. Хотя пример демонстрирует лишь один из способов (например, вместо отдельного процесса-слушателя можно использовать поток-слушатель – реализация будет аналогичной), он позволяет задать полностью разные конфигурации журналирования для слушателя и остальных процессов в вашем приложении и может быть использован как основа для кода, отвечающего вашим конкретным требованиям:10631064```python1065# Вам понадобятся эти импорты в вашем коде.1066import logging1067import logging.handlers1068import multiprocessing10691070# Следующие две строки импорта только для этой демонстрации.1071from random import choice, random1072import time10731074#1075# Поскольку нужно задать настройки логирования для слушателя и рабочих процессов, функции1076# слушателя и рабочего процесса принимают параметр configurer – вызываемый объект для1077# настройки логирования этого процесса. Эти функции также получают очередь, которую1078# используют для взаимодействия.1079#1080# На практике слушателя можно настроить как угодно, но заметьте: в этом простом1081# примере слушатель не применяет логику уровней или фильтров к полученным записям.1082# На практике эту логику, вероятно, стоит вынести в рабочие процессы, чтобы не1083# пересылать между процессами события, которые всё равно будут отфильтрованы.1084#1085# Размер файлов при ротации намеренно сделан небольшим, чтобы результат был хорошо виден.1086def listener_configurer():1087 root = logging.getLogger()1088 h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)1089 f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')1090 h.setFormatter(f)1091 root.addHandler(h)10921093# Это главный цикл процесса-слушателя: ждём события логирования1094# (LogRecords) в очереди и обрабатываем их; завершаем работу, когда получаем None вместо1095# LogRecord.1096def listener_process(queue, configurer):1097 configurer()1098 while True:1099 try:1100 record = queue.get()1101 if record is None: # Отправляем это как сигнал завершения, чтобы слушатель остановился.1102 break1103 logger = logging.getLogger(record.name)1104 logger.handle(record) # Никакой логики уровней и фильтров – просто делаем дело!1105 except Exception:1106 import sys, traceback1107 print('Whoops! Problem:', file=sys.stderr)1108 traceback.print_exc(file=sys.stderr)11091110# Массивы для случайного выбора в этой демонстрации.11111112LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,1113 logging.ERROR, logging.CRITICAL]11141115LOGGERS = ['a.b.c', 'd.e.f']11161117MESSAGES = [1118 'Random message #1',1119 'Random message #2',1120 'Random message #3',1121]11221123# Настройка рабочего процесса выполняется в начале его работы.1124# Обратите внимание: в Windows нельзя полагаться на семантику fork, поэтому каждый процесс1125# будет выполнять код настройки логирования при запуске.1126def worker_configurer(queue):1127 h = logging.handlers.QueueHandler(queue) # Нужен только один обработчик.1128 root = logging.getLogger()1129 root.addHandler(h)1130 # Отправляем все сообщения для демонстрации; никакой другой логики уровней или фильтров.1131 root.setLevel(logging.DEBUG)11321133# Это главный цикл рабочего процесса, который просто логирует десять событий с1134# случайные задержки перед завершением.1135# Сообщения print нужны лишь для того, чтобы было видно, что программа работает.1136def worker_process(queue, configurer):1137 configurer(queue)1138 name = multiprocessing.current_process().name1139 print('Worker started: %s' % name)1140 for i in range(10):1141 time.sleep(random())1142 logger = logging.getLogger(choice(LOGGERS))1143 level = choice(LEVELS)1144 message = choice(MESSAGES)1145 logger.log(level, message)1146 print('Worker finished: %s' % name)11471148# Здесь организуется демонстрация. Создать очередь, создать и запустить1149# слушатель, создать десять рабочих процессов и запустить их, дождаться их завершения,1150# затем отправить None в очередь, чтобы сообщить слушателю о завершении.1151def main():1152 queue = multiprocessing.Queue(-1)1153 listener = multiprocessing.Process(target=listener_process,1154 args=(queue, listener_configurer))1155 listener.start()1156 workers = []1157 for i in range(10):1158 worker = multiprocessing.Process(target=worker_process,1159 args=(queue, worker_configurer))1160 workers.append(worker)1161 worker.start()1162 for w in workers:1163 w.join()1164 queue.put_nowait(None)1165 listener.join()11661167if __name__ == '__main__':1168 main()1169```11701171Вариант приведённого выше сценария оставляет ведение журнала в главном процессе, в отдельном потоке:11721173```python1174import logging1175import logging.config1176import logging.handlers1177from multiprocessing import Process, Queue1178import random1179import threading1180import time11811182def logger_thread(q):1183 while True:1184 record = q.get()1185 if record is None:1186 break1187 logger = logging.getLogger(record.name)1188 logger.handle(record)11891190def worker_process(q):1191 qh = logging.handlers.QueueHandler(q)1192 root = logging.getLogger()1193 root.setLevel(logging.DEBUG)1194 root.addHandler(qh)1195 levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1196 logging.CRITICAL]1197 loggers = ['foo', 'foo.bar', 'foo.bar.baz',1198 'spam', 'spam.ham', 'spam.ham.eggs']1199 for i in range(100):1200 lvl = random.choice(levels)1201 logger = logging.getLogger(random.choice(loggers))1202 logger.log(lvl, 'Message no. %d', i)12031204if __name__ == '__main__':1205 q = Queue()1206 d = {1207 'version': 1,1208 'formatters': {1209 'detailed': {1210 'class': 'logging.Formatter',1211 'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1212 }1213 },1214 'handlers': {1215 'console': {1216 'class': 'logging.StreamHandler',1217 'level': 'INFO',1218 },1219 'file': {1220 'class': 'logging.FileHandler',1221 'filename': 'mplog.log',1222 'mode': 'w',1223 'formatter': 'detailed',1224 },1225 'foofile': {1226 'class': 'logging.FileHandler',1227 'filename': 'mplog-foo.log',1228 'mode': 'w',1229 'formatter': 'detailed',1230 },1231 'errors': {1232 'class': 'logging.FileHandler',1233 'filename': 'mplog-errors.log',1234 'mode': 'w',1235 'level': 'ERROR',1236 'formatter': 'detailed',1237 },1238 },1239 'loggers': {1240 'foo': {1241 'handlers': ['foofile']1242 }1243 },1244 'root': {1245 'level': 'DEBUG',1246 'handlers': ['console', 'file', 'errors']1247 },1248 }1249 workers = []1250 for i in range(5):1251 wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))1252 workers.append(wp)1253 wp.start()1254 logging.config.dictConfig(d)1255 lp = threading.Thread(target=logger_thread, args=(q,))1256 lp.start()1257 # На этом этапе главный процесс может заняться своей полезной работой1258 # Когда он с этим закончит, он может дождаться завершения рабочих процессов...1259 for wp in workers:1260 wp.join()1261 # А теперь указать потоку журналирования завершиться1262 q.put(None)1263 lp.join()1264```12651266Этот вариант показывает, как можно, например, применить конфигурацию для определённых регистраторов – например, регистратор `foo` имеет специальный обработчик, который сохраняет все события подсистемы `foo` в файл `mplog-foo.log`. Это будет использовано механизмом журналирования в главном процессе (даже если события журналирования генерируются в рабочих процессах) для направления сообщений к соответствующим местам назначения.12671268### Использование concurrent.futures.ProcessPoolExecutor12691270Если вы хотите использовать [`concurrent.futures.ProcessPoolExecutor`](https://python-all.ru/3.14/library/concurrent.futures.html#concurrent.futures.ProcessPoolExecutor) для запуска рабочих процессов, необходимо создать очередь немного иначе. Вместо12711272```python1273queue = multiprocessing.Queue(-1)1274```12751276следует использовать12771278```python1279queue = multiprocessing.Manager().Queue(-1) # также работает с примерами выше1280```12811282и затем можно заменить создание рабочего процесса с этого:12831284```python1285workers = []1286for i in range(10):1287 worker = multiprocessing.Process(target=worker_process,1288 args=(queue, worker_configurer))1289 workers.append(worker)1290 worker.start()1291for w in workers:1292 w.join()1293```12941295на это (не забудьте сначала импортировать [`concurrent.futures`](https://python-all.ru/3.14/library/concurrent.futures.html#module-concurrent.futures)):12961297```python1298with concurrent.futures.ProcessPoolExecutor(max_workers=10) as executor:1299 for i in range(10):1300 executor.submit(worker_process, queue, worker_configurer)1301```13021303### Развёртывание веб-приложений с помощью Gunicorn и uWSGI13041305При развёртывании веб-приложений с помощью [Gunicorn](https://python-all.ru/3.14/howto/logging-cookbook.html) или [uWSGI](https://python-all.ru/3.14/howto/logging-cookbook.html) (или аналогичных инструментов) создаётся несколько рабочих процессов для обработки запросов клиентов. В таких средах следует избегать создания обработчиков, основанных на файлах, непосредственно в веб-приложении. Вместо этого используйте [`SocketHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.SocketHandler) для ведения журнала из веб-приложения в слушатель в отдельном процессе. Это можно настроить с помощью инструмента управления процессами, такого как Supervisor – подробнее см. [Запуск слушателя сокета журналирования в рабочей среде](https://python-all.ru/3.14/howto/logging-cookbook.html#running-a-logging-socket-listener-in-production).13061307## Использование ротации файлов13081309Иногда требуется позволить файлу журнала расти до определённого размера, затем открыть новый файл и вести запись в него. Может потребоваться сохранять определённое количество таких файлов, и когда будет создано заданное число файлов, выполнять ротацию, чтобы и количество, и размер файлов оставались в заданных границах. Для такого сценария использования пакет logging предоставляет [`RotatingFileHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.RotatingFileHandler):13101311```python1312import glob1313import logging1314import logging.handlers13151316LOG_FILENAME = 'logging_rotatingfile_example.out'13171318# Настроить конкретный регистратор с нужным уровнем вывода1319my_logger = logging.getLogger('MyLogger')1320my_logger.setLevel(logging.DEBUG)13211322# Добавить обработчик сообщений журнала в регистратор1323handler = logging.handlers.RotatingFileHandler(1324 LOG_FILENAME, maxBytes=20, backupCount=5)13251326my_logger.addHandler(handler)13271328# Записать несколько сообщений1329for i in range(20):1330 my_logger.debug('i = %d' % i)13311332# Посмотреть, какие файлы созданы1333logfiles = glob.glob('%s*' % LOG_FILENAME)13341335for filename in logfiles:1336 print(filename)1337```13381339В результате должно получиться 6 отдельных файлов, каждый из которых содержит часть истории журнала приложения:13401341```text1342logging_rotatingfile_example.out1343logging_rotatingfile_example.out.11344logging_rotatingfile_example.out.21345logging_rotatingfile_example.out.31346logging_rotatingfile_example.out.41347logging_rotatingfile_example.out.51348```13491350Самый свежий файл всегда называется `logging_rotatingfile_example.out`, и каждый раз при достижении ограничения по размеру он переименовывается с суффиксом `.1`. Каждый из существующих резервных файлов переименовывается с увеличением суффикса (`.1` становится `.2` и т.д.), а файл `.6` удаляется.13511352Разумеется, в этом примере размер файла журнала установлен слишком маленьким для наглядности. В реальности нужно установить *maxBytes* в подходящее значение.13531354## Использование альтернативных стилей форматирования13551356Когда журналирование было добавлено в стандартную библиотеку Python, единственным способом форматирования сообщений с переменным содержимым было использование %-форматирования. С тех пор в Python появились два новых подхода к форматированию: [`string.Template`](https://python-all.ru/3.14/library/string.html#string.Template) (добавлен в Python 2.4) и [`str.format()`](https://python-all.ru/3.14/library/stdtypes.html#str.format) (добавлен в Python 2.6).13571358Начиная с версии 3.2, модуль logging предоставляет улучшенную поддержку этих двух дополнительных стилей форматирования. Класс [`Formatter`](https://python-all.ru/3.14/library/logging.html#logging.Formatter) был расширен: добавлен дополнительный необязательный именованный параметр `style`. По умолчанию он равен `'%'`, но возможны также значения `'{'` и `'$'`, соответствующие двум другим стилям форматирования. Обратная совместимость сохраняется по умолчанию (как и следовало ожидать), но при явном указании параметра style появляется возможность задавать строки формата, работающие с [`str.format()`](https://python-all.ru/3.14/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.14/library/string.html#string.Template). Вот пример сеанса работы в консоли, демонстрирующий возможности:13591360```pycon1361>>> import logging1362>>> root = logging.getLogger()1363>>> root.setLevel(logging.DEBUG)1364>>> handler = logging.StreamHandler()1365>>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}',1366... style='{')1367>>> handler.setFormatter(bf)1368>>> root.addHandler(handler)1369>>> logger = logging.getLogger('foo.bar')1370>>> logger.debug('This is a DEBUG message')13712010-10-28 15:11:55,341 foo.bar DEBUG This is a DEBUG message1372>>> logger.critical('This is a CRITICAL message')13732010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message1374>>> df = logging.Formatter('$asctime $name ${levelname} $message',1375... style='$')1376>>> handler.setFormatter(df)1377>>> logger.debug('This is a DEBUG message')13782010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message1379>>> logger.critical('This is a CRITICAL message')13802010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message1381>>>1382```13831384Обратите внимание: форматирование сообщений журнала для конечного вывода в файлы совершенно не зависит от того, как конструируется отдельное сообщение. Оно по-прежнему может использовать %-форматирование, как показано ниже:13851386```python1387>>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')13882010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message1389>>>1390```13911392Вызовы функций журналирования (`logger.debug()`, `logger.info()` и т.д.) принимают только позиционные параметры для самого сообщения журнала; именованные параметры используются только для определения параметров обработки вызова (например, именованный параметр `exc_info` указывает, что нужно записать информацию о трассировке стека, или именованный параметр `extra` – добавить дополнительный контекст в журнал). Поэтому невозможно напрямую использовать синтаксис [`str.format()`](https://python-all.ru/3.14/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.14/library/string.html#string.Template) при вызовах, поскольку внутри пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Изменить это без нарушения обратной совместимости нельзя, так как все существующие вызовы logging в существующем коде используют %-формат строк.13931394Однако существует способ использовать {}- и $-форматирование для построения отдельных сообщений журнала. Напомним, что в качестве строки формата сообщения можно использовать произвольный объект, и пакет logging вызовет у этого объекта `str()` для получения фактической строки формата. Рассмотрим следующие два класса:13951396```python1397class BraceMessage:1398 def __init__(self, fmt, /, *args, **kwargs):1399 self.fmt = fmt1400 self.args = args1401 self.kwargs = kwargs14021403 def __str__(self):1404 return self.fmt.format(*self.args, **self.kwargs)14051406class DollarMessage:1407 def __init__(self, fmt, /, **kwargs):1408 self.fmt = fmt1409 self.kwargs = kwargs14101411 def __str__(self):1412 from string import Template1413 return Template(self.fmt).substitute(**self.kwargs)1414```14151416Любой из этих классов можно использовать вместо строки формата, чтобы разрешить применение {}- или $-форматирования для построения фактической части «message», которая появляется в отформатированном выводе журнала вместо «%(message)s», «{message}» или «$message». Это немного громоздко – использовать имена классов каждый раз при журналировании, но вполне приемлемо, если применить псевдоним, например \_\_ (двойное подчеркивание – не путать с \_, одинарным подчеркиванием, используемым как синоним/псевдоним для [`gettext.gettext()`](https://python-all.ru/3.14/library/gettext.html#gettext.gettext) или его аналогов).14171418Вышеуказанные классы не входят в состав Python, но их легко скопировать и вставить в свой код. Их можно использовать следующим образом (предполагая, что они объявлены в модуле с именем `wherever`):14191420```pycon1421>>> from wherever import BraceMessage as __1422>>> print(__('Message with {0} {name}', 2, name='placeholders'))1423Message with 2 placeholders1424>>> class Point: pass1425...1426>>> p = Point()1427>>> p.x = 0.51428>>> p.y = 0.51429>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})',1430... point=p))1431Message with coordinates: (0.50, 0.50)1432>>> from wherever import DollarMessage as __1433>>> print(__('Message with $num $what', num=2, what='placeholders'))1434Message with 2 placeholders1435>>>1436```14371438Хотя в приведённых выше примерах используется `print()` для демонстрации работы форматирования, в реальности для ведения журнала с помощью этого подхода следует использовать `logger.debug()` или аналогичную функцию.14391440Стоит отметить, что этот подход не приводит к существенному снижению производительности: собственно форматирование происходит не в момент вызова журналирования, а когда (и если) сообщение действительно должно быть выведено в журнал обработчиком. Так что единственная необычная деталь, которая может вызвать затруднение, – это то, что круглые скобки охватывают строку формата вместе с аргументами, а не только строку формата. Это объясняется тем, что запись \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов `XXXMessage`.14411442Если хотите, можно использовать [`LoggerAdapter`](https://python-all.ru/3.14/library/logging.html#logging.LoggerAdapter) для достижения аналогичного эффекта, как в следующем примере:14431444```python1445import logging14461447class Message:1448 def __init__(self, fmt, args):1449 self.fmt = fmt1450 self.args = args14511452 def __str__(self):1453 return self.fmt.format(*self.args)14541455class StyleAdapter(logging.LoggerAdapter):1456 def log(self, level, msg, /, *args, stacklevel=1, **kwargs):1457 if self.isEnabledFor(level):1458 msg, kwargs = self.process(msg, kwargs)1459 self.logger.log(level, Message(msg, args), **kwargs,1460 stacklevel=stacklevel+1)14611462logger = StyleAdapter(logging.getLogger(__name__))14631464def main():1465 logger.debug('Hello, {}', 'world!')14661467if __name__ == '__main__':1468 logging.basicConfig(level=logging.DEBUG)1469 main()1470```14711472Приведённый выше сценарий должен записать в журнал сообщение `Hello, world!` при запуске с Python 3.8 или новее.14731474## Настройка `LogRecord`14751476Каждое событие журналирования представлено экземпляром [`LogRecord`](https://python-all.ru/3.14/library/logging.html#logging.LogRecord). Когда событие регистрируется и не отфильтровывается по уровню регистратора, создаётся `LogRecord`, заполняется информацией о событии и затем передаётся обработчикам для этого регистратора (и его предков, вплоть до регистратора, в котором дальнейшее распространение по иерархии отключено). До Python 3.2 было только два места, где выполнялось это создание:14771478- [`Logger.makeRecord()`](https://python-all.ru/3.14/library/logging.html#logging.Logger.makeRecord), который вызывается в обычном процессе регистрации события. Он напрямую вызывал [`LogRecord`](https://python-all.ru/3.14/library/logging.html#logging.LogRecord) для создания экземпляра.1479- [`makeLogRecord()`](https://python-all.ru/3.14/library/logging.html#logging.makeLogRecord), которая вызывается со словарем, содержащим атрибуты для добавления в LogRecord. Обычно она вызывается, когда подходящий словарь был получен по сети (например, в виде pickle через [`SocketHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.SocketHandler) или в формате JSON через [`HTTPHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.HTTPHandler)).14801481Обычно это означало, что если требуется выполнить какие-либо специальные действия с [`LogRecord`](https://python-all.ru/3.14/library/logging.html#logging.LogRecord), приходилось делать одно из следующего.14821483- Создать собственный подкласс [`Logger`](https://python-all.ru/3.14/library/logging.html#logging.Logger), который переопределяет [`Logger.makeRecord()`](https://python-all.ru/3.14/library/logging.html#logging.Logger.makeRecord), и установить его с помощью [`setLoggerClass()`](https://python-all.ru/3.14/library/logging.html#logging.setLoggerClass) до того, как будут созданы какие-либо логгеры, которые вас интересуют.1484- Добавить [`Filter`](https://python-all.ru/3.14/library/logging.html#logging.Filter) к логгеру или обработчику, который выполняет необходимые специальные манипуляции при вызове его метода [`filter()`](https://python-all.ru/3.14/library/logging.html#logging.Filter.filter).14851486Первый подход был бы несколько громоздким в сценарии, где (скажем) несколько разных библиотек хотели бы делать разные вещи. Каждая попыталась бы установить свой собственный подкласс [`Logger`](https://python-all.ru/3.14/library/logging.html#logging.Logger), и та, которая сделала это последней, победила бы.14871488Второй подход достаточно хорошо работает во многих случаях, но не позволяет, например, использовать специализированный подкласс [`LogRecord`](https://python-all.ru/3.14/library/logging.html#logging.LogRecord). Разработчики библиотек могут установить подходящий фильтр на своих логгерах, но им приходилось бы помнить об этом каждый раз, когда они добавляют новый логгер (что они делают, просто добавляя новые пакеты или модули и выполняя14891490```python1491logger = logging.getLogger(__name__)1492```14931494на уровне модуля). Вероятно, это одна из тех вещей, о которых нужно помнить. Разработчики также могли бы добавить фильтр к [`NullHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.NullHandler), прикрепленному к их корневому логгеру, но он не будет вызываться, если разработчик приложения прикрепит обработчик к логгеру библиотеки нижнего уровня – так что вывод от этого обработчика не будет отражать намерений разработчика библиотеки.14951496В Python 3.2 и новее создание [`LogRecord`](https://python-all.ru/3.14/library/logging.html#logging.LogRecord) осуществляется через фабрику, которую можно указать. Фабрика – это просто вызываемый объект, который можно установить с помощью [`setLogRecordFactory()`](https://python-all.ru/3.14/library/logging.html#logging.setLogRecordFactory) и запросить с помощью [`getLogRecordFactory()`](https://python-all.ru/3.14/library/logging.html#logging.getLogRecordFactory). Фабрика вызывается с той же сигнатурой, что и конструктор `LogRecord`, поскольку [`LogRecord`](https://python-all.ru/3.14/library/logging.html#logging.LogRecord) является значением по умолчанию для фабрики.14971498Этот подход позволяет пользовательской фабрике контролировать все аспекты создания LogRecord. Например, можно вернуть подкласс или просто добавить несколько дополнительных атрибутов к записи после ее создания, используя шаблон, подобный следующему:14991500```python1501old_factory = logging.getLogRecordFactory()15021503def record_factory(*args, **kwargs):1504 record = old_factory(*args, **kwargs)1505 record.custom_attribute = 0xdecafbad1506 return record15071508logging.setLogRecordFactory(record_factory)1509```15101511Этот шаблон позволяет разным библиотекам объединять фабрики в цепочку, и пока они не перезаписывают атрибуты друг друга или случайно не перезаписывают стандартные атрибуты, никаких сюрпризов быть не должно. Однако следует иметь в виду, что каждое звено цепочки добавляет накладные расходы во время выполнения ко всем операциям логирования, и эту технику следует использовать только тогда, когда использование [`Filter`](https://python-all.ru/3.14/library/logging.html#logging.Filter) не дает желаемого результата.15121513## Создание подклассов QueueHandler и QueueListener – пример с ZeroMQ15141515### Подкласс `QueueHandler`15161517Можно использовать подкласс [`QueueHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.QueueHandler) для отправки сообщений в очереди других типов, например, в сокет ZeroMQ «publish». В приведенном ниже примере сокет создается отдельно и передается обработчику (в качестве его «очереди»):15181519```python1520import zmq # с использованием pyzmq, привязки Python к ZeroMQ1521import json # для переносимой сериализации записей15221523ctx = zmq.Context()1524sock = zmq.Socket(ctx, zmq.PUB) # или zmq.PUSH, или другое подходящее значение1525sock.bind('tcp://*:5556') # или где угодно15261527class ZeroMQSocketHandler(QueueHandler):1528 def enqueue(self, record):1529 self.queue.send_json(record.__dict__)15301531handler = ZeroMQSocketHandler(sock)1532```15331534Конечно, есть и другие способы организации этого, например, передача данных, необходимых обработчику для создания сокета:15351536```python1537class ZeroMQSocketHandler(QueueHandler):1538 def __init__(self, uri, socktype=zmq.PUB, ctx=None):1539 self.ctx = ctx or zmq.Context()1540 socket = zmq.Socket(self.ctx, socktype)1541 socket.bind(uri)1542 super().__init__(socket)15431544 def enqueue(self, record):1545 self.queue.send_json(record.__dict__)15461547 def close(self):1548 self.queue.close()1549```15501551### Подкласс `QueueListener`15521553Можно также создать подкласс [`QueueListener`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.QueueListener) для получения сообщений из очередей других типов, например, из сокета ZeroMQ «subscribe». Вот пример:15541555```python1556class ZeroMQSocketListener(QueueListener):1557 def __init__(self, uri, /, *handlers, **kwargs):1558 self.ctx = kwargs.get('ctx') or zmq.Context()1559 socket = zmq.Socket(self.ctx, zmq.SUB)1560 socket.setsockopt_string(zmq.SUBSCRIBE, '') # подписаться на всё1561 socket.connect(uri)1562 super().__init__(socket, *handlers, **kwargs)15631564 def dequeue(self):1565 msg = self.queue.recv_json()1566 return logging.makeLogRecord(msg)1567```15681569## Создание подклассов QueueHandler и QueueListener – пример с `pynng`15701571Подобно предыдущему разделу, можно реализовать прослушиватель и обработчик с помощью [pynng](https://python-all.ru/3.14/howto/logging-cookbook.html), который является привязкой Python к [NNG](https://python-all.ru/3.14/howto/logging-cookbook.html), позиционируемой как духовный преемник ZeroMQ. Следующие фрагменты кода иллюстрируют это – их можно протестировать в среде, где установлен `pynng`. Для разнообразия сначала приводим прослушиватель.15721573### Подкласс `QueueListener`15741575```python1576# listener.py1577import json1578import logging1579import logging.handlers15801581import pynng15821583DEFAULT_ADDR = "tcp://localhost:13232"15841585interrupted = False15861587class NNGSocketListener(logging.handlers.QueueListener):15881589 def __init__(self, uri, /, *handlers, **kwargs):1590 # Установить тайм-аут для возможности прерывания и открыть1591 # сокет подписчика1592 socket = pynng.Sub0(listen=uri, recv_timeout=500)1593 # Подписка b'' соответствует всем темам1594 topics = kwargs.pop('topics', None) or b''1595 socket.subscribe(topics)1596 # Используем сокет как очередь1597 super().__init__(socket, *handlers, **kwargs)15981599 def dequeue(self, block):1600 data = None1601 # Продолжать цикл, пока не прерван и не получены данные через1602 # сокет1603 while not interrupted:1604 try:1605 data = self.queue.recv(block=block)1606 break1607 except pynng.Timeout:1608 pass1609 except pynng.Closed: # иногда происходит при нажатии Ctrl-C1610 break1611 if data is None:1612 return None1613 # Получить событие журнала, отправленное издателем1614 event = json.loads(data.decode('utf-8'))1615 return logging.makeLogRecord(event)16161617 def enqueue_sentinel(self):1618 # Не используется в этой реализации, так как сокет на самом деле не является1619 # очередь1620 pass16211622logging.getLogger('pynng').propagate = False1623listener = NNGSocketListener(DEFAULT_ADDR, logging.StreamHandler(), topics=b'')1624listener.start()1625print('Press Ctrl-C to stop.')1626try:1627 while True:1628 pass1629except KeyboardInterrupt:1630 interrupted = True1631finally:1632 listener.stop()1633```16341635### Подкласс `QueueHandler`16361637```python1638# sender.py1639import json1640import logging1641import logging.handlers1642import time1643import random16441645import pynng16461647DEFAULT_ADDR = "tcp://localhost:13232"16481649class NNGSocketHandler(logging.handlers.QueueHandler):16501651 def __init__(self, uri):1652 socket = pynng.Pub0(dial=uri, send_timeout=500)1653 super().__init__(socket)16541655 def enqueue(self, record):1656 # Отправить запись в виде JSON с кодировкой UTF-81657 d = dict(record.__dict__)1658 data = json.dumps(d)1659 self.queue.send(data.encode('utf-8'))16601661 def close(self):1662 self.queue.close()16631664logging.getLogger('pynng').propagate = False1665handler = NNGSocketHandler(DEFAULT_ADDR)1666# Убедиться, что идентификатор процесса присутствует в выводе1667logging.basicConfig(level=logging.DEBUG,1668 handlers=[logging.StreamHandler(), handler],1669 format='%(levelname)-8s %(name)10s %(process)6s %(message)s')1670levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1671 logging.CRITICAL)1672logger_names = ('myapp', 'myapp.lib1', 'myapp.lib2')1673msgno = 11674while True:1675 # Просто случайным образом выбирать несколько регистраторов и уровней и вести запись1676 level = random.choice(levels)1677 logger = logging.getLogger(random.choice(logger_names))1678 logger.log(level, 'Message no. %5d' % msgno)1679 msgno += 11680 delay = random.random() * 2 + 0.51681 time.sleep(delay)1682```16831684Можно выполнить два указанных выше фрагмента в отдельных командных оболочках. Если запустить прослушиватель в одной оболочке, а отправителя – в двух отдельных оболочках, должно получиться что-то вроде следующего. В первой оболочке отправителя:16851686```console1687$ python sender.py1688DEBUG myapp 613 Message no. 11689WARNING myapp.lib2 613 Message no. 21690CRITICAL myapp.lib2 613 Message no. 31691WARNING myapp.lib2 613 Message no. 41692CRITICAL myapp.lib1 613 Message no. 51693DEBUG myapp 613 Message no. 61694CRITICAL myapp.lib1 613 Message no. 71695INFO myapp.lib1 613 Message no. 81696(and so on)1697```16981699Во второй оболочке отправителя:17001701```console1702$ python sender.py1703INFO myapp.lib2 657 Message no. 11704CRITICAL myapp.lib2 657 Message no. 21705CRITICAL myapp 657 Message no. 31706CRITICAL myapp.lib1 657 Message no. 41707INFO myapp.lib1 657 Message no. 51708WARNING myapp.lib2 657 Message no. 61709CRITICAL myapp 657 Message no. 71710DEBUG myapp.lib1 657 Message no. 81711(and so on)1712```17131714В оболочке прослушивателя:17151716```console1717$ python listener.py1718Press Ctrl-C to stop.1719DEBUG myapp 613 Message no. 11720WARNING myapp.lib2 613 Message no. 21721INFO myapp.lib2 657 Message no. 11722CRITICAL myapp.lib2 613 Message no. 31723CRITICAL myapp.lib2 657 Message no. 21724CRITICAL myapp 657 Message no. 31725WARNING myapp.lib2 613 Message no. 41726CRITICAL myapp.lib1 613 Message no. 51727CRITICAL myapp.lib1 657 Message no. 41728INFO myapp.lib1 657 Message no. 51729DEBUG myapp 613 Message no. 61730WARNING myapp.lib2 657 Message no. 61731CRITICAL myapp 657 Message no. 71732CRITICAL myapp.lib1 613 Message no. 71733INFO myapp.lib1 613 Message no. 81734DEBUG myapp.lib1 657 Message no. 81735(and so on)1736```17371738Как видно, записи журнала от двух процессов-отправителей перемежаются в выводе прослушивателя.17391740## Пример конфигурации на основе словаря17411742Ниже приведен пример словаря конфигурации логирования – он взят из [документации проекта Django](https://python-all.ru/3.14/howto/logging-cookbook.html). Этот словарь передается в [`dictConfig()`](https://python-all.ru/3.14/library/logging.config.html#logging.config.dictConfig) для применения конфигурации:17431744```python1745LOGGING = {1746 'version': 1,1747 'disable_existing_loggers': False,1748 'formatters': {1749 'verbose': {1750 'format': '{levelname} {asctime} {module} {process:d} {thread:d} {message}',1751 'style': '{',1752 },1753 'simple': {1754 'format': '{levelname} {message}',1755 'style': '{',1756 },1757 },1758 'filters': {1759 'special': {1760 '()': 'project.logging.SpecialFilter',1761 'foo': 'bar',1762 },1763 },1764 'handlers': {1765 'console': {1766 'level': 'INFO',1767 'class': 'logging.StreamHandler',1768 'formatter': 'simple',1769 },1770 'mail_admins': {1771 'level': 'ERROR',1772 'class': 'django.utils.log.AdminEmailHandler',1773 'filters': ['special']1774 }1775 },1776 'loggers': {1777 'django': {1778 'handlers': ['console'],1779 'propagate': True,1780 },1781 'django.request': {1782 'handlers': ['mail_admins'],1783 'level': 'ERROR',1784 'propagate': False,1785 },1786 'myproject.custom': {1787 'handlers': ['console', 'mail_admins'],1788 'level': 'INFO',1789 'filters': ['special']1790 }1791 }1792}1793```17941795Для получения дополнительной информации об этой конфигурации можно обратиться к [соответствующему разделу](https://python-all.ru/3.14/howto/logging-cookbook.html) документации Django.17961797## Использование ротатора и средства именования для настройки обработки ротации журналов17981799Пример того, как можно определить именователя и ротатора, приведен в следующем исполняемом скрипте, который показывает сжатие gzip файла журнала:18001801```python1802import gzip1803import logging1804import logging.handlers1805import os1806import shutil18071808def namer(name):1809 return name + ".gz"18101811def rotator(source, dest):1812 with open(source, 'rb') as f_in:1813 with gzip.open(dest, 'wb') as f_out:1814 shutil.copyfileobj(f_in, f_out)1815 os.remove(source)18161817rh = logging.handlers.RotatingFileHandler('rotated.log', maxBytes=128, backupCount=5)1818rh.rotator = rotator1819rh.namer = namer18201821root = logging.getLogger()1822root.setLevel(logging.INFO)1823root.addHandler(rh)1824f = logging.Formatter('%(asctime)s %(message)s')1825rh.setFormatter(f)1826for i in range(1000):1827 root.info(f'Message no. {i + 1}')1828```18291830После запуска будут созданы шесть новых файлов, пять из которых сжаты:18311832```console1833$ ls rotated.log*1834rotated.log rotated.log.2.gz rotated.log.4.gz1835rotated.log.1.gz rotated.log.3.gz rotated.log.5.gz1836$ zcat rotated.log.1.gz18372023-01-20 02:28:17,767 Message no. 99618382023-01-20 02:28:17,767 Message no. 99718392023-01-20 02:28:17,767 Message no. 9981840```18411842## Более сложный пример с многопроцессностью18431844Следующий рабочий пример показывает, как можно использовать логирование с многопроцессностью с помощью файлов конфигурации. Конфигурации довольно просты, но служат иллюстрацией того, как можно реализовать более сложные в реальном сценарии многопроцессной обработки.18451846В примере главный процесс порождает процесс-слушатель и несколько рабочих процессов. Каждый из главного процесса, слушателя и рабочих имеет три отдельные конфигурации (все рабочие используют одну и ту же конфигурацию). Видно ведение журнала в главном процессе, как рабочие пишут в QueueHandler, а слушатель реализует QueueListener и более сложную конфигурацию ведения журнала, и организует отправку событий, полученных через очередь, обработчикам, указанным в конфигурации. Обратите внимание, что эти конфигурации чисто иллюстративные, но этот пример можно адаптировать под свой сценарий.18471848Вот скрипт – строки документации и комментарии, надеюсь, поясняют, как он работает:18491850```python1851import logging1852import logging.config1853import logging.handlers1854from multiprocessing import Process, Queue, Event, current_process1855import os1856import random1857import time18581859class MyHandler:1860 """1861 Простой обработчик для событий логирования. Он выполняется в процессе-слушателе и1862 распределяет события по логгерам на основе имени в полученной записи,1863 которые затем передаются системой логирования обработчикам,1864 настроенным для этих логгеров.1865 """18661867 def handle(self, record):1868 if record.name == "root":1869 logger = logging.getLogger()1870 else:1871 logger = logging.getLogger(record.name)18721873 if logger.isEnabledFor(record.levelno):1874 # Имя процесса преобразуется только для того, чтобы показать, что это слушатель1875 # выполняет логирование в файлы и консоль.1876 record.processName = '%s (for %s)' % (current_process().name, record.processName)1877 logger.handle(record)18781879def listener_process(q, stop_event, config):1880 """1881 Это можно было бы сделать в главном процессе, но сделано в отдельном1882 процессе для наглядности.18831884 Это инициализирует логирование согласно указанной конфигурации1885 запускает слушатель и ожидает сигнала от главного процесса о завершении1886 через событие. Затем слушатель останавливается, и процесс завершается.1887 """1888 logging.config.dictConfig(config)1889 listener = logging.handlers.QueueListener(q, MyHandler())1890 listener.start()1891 if os.name == 'posix':1892 # В POSIX логгер setup уже был настроен в1893 # родительском процессе, но должен был быть отключён после вызова1894 # dictConfig.1895 # В Windows, поскольку fork не используется, логгер setup не будет1896 # существовать в дочернем процессе, поэтому он будет создан, и сообщение1897 # появится – отсюда и конструкция "if posix".1898 logger = logging.getLogger('setup')1899 logger.critical('Should not appear, because of disabled logger ...')1900 stop_event.wait()1901 listener.stop()19021903def worker_process(config):1904 """1905 Некоторое количество таких процессов порождается для иллюстрации. На1906 практике это могла бы быть разнородная группа процессов, а не1907 идентичные друг другу.19081909 Это инициализирует логирование согласно указанной конфигурации1910 и записывает сотню сообщений со случайными уровнями в случайно выбранные1911 логгеры.19121913 Добавлена небольшая задержка, чтобы дать другим процессам шанс выполниться. Это1914 не является строго необходимым, но позволяет немного перемешать вывод от разных1915 процессов больше, чем если бы её не было.1916 """1917 logging.config.dictConfig(config)1918 levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1919 logging.CRITICAL]1920 loggers = ['foo', 'foo.bar', 'foo.bar.baz',1921 'spam', 'spam.ham', 'spam.ham.eggs']1922 if os.name == 'posix':1923 # В POSIX логгер setup уже был настроен в1924 # родительском процессе, но должен был быть отключён после вызова1925 # dictConfig.1926 # В Windows, поскольку fork не используется, логгер setup не будет1927 # существовать в дочернем процессе, поэтому он будет создан, и сообщение1928 # появится – отсюда и конструкция "if posix".1929 logger = logging.getLogger('setup')1930 logger.critical('Should not appear, because of disabled logger ...')1931 for i in range(100):1932 lvl = random.choice(levels)1933 logger = logging.getLogger(random.choice(loggers))1934 logger.log(lvl, 'Message no. %d', i)1935 time.sleep(0.01)19361937def main():1938 q = Queue()1939 # Главный процесс получает простую конфигурацию, которая выводит информацию в консоль.1940 config_initial = {1941 'version': 1,1942 'handlers': {1943 'console': {1944 'class': 'logging.StreamHandler',1945 'level': 'INFO'1946 }1947 },1948 'root': {1949 'handlers': ['console'],1950 'level': 'DEBUG'1951 }1952 }1953 # Конфигурация рабочего процесса представляет собой QueueHandler, прикреплённый к1954 # корневому логгеру, что позволяет отправлять все сообщения в очередь.1955 # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1956 # родительском процессе. Это необходимо в POSIX, потому что логгер будет1957 # присутствовать в дочернем процессе после вызова fork().1958 config_worker = {1959 'version': 1,1960 'disable_existing_loggers': True,1961 'handlers': {1962 'queue': {1963 'class': 'logging.handlers.QueueHandler',1964 'queue': q1965 }1966 },1967 'root': {1968 'handlers': ['queue'],1969 'level': 'DEBUG'1970 }1971 }1972 # Конфигурация процесса-слушателя показывает, что вся гибкость1973 # конфигурации логирования доступна для отправки событий обработчикам так, как1974 # требуется.1975 # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1976 # родительском процессе. Это необходимо в POSIX, потому что логгер будет1977 # присутствовать в дочернем процессе после вызова fork().1978 config_listener = {1979 'version': 1,1980 'disable_existing_loggers': True,1981 'formatters': {1982 'detailed': {1983 'class': 'logging.Formatter',1984 'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1985 },1986 'simple': {1987 'class': 'logging.Formatter',1988 'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1989 }1990 },1991 'handlers': {1992 'console': {1993 'class': 'logging.StreamHandler',1994 'formatter': 'simple',1995 'level': 'INFO'1996 },1997 'file': {1998 'class': 'logging.FileHandler',1999 'filename': 'mplog.log',2000 'mode': 'w',2001 'formatter': 'detailed'2002 },2003 'foofile': {2004 'class': 'logging.FileHandler',2005 'filename': 'mplog-foo.log',2006 'mode': 'w',2007 'formatter': 'detailed'2008 },2009 'errors': {2010 'class': 'logging.FileHandler',2011 'filename': 'mplog-errors.log',2012 'mode': 'w',2013 'formatter': 'detailed',2014 'level': 'ERROR'2015 }2016 },2017 'loggers': {2018 'foo': {2019 'handlers': ['foofile']2020 }2021 },2022 'root': {2023 'handlers': ['console', 'file', 'errors'],2024 'level': 'DEBUG'2025 }2026 }2027 # Записываем несколько начальных событий, просто чтобы показать, что логирование в родительском процессе работает2028 # нормально.2029 logging.config.dictConfig(config_initial)2030 logger = logging.getLogger('setup')2031 logger.info('About to create workers ...')2032 workers = []2033 for i in range(5):2034 wp = Process(target=worker_process, name='worker %d' % (i + 1),2035 args=(config_worker,))2036 workers.append(wp)2037 wp.start()2038 logger.info('Started worker: %s', wp.name)2039 logger.info('About to create listener ...')2040 stop_event = Event()2041 lp = Process(target=listener_process, name='listener',2042 args=(q, stop_event, config_listener))2043 lp.start()2044 logger.info('Started listener')2045 # Теперь ожидаем завершения работы рабочих процессов.2046 for wp in workers:2047 wp.join()2048 # Все рабочие процессы завершены, теперь можно остановить прослушивание.2049 # Логирование в родительском процессе всё ещё работает нормально.2050 logger.info('Telling listener to stop ...')2051 stop_event.set()2052 lp.join()2053 logger.info('All done.')20542055if __name__ == '__main__':2056 main()2057```20582059## Вставка BOM в сообщения, отправляемые в SysLogHandler20602061[**RFC 5424**](https://python-all.ru/3.14/howto/logging-cookbook.html) требует, чтобы сообщение Unicode отправлялось демону syslog в виде набора байтов, имеющего следующую структуру: необязательный чисто ASCII-компонент, за которым следует метка порядка байтов UTF-8 (BOM), а затем Unicode, закодированный в UTF-8. (См. [**соответствующий раздел спецификации**](https://python-all.ru/3.14/howto/logging-cookbook.html).)20622063В Python 3.1 в [`SysLogHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.SysLogHandler) был добавлен код для вставки BOM в сообщение, но, к сожалению, он был реализован некорректно: BOM появлялся в начале сообщения и, следовательно, не допускал наличия чисто ASCII-компонента перед ним.20642065Поскольку такое поведение ошибочно, некорректный код вставки BOM удаляется из Python 3.2.4 и более поздних версий. Однако он не заменяется, и если требуется создавать сообщения, соответствующие [**RFC 5424**](https://python-all.ru/3.14/howto/logging-cookbook.html), которые включают BOM, необязательную чисто ASCII-последовательность перед ним и произвольный Unicode после него, закодированный в UTF-8, то необходимо сделать следующее:206620671. Необходимо присоединить экземпляр [`Formatter`](https://python-all.ru/3.14/library/logging.html#logging.Formatter) к экземпляру [`SysLogHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.SysLogHandler), указав строку формата, например:20682069 ```python2070 'ASCII section\ufeffUnicode section'2071 ```20722073 Кодовая точка Unicode U+FEFF при кодировании в UTF-8 будет представлена как метка порядка байтов UTF-8 – строка байтов `b'\xef\xbb\xbf'`.20742. ASCII-часть следует заменить на любые подходящие заполнители, но необходимо следить, чтобы данные, которые появляются там после подстановки, всегда были в ASCII (таким образом, они останутся без изменений после кодирования UTF-8).20753. Unicode-часть следует заменить на любые заполнители; если данные после подстановки содержат символы за пределами диапазона ASCII, это нормально – они будут закодированы в UTF-8.20762077Отформатированное сообщение *будет* закодировано в UTF-8 с помощью `SysLogHandler`. Если следовать приведённым выше правилам, можно создавать сообщения, соответствующие [**RFC 5424**](https://python-all.ru/3.14/howto/logging-cookbook.html). Если этого не делать, модуль logging может не жаловаться, но сообщения не будут соответствовать RFC 5424, и демон syslog может выражать недовольство.20782079## Реализация структурированного ведения журнала20802081Хотя большинство сообщений журнала предназначены для чтения человеком и поэтому не предназначены для машинного разбора, могут возникнуть ситуации, когда требуется выводить сообщения в структурированном формате, *который* может быть разобран программой (без необходимости в сложных регулярных выражениях). Это легко достигается с помощью пакета logging. Существует несколько способов, но ниже приведён простой подход, использующий JSON для сериализации события в машиночитаемом виде.20822083```python2084import json2085import logging20862087class StructuredMessage:2088 def __init__(self, message, /, **kwargs):2089 self.message = message2090 self.kwargs = kwargs20912092 def __str__(self):2093 return '%s >>> %s' % (self.message, json.dumps(self.kwargs))20942095_ = StructuredMessage # необязательно, для улучшения читаемости20962097logging.basicConfig(level=logging.INFO, format='%(message)s')2098logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))2099```21002101Если запустить приведённый выше скрипт, он выведет:21022103```text2104message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}2105```21062107Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.21082109Если требуется более специализированная обработка, можно использовать пользовательский кодировщик JSON, как в следующем полном примере:21102111```python2112import json2113import logging21142115class Encoder(json.JSONEncoder):2116 def default(self, o):2117 if isinstance(o, set):2118 return tuple(o)2119 elif isinstance(o, str):2120 return o.encode('unicode_escape').decode('ascii')2121 return super().default(o)21222123class StructuredMessage:2124 def __init__(self, message, /, **kwargs):2125 self.message = message2126 self.kwargs = kwargs21272128 def __str__(self):2129 s = Encoder().encode(self.kwargs)2130 return '%s >>> %s' % (self.message, s)21312132_ = StructuredMessage # необязательно, для улучшения читаемости21332134def main():2135 logging.basicConfig(level=logging.INFO, format='%(message)s')2136 logging.info(_('message 1', set_value={1, 2, 3}, snowman='\u2603'))21372138if __name__ == '__main__':2139 main()2140```21412142При запуске приведённого выше скрипта он выведет:21432144```text2145message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}2146```21472148Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.21492150## Настройка обработчиков с помощью [`dictConfig()`](https://python-all.ru/3.14/library/logging.config.html#logging.config.dictConfig)21512152Иногда требуется настроить обработчики логирования особым образом, и при использовании [`dictConfig()`](https://python-all.ru/3.14/library/logging.config.html#logging.config.dictConfig) это можно сделать без создания подклассов. Например, может потребоваться установить владельца файла журнала. В POSIX это легко сделать с помощью [`shutil.chown()`](https://python-all.ru/3.14/library/shutil.html#shutil.chown), но файловые обработчики в стандартной библиотеке не предоставляют встроенной поддержки. Можно настроить создание обработчика с помощью обычной функции, такой как:21532154```python2155def owned_file_handler(filename, mode='a', encoding=None, owner=None):2156 if owner:2157 if not os.path.exists(filename):2158 open(filename, 'a').close()2159 shutil.chown(filename, *owner)2160 return logging.FileHandler(filename, mode, encoding)2161```21622163Затем в конфигурации логирования, передаваемой в [`dictConfig()`](https://python-all.ru/3.14/library/logging.config.html#logging.config.dictConfig), можно указать, что обработчик должен быть создан вызовом этой функции:21642165```python2166LOGGING = {2167 'version': 1,2168 'disable_existing_loggers': False,2169 'formatters': {2170 'default': {2171 'format': '%(asctime)s %(levelname)s %(name)s %(message)s'2172 },2173 },2174 'handlers': {2175 'file':{2176 # Значения ниже извлекаются из этого словаря и2177 # используются для создания обработчика, установки его уровня и2178 # его форматтера.2179 '()': owned_file_handler,2180 'level':'DEBUG',2181 'formatter': 'default',2182 # Значения ниже передаются вызываемому объекту-создателю обработчика2183 # в качестве именованных аргументов.2184 'owner': ['pulse', 'pulse'],2185 'filename': 'chowntest.log',2186 'mode': 'w',2187 'encoding': 'utf-8',2188 },2189 },2190 'root': {2191 'handlers': ['file'],2192 'level': 'DEBUG',2193 },2194}2195```21962197В этом примере для иллюстрации права владения устанавливаются с использованием пользователя и группы `pulse`. Собирая всё вместе в рабочий скрипт, `chowntest.py`:21982199```python2200import logging, logging.config, os, shutil22012202def owned_file_handler(filename, mode='a', encoding=None, owner=None):2203 if owner:2204 if not os.path.exists(filename):2205 open(filename, 'a').close()2206 shutil.chown(filename, *owner)2207 return logging.FileHandler(filename, mode, encoding)22082209LOGGING = {2210 'version': 1,2211 'disable_existing_loggers': False,2212 'formatters': {2213 'default': {2214 'format': '%(asctime)s %(levelname)s %(name)s %(message)s'2215 },2216 },2217 'handlers': {2218 'file':{2219 # Значения ниже извлекаются из этого словаря и2220 # используются для создания обработчика, установки его уровня и2221 # его форматтера.2222 '()': owned_file_handler,2223 'level':'DEBUG',2224 'formatter': 'default',2225 # Значения ниже передаются вызываемому объекту-создателю обработчика2226 # в качестве именованных аргументов.2227 'owner': ['pulse', 'pulse'],2228 'filename': 'chowntest.log',2229 'mode': 'w',2230 'encoding': 'utf-8',2231 },2232 },2233 'root': {2234 'handlers': ['file'],2235 'level': 'DEBUG',2236 },2237}22382239logging.config.dictConfig(LOGGING)2240logger = logging.getLogger('mylogger')2241logger.debug('A debug message')2242```22432244Для запуска, вероятно, потребуется выполнить от имени `root`:22452246```console2247$ sudo python3.3 chowntest.py2248$ cat chowntest.log22492013-11-05 09:34:51,128 DEBUG mylogger A debug message2250$ ls -l chowntest.log2251-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log2252```22532254Обратите внимание, что в этом примере используется Python 3.3, потому что в нём появился [`shutil.chown()`](https://python-all.ru/3.14/library/shutil.html#shutil.chown). Этот подход должен работать с любой версией Python, поддерживающей [`dictConfig()`](https://python-all.ru/3.14/library/logging.config.html#logging.config.dictConfig) – а именно Python 2.7, 3.2 или новее. В версиях до 3.3 потребовалось бы реализовать фактическую смену владельца, например, с помощью [`os.chown()`](https://python-all.ru/3.14/library/os.html#os.chown).22552256На практике функция создания обработчика может находиться в служебном модуле где-нибудь в вашем проекте. Вместо строки в конфигурации:22572258```python2259'()': owned_file_handler,2260```22612262можно использовать, например:22632264```python2265'()': 'ext://project.util.owned_file_handler',2266```22672268где `project.util` можно заменить на фактическое имя пакета, в котором находится функция. В приведённом рабочем скрипте должно сработать использование `'ext://__main__.owned_file_handler'`. Здесь фактический вызываемый объект разрешается с помощью [`dictConfig()`](https://python-all.ru/3.14/library/logging.config.html#logging.config.dictConfig) из спецификации `ext://`.22692270Этот пример, надеюсь, также показывает, как можно реализовать другие типы изменений файлов – например, установку определённых битов разрешений POSIX – аналогичным образом, с помощью [`os.chmod()`](https://python-all.ru/3.14/library/os.html#os.chmod).22712272Разумеется, этот подход можно распространить и на другие типы обработчиков, помимо [`FileHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.FileHandler) – например, на один из вращающихся файловых обработчиков или на совершенно другой тип обработчика.22732274## Использование определённых стилей форматирования во всём приложении22752276В Python 3.2 у [`Formatter`](https://python-all.ru/3.14/library/logging.html#logging.Formatter) появился именованный параметр `style`, который, хотя по умолчанию для обратной совместимости он равен `%`, позволяет указать `{` или `$` для поддержки подходов к форматированию, поддерживаемых [`str.format()`](https://python-all.ru/3.14/library/stdtypes.html#str.format) и [`string.Template`](https://python-all.ru/3.14/library/string.html#string.Template). Обратите внимание, что это управляет форматированием сообщений журнала для окончательного вывода в журнал и совершенно не зависит от того, как конструируется отдельное сообщение журнала.22772278Вызовы логирования ([`debug()`](https://python-all.ru/3.14/library/logging.html#logging.Logger.debug), [`info()`](https://python-all.ru/3.14/library/logging.html#logging.Logger.info) и т.д.) принимают только позиционные параметры для самого сообщения журнала, а именованные параметры используются только для определения параметров обработки вызова (например, именованный параметр `exc_info` для указания, что нужно записывать информацию о трассировке, или именованный параметр `extra` для указания дополнительной контекстной информации, добавляемой в журнал). Таким образом, нельзя напрямую выполнять вызовы логирования с использованием синтаксиса [`str.format()`](https://python-all.ru/3.14/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.14/library/string.html#string.Template), потому что внутри пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Изменить это без нарушения обратной совместимости было бы невозможно, поскольку все существующие вызовы логирования в коде используют строки с %-форматированием.22792280Высказывались предложения связывать стили форматирования с конкретными регистраторами, но этот подход также сталкивается с проблемами обратной совместимости, поскольку любой существующий код может использовать данное имя регистратора и %-форматирование.22812282Чтобы логирование работало совместимо между любыми сторонними библиотеками и вашим кодом, решения о форматировании необходимо принимать на уровне отдельного вызова логирования. Это открывает несколько способов, которыми можно реализовать альтернативные стили форматирования.22832284### Использование фабрик LogRecord22852286В Python 3.2, вместе с упомянутыми выше изменениями [`Formatter`](https://python-all.ru/3.14/library/logging.html#logging.Formatter), пакет logging получил возможность позволять пользователям устанавливать свои собственные подклассы [`LogRecord`](https://python-all.ru/3.14/library/logging.html#logging.LogRecord) с помощью функции [`setLogRecordFactory()`](https://python-all.ru/3.14/library/logging.html#logging.setLogRecordFactory). Вы можете использовать это, чтобы установить свой собственный подкласс `LogRecord`, который делает правильные вещи, переопределяя метод [`getMessage()`](https://python-all.ru/3.14/library/logging.html#logging.LogRecord.getMessage). В реализации базового класса этого метода происходит форматирование `msg % args`, и именно здесь можно подставить альтернативное форматирование; однако следует быть осторожным, чтобы поддерживать все стили форматирования и разрешить %-форматирование по умолчанию для обеспечения совместимости с другим кодом. Также следует позаботиться о вызове `str(self.msg)`, как это делает базовая реализация.22872288Обратитесь к справочной документации по [`setLogRecordFactory()`](https://python-all.ru/3.14/library/logging.html#logging.setLogRecordFactory) и [`LogRecord`](https://python-all.ru/3.14/library/logging.html#logging.LogRecord) для получения дополнительной информации.22892290### Использование пользовательских объектов сообщений22912292Есть еще один, возможно, более простой способ использовать {}- и $-форматирование для построения отдельных сообщений лога. Вы, возможно, помните (из раздела [Использование произвольных объектов в качестве сообщений](https://python-all.ru/3.14/howto/logging.html#arbitrary-object-messages)), что при логировании можно использовать произвольный объект в качестве строки формата сообщения, и пакет logging вызовет [`str()`](https://python-all.ru/3.14/library/stdtypes.html#str) для этого объекта, чтобы получить фактическую строку формата. Рассмотрим следующие два класса:22932294```python2295class BraceMessage:2296 def __init__(self, fmt, /, *args, **kwargs):2297 self.fmt = fmt2298 self.args = args2299 self.kwargs = kwargs23002301 def __str__(self):2302 return self.fmt.format(*self.args, **self.kwargs)23032304class DollarMessage:2305 def __init__(self, fmt, /, **kwargs):2306 self.fmt = fmt2307 self.kwargs = kwargs23082309 def __str__(self):2310 from string import Template2311 return Template(self.fmt).substitute(**self.kwargs)2312```23132314Любой из них можно использовать вместо строки формата, чтобы разрешить {}- или $-форматирование для построения фактической части «message», которая появляется в форматированном выводе лога вместо «%(message)s», «{message}» или «$message». Если вам кажется неудобным использовать имена классов каждый раз при логировании, вы можете сделать это более приятным, используя псевдоним, такой как `M` или `_` для сообщения (или, возможно, `__`, если вы используете `_` для локализации).23152316Примеры этого подхода приведены ниже. Во-первых, форматирование с помощью [`str.format()`](https://python-all.ru/3.14/library/stdtypes.html#str.format):23172318```python2319>>> __ = BraceMessage2320>>> print(__('Message with {0} {1}', 2, 'placeholders'))2321Message with 2 placeholders2322>>> class Point: pass2323...2324>>> p = Point()2325>>> p.x = 0.52326>>> p.y = 0.52327>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))2328Message with coordinates: (0.50, 0.50)2329```23302331Во-вторых, форматирование с помощью [`string.Template`](https://python-all.ru/3.14/library/string.html#string.Template):23322333```python2334>>> __ = DollarMessage2335>>> print(__('Message with $num $what', num=2, what='placeholders'))2336Message with 2 placeholders2337>>>2338```23392340Стоит отметить, что при таком подходе вы не платите значительных потерь производительности: фактическое форматирование происходит не при вызове логирования, а когда (и если) сообщение лога действительно должно быть выведено в лог обработчиком. Так что единственная необычная вещь, которая может вас сбить с толку, это то, что круглые скобки ставятся вокруг строки формата и аргументов, а не только вокруг строки формата. Это потому, что нотация \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов `XXXMessage`, показанных выше.23412342## Настройка фильтров с помощью [`dictConfig()`](https://python-all.ru/3.14/library/logging.config.html#logging.config.dictConfig)23432344*Можно* настраивать фильтры с помощью [`dictConfig()`](https://python-all.ru/3.14/library/logging.config.html#logging.config.dictConfig), хотя с первого взгляда может быть неочевидно, как это сделать (поэтому и дан этот рецепт). Поскольку [`Filter`](https://python-all.ru/3.14/library/logging.html#logging.Filter) – единственный класс фильтра, включенный в стандартную библиотеку, и вряд ли он удовлетворит многие требования (он присутствует только как базовый класс), вам, как правило, потребуется определить свой собственный подкласс `Filter` с переопределенным методом [`filter()`](https://python-all.ru/3.14/library/logging.html#logging.Filter.filter). Для этого укажите ключ `()` в словаре конфигурации для фильтра, указав вызываемый объект, который будет использоваться для создания фильтра (класс – наиболее очевидный вариант, но вы можете предоставить любой вызываемый объект, возвращающий экземпляр `Filter`). Вот полный пример:23452346```python2347import logging2348import logging.config2349import sys23502351class MyFilter(logging.Filter):2352 def __init__(self, param=None):2353 self.param = param23542355 def filter(self, record):2356 if self.param is None:2357 allow = True2358 else:2359 allow = self.param not in record.msg2360 if allow:2361 record.msg = 'changed: ' + record.msg2362 return allow23632364LOGGING = {2365 'version': 1,2366 'filters': {2367 'myfilter': {2368 '()': MyFilter,2369 'param': 'noshow',2370 }2371 },2372 'handlers': {2373 'console': {2374 'class': 'logging.StreamHandler',2375 'filters': ['myfilter']2376 }2377 },2378 'root': {2379 'level': 'DEBUG',2380 'handlers': ['console']2381 },2382}23832384if __name__ == '__main__':2385 logging.config.dictConfig(LOGGING)2386 logging.debug('hello')2387 logging.debug('hello - noshow')2388```23892390Этот пример показывает, как можно передавать конфигурационные данные вызываемому объекту, который создает экземпляр, в виде именованных параметров. При запуске приведенный выше скрипт выведет:23912392```text2393changed: hello2394```23952396что показывает, что фильтр работает в соответствии с настройками.23972398Несколько дополнительных моментов, на которые стоит обратить внимание:23992400- Если вы не можете сослаться на вызываемый объект напрямую в конфигурации (например, если он находится в другом модуле, и вы не можете импортировать его напрямую в том месте, где находится словарь конфигурации), вы можете использовать форму `ext://...`, как описано в разделе [Доступ к внешним объектам](https://python-all.ru/3.14/library/logging.config.html#logging-config-dict-externalobj). Например, в приведенном выше примере можно было использовать текст `'ext://__main__.MyFilter'` вместо `MyFilter`.2401- Помимо фильтров, этот метод также можно использовать для настройки пользовательских обработчиков и форматтеров. Смотрите раздел [Пользовательские объекты](https://python-all.ru/3.14/library/logging.config.html#logging-config-dict-userdef) для получения дополнительной информации о том, как logging поддерживает использование пользовательских объектов в своей конфигурации, а также см. другой рецепт из этой книги рецептов [Настройка обработчиков с помощью dictConfig()](https://python-all.ru/3.14/howto/logging-cookbook.html#custom-handlers) выше.24022403## Настраиваемое форматирование исключений24042405Могут возникнуть ситуации, когда вы захотите настроить форматирование исключений – для примера, предположим, вы хотите ровно одну строку на каждое событие лога, даже если присутствует информация об исключении. Вы можете сделать это с помощью пользовательского класса форматтера, как показано в следующем примере:24062407```python2408import logging24092410class OneLineExceptionFormatter(logging.Formatter):2411 def formatException(self, exc_info):2412 """2413 Форматировать исключение так, чтобы оно выводилось одной строкой.2414 """2415 result = super().formatException(exc_info)2416 return repr(result) # или форматировать одной строкой по своему усмотрению24172418 def format(self, record):2419 s = super().format(record)2420 if record.exc_text:2421 s = s.replace('\n', '') + '|'2422 return s24232424def configure_logging():2425 fh = logging.FileHandler('output.txt', 'w')2426 f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',2427 '%d/%m/%Y %H:%M:%S')2428 fh.setFormatter(f)2429 root = logging.getLogger()2430 root.setLevel(logging.DEBUG)2431 root.addHandler(fh)24322433def main():2434 configure_logging()2435 logging.info('Sample message')2436 try:2437 x = 1 / 02438 except ZeroDivisionError as e:2439 logging.exception('ZeroDivisionError: %s', e)24402441if __name__ == '__main__':2442 main()2443```24442445При запуске это создает файл ровно с двумя строками:24462447```text244828/01/2015 07:21:23|INFO|Sample message|244928/01/2015 07:21:23|ERROR|ZeroDivisionError: division by zero|'Traceback (most recent call last):\n File "logtest7.py", line 30, in main\n x = 1 / 0\nZeroDivisionError: division by zero'|2450```24512452Хотя описанный выше подход упрощен, он показывает путь к тому, как можно форматировать информацию об исключениях по своему вкусу. Модуль [`traceback`](https://python-all.ru/3.14/library/traceback.html#module-traceback) может быть полезен для более специализированных нужд.24532454## Озвучивание сообщений лога24552456Могут быть ситуации, когда желательно выводить сообщения лога в звуковом, а не визуальном формате. Это легко сделать, если в вашей системе доступна функция преобразования текста в речь (TTS), даже если у нее нет привязки к Python. Большинство TTS-систем имеют программу командной строки, которую можно запустить, и ее можно вызвать из обработчика с помощью [`subprocess`](https://python-all.ru/3.14/library/subprocess.html#module-subprocess). Здесь предполагается, что программы командной строки TTS не будут ожидать взаимодействия с пользователем или занимать много времени для завершения, и что частота сообщений лога не будет настолько высокой, чтобы перегружать пользователя сообщениями, и что допустимо проговаривать сообщения по одному, а не одновременно. В приведенном ниже примере реализации ожидается, пока одно сообщение не будет произнесено, прежде чем обрабатывать следующее, и это может заставить другие обработчики ждать. Вот короткий пример, демонстрирующий подход, который предполагает, что доступен TTS-пакет `espeak`:24572458```python2459import logging2460import subprocess2461import sys24622463class TTSHandler(logging.Handler):2464 def emit(self, record):2465 msg = self.format(record)2466 # Говорить медленно женским английским голосом.2467 cmd = ['espeak', '-s150', '-ven+f3', msg]2468 p = subprocess.Popen(cmd, stdout=subprocess.PIPE,2469 stderr=subprocess.STDOUT)2470 # дождаться завершения программы2471 p.communicate()24722473def configure_logging():2474 h = TTSHandler()2475 root = logging.getLogger()2476 root.addHandler(h)2477 # стандартный форматтер просто возвращает сообщение2478 root.setLevel(logging.DEBUG)24792480def main():2481 logging.info('Hello')2482 logging.debug('Goodbye')24832484if __name__ == '__main__':2485 configure_logging()2486 sys.exit(main())2487```24882489При запуске этот скрипт должен сказать «Hello», а затем «Goodbye» женским голосом.24902491Описанный выше подход, конечно, можно адаптировать для других TTS-систем и даже для других систем, которые могут обрабатывать сообщения через внешние программы, запускаемые из командной строки.24922493## Буферизация сообщений лога и условный вывод24942495Могут возникнуть ситуации, когда вы хотите записывать сообщения во временную область и выводить их только при наступлении определенного условия. Например, вы можете начать запись отладочных событий в функции, и если функция завершится без ошибок, вы не захотите засорять лог собранной отладочной информацией, но если возникнет ошибка, вы захотите вывести всю отладочную информацию вместе с ошибкой.24962497Вот пример, показывающий, как это можно сделать с помощью декоратора для ваших функций, где вы хотите, чтобы логирование вело себя таким образом. Он использует [`logging.handlers.MemoryHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.MemoryHandler), который позволяет буферизовать зарегистрированные события до наступления некоторого условия, после чего буферизованные события `flushed` – передаются другому обработчику (обработчику `target`) для обработки. По умолчанию `MemoryHandler` сбрасывается, когда его буфер заполняется или встречается событие, уровень которого больше или равен указанному порогу. Вы можете использовать этот рецепт с более специализированным подклассом `MemoryHandler`, если хотите настроить поведение сброса.24982499Пример скрипта содержит простую функцию `foo`, которая просто перебирает все уровни логирования, записывая в `sys.stderr` информацию о том, какой уровень будет использоваться, а затем регистрирует сообщение на этом уровне. Вы можете передать параметр в `foo`, который, если равен true, будет регистрировать на уровнях ERROR и CRITICAL – в противном случае он регистрирует только на уровнях DEBUG, INFO и WARNING.25002501Скрипт просто настраивает декорирование `foo` декоратором, который будет выполнять необходимое условное логирование. Декоратор принимает регистратор в качестве параметра и подключает обработчик памяти на время вызова декорированной функции. Декоратор можно дополнительно параметризовать с помощью целевого обработчика, уровня, при котором должен происходить сброс, и емкости буфера (количество буферизируемых записей). По умолчанию они равны [`StreamHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.StreamHandler), который пишет в `sys.stderr`, `logging.ERROR` и `100` соответственно.25022503Вот скрипт:25042505```python2506import logging2507from logging.handlers import MemoryHandler2508import sys25092510logger = logging.getLogger(__name__)2511logger.addHandler(logging.NullHandler())25122513def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):2514 if target_handler is None:2515 target_handler = logging.StreamHandler()2516 if flush_level is None:2517 flush_level = logging.ERROR2518 if capacity is None:2519 capacity = 1002520 handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)25212522 def decorator(fn):2523 def wrapper(*args, **kwargs):2524 logger.addHandler(handler)2525 try:2526 return fn(*args, **kwargs)2527 except Exception:2528 logger.exception('call failed')2529 raise2530 finally:2531 super(MemoryHandler, handler).flush()2532 logger.removeHandler(handler)2533 return wrapper25342535 return decorator25362537def write_line(s):2538 sys.stderr.write('%s\n' % s)25392540def foo(fail=False):2541 write_line('about to log at DEBUG ...')2542 logger.debug('Actually logged at DEBUG')2543 write_line('about to log at INFO ...')2544 logger.info('Actually logged at INFO')2545 write_line('about to log at WARNING ...')2546 logger.warning('Actually logged at WARNING')2547 if fail:2548 write_line('about to log at ERROR ...')2549 logger.error('Actually logged at ERROR')2550 write_line('about to log at CRITICAL ...')2551 logger.critical('Actually logged at CRITICAL')2552 return fail25532554decorated_foo = log_if_errors(logger)(foo)25552556if __name__ == '__main__':2557 logger.setLevel(logging.DEBUG)2558 write_line('Calling undecorated foo with False')2559 assert not foo(False)2560 write_line('Calling undecorated foo with True')2561 assert foo(True)2562 write_line('Calling decorated foo with False')2563 assert not decorated_foo(False)2564 write_line('Calling decorated foo with True')2565 assert decorated_foo(True)2566```25672568При запуске этого скрипта отобразится следующий вывод:25692570```text2571Calling undecorated foo with False2572about to log at DEBUG ...2573about to log at INFO ...2574about to log at WARNING ...2575Calling undecorated foo with True2576about to log at DEBUG ...2577about to log at INFO ...2578about to log at WARNING ...2579about to log at ERROR ...2580about to log at CRITICAL ...2581Calling decorated foo with False2582about to log at DEBUG ...2583about to log at INFO ...2584about to log at WARNING ...2585Calling decorated foo with True2586about to log at DEBUG ...2587about to log at INFO ...2588about to log at WARNING ...2589about to log at ERROR ...2590Actually logged at DEBUG2591Actually logged at INFO2592Actually logged at WARNING2593Actually logged at ERROR2594about to log at CRITICAL ...2595Actually logged at CRITICAL2596```25972598Как видно, фактический вывод журнала происходит только при регистрации события, уровень которого ERROR или выше, но в этом случае также регистрируются все предыдущие события с более низкими уровнями.25992600Конечно, можно использовать обычные средства декорирования:26012602```python2603@log_if_errors(logger)2604def foo(fail=False):2605 ...2606```26072608## Отправка сообщений журнала по электронной почте с буферизацией26092610Чтобы проиллюстрировать, как можно отправлять сообщения журнала по электронной почте, так чтобы заданное количество сообщений отправлялось за одно письмо, можно создать подкласс [`BufferingHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.BufferingHandler). В приведённом ниже примере, который можно адаптировать под свои нужды, предоставляется простая тестовая обвязка, позволяющая запустить скрипт с аргументами командной строки, указывающими, что обычно необходимо для отправки через SMTP. (Запустите загруженный скрипт с аргументом `-h`, чтобы увидеть обязательные и необязательные аргументы.)26112612```python2613import logging2614import logging.handlers2615import smtplib26162617class BufferingSMTPHandler(logging.handlers.BufferingHandler):2618 def __init__(self, mailhost, port, username, password, fromaddr, toaddrs,2619 subject, capacity):2620 logging.handlers.BufferingHandler.__init__(self, capacity)2621 self.mailhost = mailhost2622 self.mailport = port2623 self.username = username2624 self.password = password2625 self.fromaddr = fromaddr2626 if isinstance(toaddrs, str):2627 toaddrs = [toaddrs]2628 self.toaddrs = toaddrs2629 self.subject = subject2630 self.setFormatter(logging.Formatter("%(asctime)s %(levelname)-5s %(message)s"))26312632 def flush(self):2633 if len(self.buffer) > 0:2634 try:2635 smtp = smtplib.SMTP(self.mailhost, self.mailport)2636 smtp.starttls()2637 smtp.login(self.username, self.password)2638 msg = "From: %s\r\nTo: %s\r\nSubject: %s\r\n\r\n" % (self.fromaddr, ','.join(self.toaddrs), self.subject)2639 for record in self.buffer:2640 s = self.format(record)2641 msg = msg + s + "\r\n"2642 smtp.sendmail(self.fromaddr, self.toaddrs, msg)2643 smtp.quit()2644 except Exception:2645 if logging.raiseExceptions:2646 raise2647 self.buffer = []26482649if __name__ == '__main__':2650 import argparse26512652 ap = argparse.ArgumentParser()2653 aa = ap.add_argument2654 aa('host', metavar='HOST', help='SMTP server')2655 aa('--port', '-p', type=int, default=587, help='SMTP port')2656 aa('user', metavar='USER', help='SMTP username')2657 aa('password', metavar='PASSWORD', help='SMTP password')2658 aa('to', metavar='TO', help='Addressee for emails')2659 aa('sender', metavar='SENDER', help='Sender email address')2660 aa('--subject', '-s',2661 default='Test Logging email from Python logging module (buffering)',2662 help='Subject of email')2663 options = ap.parse_args()2664 logger = logging.getLogger()2665 logger.setLevel(logging.DEBUG)2666 h = BufferingSMTPHandler(options.host, options.port, options.user,2667 options.password, options.sender,2668 options.to, options.subject, 10)2669 logger.addHandler(h)2670 for i in range(102):2671 logger.info("Info index = %d", i)2672 h.flush()2673 h.close()2674```26752676Если запустить этот скрипт и SMTP-сервер настроен правильно, то будет отправлено одиннадцать писем указанному адресату. Первые десять писем будут содержать по десять сообщений журнала, а одиннадцатое – два сообщения. В сумме получается 102 сообщения, как указано в скрипте.26772678## Форматирование времени с использованием UTC (GMT) через конфигурацию26792680Иногда требуется форматировать время в UTC, что можно сделать с помощью класса `UTCFormatter`, показанного ниже:26812682```python2683import logging2684import time26852686class UTCFormatter(logging.Formatter):2687 converter = time.gmtime2688```26892690и затем можно использовать `UTCFormatter` в своём коде вместо [`Formatter`](https://python-all.ru/3.14/library/logging.html#logging.Formatter). Если требуется сделать это через конфигурацию, можно воспользоваться API [`dictConfig()`](https://python-all.ru/3.14/library/logging.config.html#logging.config.dictConfig), как показано в следующем полном примере:26912692```python2693import logging2694import logging.config2695import time26962697class UTCFormatter(logging.Formatter):2698 converter = time.gmtime26992700LOGGING = {2701 'version': 1,2702 'disable_existing_loggers': False,2703 'formatters': {2704 'utc': {2705 '()': UTCFormatter,2706 'format': '%(asctime)s %(message)s',2707 },2708 'local': {2709 'format': '%(asctime)s %(message)s',2710 }2711 },2712 'handlers': {2713 'console1': {2714 'class': 'logging.StreamHandler',2715 'formatter': 'utc',2716 },2717 'console2': {2718 'class': 'logging.StreamHandler',2719 'formatter': 'local',2720 },2721 },2722 'root': {2723 'handlers': ['console1', 'console2'],2724 }2725}27262727if __name__ == '__main__':2728 logging.config.dictConfig(LOGGING)2729 logging.warning('The local time is %s', time.asctime())2730```27312732При запуске этого скрипта он должен вывести примерно следующее:27332734```text27352015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 201527362015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 20152737```27382739показывая, как время форматируется как в местном времени, так и в UTC, по одному для каждого обработчика.27402741## Использование контекстного менеджера для выборочного журналирования27422743Бывают ситуации, когда полезно временно изменить конфигурацию журналирования, а затем вернуть её обратно после выполнения каких-то действий. Для этого контекстный менеджер – самый очевидный способ сохранить и восстановить контекст журналирования. Вот простой пример такого контекстного менеджера, который позволяет по желанию изменить уровень журналирования и добавить обработчик журнала исключительно в области действия контекстного менеджера:27442745```python2746import logging2747import sys27482749class LoggingContext:2750 def __init__(self, logger, level=None, handler=None, close=True):2751 self.logger = logger2752 self.level = level2753 self.handler = handler2754 self.close = close27552756 def __enter__(self):2757 if self.level is not None:2758 self.old_level = self.logger.level2759 self.logger.setLevel(self.level)2760 if self.handler:2761 self.logger.addHandler(self.handler)27622763 def __exit__(self, et, ev, tb):2764 if self.level is not None:2765 self.logger.setLevel(self.old_level)2766 if self.handler:2767 self.logger.removeHandler(self.handler)2768 if self.handler and self.close:2769 self.handler.close()2770 # неявный возврат None => не подавлять исключения2771```27722773Если указать значение уровня, уровень регистратора устанавливается на это значение в области действия блока with, охватываемого контекстным менеджером. Если указать обработчик, он добавляется к регистратору при входе в блок и удаляется при выходе из блока. Также можно попросить менеджер закрыть обработчик при выходе из блока – это можно сделать, если обработчик больше не нужен.27742775Чтобы проиллюстрировать, как это работает, можно добавить следующий блок кода к предыдущему:27762777```python2778if __name__ == '__main__':2779 logger = logging.getLogger('foo')2780 logger.addHandler(logging.StreamHandler())2781 logger.setLevel(logging.INFO)2782 logger.info('1. This should appear just once on stderr.')2783 logger.debug('2. This should not appear.')2784 with LoggingContext(logger, level=logging.DEBUG):2785 logger.debug('3. This should appear once on stderr.')2786 logger.debug('4. This should not appear.')2787 h = logging.StreamHandler(sys.stdout)2788 with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):2789 logger.debug('5. This should appear twice - once on stderr and once on stdout.')2790 logger.info('6. This should appear just once on stderr.')2791 logger.debug('7. This should not appear.')2792```27932794Изначально устанавливаем уровень регистратора равным `INFO`, поэтому сообщение №1 отображается, а сообщение №2 – нет. Затем временно меняем уровень на `DEBUG` в следующем блоке `with`, и сообщение №3 отображается. После выхода из блока уровень регистратора восстанавливается до `INFO`, поэтому сообщение №4 не отображается. В следующем блоке `with` снова устанавливаем уровень `DEBUG`, но также добавляем обработчик, записывающий в `sys.stdout`. Таким образом, сообщение №5 отображается дважды на консоли (один раз через `stderr` и один раз через `stdout`). После завершения оператора `with` состояние возвращается к исходному, поэтому сообщение №6 отображается (как сообщение №1), а сообщение №7 – нет (как сообщение №2).27952796Если запустить полученный скрипт, результат будет следующим:27972798```console2799$ python logctx.py28001. This should appear just once on stderr.28013. This should appear once on stderr.28025. This should appear twice - once on stderr and once on stdout.28035. This should appear twice - once on stderr and once on stdout.28046. This should appear just once on stderr.2805```28062807Если запустить его снова, но перенаправить `stderr` в `/dev/null`, мы увидим следующее, что является единственным сообщением, записанным в `stdout`:28082809```console2810$ python logctx.py 2>/dev/null28115. This should appear twice - once on stderr and once on stdout.2812```28132814Ещё раз, но перенаправляя `stdout` в `/dev/null`, получаем:28152816```console2817$ python logctx.py >/dev/null28181. This should appear just once on stderr.28193. This should appear once on stderr.28205. This should appear twice - once on stderr and once on stdout.28216. This should appear just once on stderr.2822```28232824В этом случае сообщение №5, выведенное в `stdout`, не отображается, как и ожидалось.28252826Разумеется, описанный подход можно обобщить, например, для временного подключения фильтров журналирования. Обратите внимание, что приведённый выше код работает как в Python 2, так и в Python 3.28272828## Шаблон для запуска CLI-приложения28292830Вот пример, показывающий, как можно:28312832- Использовать уровень журналирования на основе аргументов командной строки2833- Перенаправлять вызовы к нескольким подкомандам в отдельных файлах, все с журналированием на одном уровне согласованным образом2834- Использовать простую минимальную конфигурацию28352836Предположим, у нас есть приложение командной строки, которое останавливает, запускает или перезапускает некоторые службы. Для иллюстрации это может быть организовано в виде файла `app.py`, который является главным скриптом приложения, с отдельными командами, реализованными в `start.py`, `stop.py` и `restart.py`. Предположим также, что мы хотим управлять степенью подробности вывода приложения через аргумент командной строки с значением по умолчанию `logging.INFO`. Вот один из способов, как мог бы быть написан `app.py`:28372838```python2839import argparse2840import importlib2841import logging2842import os2843import sys28442845def main(args=None):2846 scriptname = os.path.basename(__file__)2847 parser = argparse.ArgumentParser(scriptname)2848 levels = ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')2849 parser.add_argument('--log-level', default='INFO', choices=levels)2850 subparsers = parser.add_subparsers(dest='command',2851 help='Available commands:')2852 start_cmd = subparsers.add_parser('start', help='Start a service')2853 start_cmd.add_argument('name', metavar='NAME',2854 help='Name of service to start')2855 stop_cmd = subparsers.add_parser('stop',2856 help='Stop one or more services')2857 stop_cmd.add_argument('names', metavar='NAME', nargs='+',2858 help='Name of service to stop')2859 restart_cmd = subparsers.add_parser('restart',2860 help='Restart one or more services')2861 restart_cmd.add_argument('names', metavar='NAME', nargs='+',2862 help='Name of service to restart')2863 options = parser.parse_args()2864 # весь код для отправки команд мог бы быть в этом файле. Для целей2865 # только в целях иллюстрации каждая команда реализована в отдельном модуле.2866 try:2867 mod = importlib.import_module(options.command)2868 cmd = getattr(mod, 'command')2869 except (ImportError, AttributeError):2870 print('Unable to find the code for command \'%s\'' % options.command)2871 return 12872 # Здесь можно было бы сделать по-хитрому и загрузить конфигурацию из файла или словаря2873 logging.basicConfig(level=options.log_level,2874 format='%(levelname)s %(name)s %(message)s')2875 cmd(options)28762877if __name__ == '__main__':2878 sys.exit(main())2879```28802881А команды `start`, `stop` и `restart` могут быть реализованы в отдельных модулях, например, для запуска:28822883```python2884# start.py2885import logging28862887logger = logging.getLogger(__name__)28882889def command(options):2890 logger.debug('About to start %s', options.name)2891 # здесь происходит фактическая обработка команды...2892 logger.info('Started the \'%s\' service.', options.name)2893```28942895и аналогично для остановки:28962897```python2898# stop.py2899import logging29002901logger = logging.getLogger(__name__)29022903def command(options):2904 n = len(options.names)2905 if n == 1:2906 plural = ''2907 services = '\'%s\'' % options.names[0]2908 else:2909 plural = 's'2910 services = ', '.join('\'%s\'' % name for name in options.names)2911 i = services.rfind(', ')2912 services = services[:i] + ' and ' + services[i + 2:]2913 logger.debug('About to stop %s', services)2914 # здесь происходит фактическая обработка команды...2915 logger.info('Stopped the %s service%s.', services, plural)2916```29172918и аналогично для перезапуска:29192920```python2921# restart.py2922import logging29232924logger = logging.getLogger(__name__)29252926def command(options):2927 n = len(options.names)2928 if n == 1:2929 plural = ''2930 services = '\'%s\'' % options.names[0]2931 else:2932 plural = 's'2933 services = ', '.join('\'%s\'' % name for name in options.names)2934 i = services.rfind(', ')2935 services = services[:i] + ' and ' + services[i + 2:]2936 logger.debug('About to restart %s', services)2937 # здесь происходит фактическая обработка команды...2938 logger.info('Restarted the %s service%s.', services, plural)2939```29402941Если запустить это приложение с уровнем журналирования по умолчанию, мы получим примерно такой вывод:29422943```console2944$ python app.py start foo2945INFO start Started the 'foo' service.29462947$ python app.py stop foo bar2948INFO stop Stopped the 'foo' and 'bar' services.29492950$ python app.py restart foo bar baz2951INFO restart Restarted the 'foo', 'bar' and 'baz' services.2952```29532954Первое слово – уровень журналирования, а второе – имя модуля или пакета, в котором было зарегистрировано событие.29552956Если изменить уровень журналирования, можно изменить объём информации, отправляемой в журнал. Например, чтобы получить больше информации:29572958```console2959$ python app.py --log-level DEBUG start foo2960DEBUG start About to start foo2961INFO start Started the 'foo' service.29622963$ python app.py --log-level DEBUG stop foo bar2964DEBUG stop About to stop 'foo' and 'bar'2965INFO stop Stopped the 'foo' and 'bar' services.29662967$ python app.py --log-level DEBUG restart foo bar baz2968DEBUG restart About to restart 'foo', 'bar' and 'baz'2969INFO restart Restarted the 'foo', 'bar' and 'baz' services.2970```29712972А если нужно меньше:29732974```console2975$ python app.py --log-level WARNING start foo2976$ python app.py --log-level WARNING stop foo bar2977$ python app.py --log-level WARNING restart foo bar baz2978```29792980В этом случае команды ничего не выводят в консоль, поскольку ни одно сообщение уровня `WARNING` и выше ими не записывается.29812982## Графический интерфейс Qt для журналирования29832984Время от времени возникает вопрос о том, как вести журналирование в приложении с графическим интерфейсом. Фреймворк [Qt](https://python-all.ru/3.14/howto/logging-cookbook.html) – популярный кроссплатформенный инструмент для создания UI, имеющий привязки к Python через библиотеки [PySide2](https://python-all.ru/3.14/howto/logging-cookbook.html) или [PyQt5](https://python-all.ru/3.14/howto/logging-cookbook.html).29852986В следующем примере показано, как выполнять журналирование в графический интерфейс Qt. Он представляет простой класс `QtHandler`, который принимает вызываемый объект – слот главного потока, обновляющий GUI. Также создаётся рабочий поток, чтобы продемонстрировать возможность журналирования как из самого интерфейса (через кнопку для ручной записи), так и из фонового рабочего потока (который в данном случае просто выводит сообщения со случайными уровнями и случайными короткими задержками).29872988Рабочий поток реализован с помощью класса `QThread` из Qt, а не модуля [`threading`](https://python-all.ru/3.14/library/threading.html#module-threading), поскольку бывают ситуации, когда необходимо использовать `QThread`, который обеспечивает лучшую интеграцию с другими компонентами `Qt`.29892990Код должен работать с последними версиями `PySide6`, `PyQt6`, `PySide2` или `PyQt5`. Вы сможете адаптировать этот подход для более ранних версий Qt. Обратитесь к комментариям в примере кода за более подробной информацией.29912992```python2993import logging2994import random2995import sys2996import time29972998# Обработка небольших различий между разными пакетами Qt2999try:3000 from PySide6 import QtCore, QtGui, QtWidgets3001 Signal = QtCore.Signal3002 Slot = QtCore.Slot3003except ImportError:3004 try:3005 from PyQt6 import QtCore, QtGui, QtWidgets3006 Signal = QtCore.pyqtSignal3007 Slot = QtCore.pyqtSlot3008 except ImportError:3009 try:3010 from PySide2 import QtCore, QtGui, QtWidgets3011 Signal = QtCore.Signal3012 Slot = QtCore.Slot3013 except ImportError:3014 from PyQt5 import QtCore, QtGui, QtWidgets3015 Signal = QtCore.pyqtSignal3016 Slot = QtCore.pyqtSlot30173018logger = logging.getLogger(__name__)30193020#3021# Сигналы должны содержаться в QObject или подклассе, чтобы корректно3022# инициализироваться.3023#3024class Signaller(QtCore.QObject):3025 signal = Signal(str, logging.LogRecord)30263027#3028# Вывод в графический интерфейс Qt должен происходить только в главном потоке. Поэтому данный3029# обработчик спроектирован так, чтобы принимать функцию-слот, настроенную на выполнение в главном3030# потоке. В этом примере функция принимает строковый аргумент, который является3031# отформатированным сообщением лога, и запись лога, которая его породила. Отформатированная3032# строка – это просто удобство; можно отформатировать строку для вывода любым способом3033# в самой функции-слоте.3034#3035# Функцию-слот можно настроить на любые нужные обновления GUI. Обработчик3036# не знает и не заботится о конкретных элементах интерфейса.3037#3038class QtHandler(logging.Handler):3039 def __init__(self, slotfunc, *args, **kwargs):3040 super().__init__(*args, **kwargs)3041 self.signaller = Signaller()3042 self.signaller.signal.connect(slotfunc)30433044 def emit(self, record):3045 s = self.format(record)3046 self.signaller.signal.emit(s, record)30473048#3049# В этом примере используются QThreads, что означает, что потоки на уровне Python3050# называются как-то вроде "Dummy-1". Функция ниже получает имя Qt3051# текущего потока.3052#3053def ctname():3054 return QtCore.QThread.currentThread().objectName()30553056#3057# Используется для генерации случайных уровней для логирования.3058#3059LEVELS = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,3060 logging.CRITICAL)30613062#3063# Этот класс-воркер представляет работу, выполняемую в потоке, отдельном от3064# главного потока. Поток запускается на выполнение работы по нажатию кнопки,3065# которая соединяется со слотом в воркере.3066#3067# Поскольку значение threadName по умолчанию в LogRecord не очень полезно, мы добавляем3068# qThreadName, содержащий имя QThread, вычисленное выше, и передаём это3069# значение в словаре "extra", который используется для обновления LogRecord с помощью3070# имя QThread.3071#3072# Этот пример рабочего просто выводит сообщения последовательно, перемежая их случайными задержками порядка нескольких секунд.3073# Позволяет потоку выполняться до прерывания. Это обеспечивает достаточно чистую остановку потока.3074#3075class Worker(QtCore.QObject):3076 @Slot()3077 def start(self):3078 extra = {'qThreadName': ctname() }3079 logger.debug('Started work', extra=extra)3080 i = 13081 # Реализует простой пользовательский интерфейс для этого примера из кулинарной книги. Он содержит:3082 # * Окно текстового редактора только для чтения, которое содержит форматированные сообщения журнала3083 while not QtCore.QThread.currentThread().isInterruptionRequested():3084 delay = 0.5 + random.random() * 23085 time.sleep(delay)3086 try:3087 if random.random() < 0.1:3088 raise ValueError('Exception raised: %d' % i)3089 else:3090 level = random.choice(LEVELS)3091 logger.log(level, 'Message after delay of %3.1f: %d', delay, i, extra=extra)3092 except ValueError as e:3093 logger.exception('Failed: %s', e, extra=extra)3094 i += 130953096#3097# * Кнопка запуска работы и записи в журнал в отдельном потоке3098#3099# * Кнопка записи чего-либо из основного потока3100# * Кнопка очистки окна журнала3101# Устанавливает моноширинный шрифт, принятый по умолчанию на платформе3102# для Qt63103#3104class Window(QtWidgets.QWidget):31053106 COLORS = {3107 logging.DEBUG: 'black',3108 logging.INFO: 'blue',3109 logging.WARNING: 'orange',3110 logging.ERROR: 'red',3111 logging.CRITICAL: 'purple',3112 }31133114 def __init__(self, app):3115 super().__init__()3116 self.app = app3117 self.textedit = te = QtWidgets.QPlainTextEdit(self)3118 # Устанавливает моноширинный шрифт по умолчанию для платформы3119 f = QtGui.QFont('nosuchfont')3120 if hasattr(f, 'Monospace'):3121 f.setStyleHint(f.Monospace)3122 else:3123 f.setStyleHint(f.StyleHint.Monospace) # для Qt63124 te.setFont(f)3125 te.setReadOnly(True)3126 PB = QtWidgets.QPushButton3127 self.work_button = PB('Start background work', self)3128 self.log_button = PB('Log a message at a random level', self)3129 self.clear_button = PB('Clear log window', self)3130 self.handler = h = QtHandler(self.update_status)3131 # Размещает все виджеты3132 fs = '%(asctime)s %(qThreadName)-12s %(levelname)-8s %(message)s'3133 formatter = logging.Formatter(fs)3134 h.setFormatter(formatter)3135 logger.addHandler(h)3136 # Подключает слоты и сигналы, не относящиеся к рабочему3137 app.aboutToQuit.connect(self.force_quit)31383139 # Запускает новый рабочий поток и подключает слоты для рабочего3140 layout = QtWidgets.QVBoxLayout(self)3141 layout.addWidget(te)3142 layout.addWidget(self.work_button)3143 layout.addWidget(self.log_button)3144 layout.addWidget(self.clear_button)3145 self.setFixedSize(900, 400)31463147 # После запуска кнопка должна быть отключена3148 self.log_button.clicked.connect(self.manual_update)3149 self.clear_button.clicked.connect(self.clear_display)31503151 # Запустить новый рабочий поток и подключить слоты для рабочего3152 self.start_thread()3153 self.work_button.clicked.connect(self.worker.start)3154 # Это запустит цикл событий в рабочем потоке3155 self.work_button.clicked.connect(lambda : self.work_button.setEnabled(False))31563157 def start_thread(self):3158 self.worker = Worker()3159 self.worker_thread = QtCore.QThread()3160 self.worker.setObjectName('Worker')3161 self.worker_thread.setObjectName('WorkerThread') # Просто скажите рабочему остановиться, затем скажите ему выйти и дождитесь этого3162 self.worker.moveToThread(self.worker_thread)3163 # Для использования при закрытии окна3164 self.worker_thread.start()31653166 def kill_thread(self):3167 # Функции ниже обновляют интерфейс и выполняются в основном потоке, поскольку слоты настроены именно там3168 # Эта функция использует переданное форматированное сообщение, но также использует информацию из записи, чтобы отформатировать сообщение подходящим цветом в соответствии с его серьёзностью (уровнем).3169 self.worker_thread.requestInterruption()3170 if self.worker_thread.isRunning():3171 self.worker_thread.quit()3172 self.worker_thread.wait()3173 else:3174 print('worker has already exited.')31753176 def force_quit(self):3177 # Для использования при закрытии окна3178 if self.worker_thread.isRunning():3179 self.kill_thread()31803181 # Функции ниже обновляют пользовательский интерфейс и выполняются в главном потоке, потому что3182 # здесь настраиваются слоты31833184 @Slot(str, logging.LogRecord)3185 def update_status(self, status, record):3186 color = self.COLORS.get(record.levelno, 'black')3187 s = '<pre><font color="%s">%s</font></pre>' % (color, status)3188 self.textedit.appendHtml(s)31893190 @Slot()3191 def manual_update(self):3192 # Эта функция использует переданное форматированное сообщение, а также использует3193 # информацию из записи для форматирования сообщения в подходящий3194 # цвет в соответствии с его серьёзностью (уровнем).3195 level = random.choice(LEVELS)3196 extra = {'qThreadName': ctname() }3197 logger.log(level, 'Manually logged!', extra=extra)31983199 @Slot()3200 def clear_display(self):3201 self.textedit.clear()32023203def main():3204 QtCore.QThread.currentThread().setObjectName('MainThread')3205 logging.getLogger().setLevel(logging.DEBUG)3206 app = QtWidgets.QApplication(sys.argv)3207 example = Window(app)3208 example.show()3209 if hasattr(app, 'exec'):3210 rc = app.exec()3211 else:3212 rc = app.exec_()3213 sys.exit(rc)32143215if __name__=='__main__':3216 main()3217```32183219## Журналирование в syslog с поддержкой RFC 542432203221Хотя [**RFC 5424**](https://python-all.ru/3.14/howto/logging-cookbook.html) датируется 2009 годом, большинство syslog-серверов по умолчанию настроены на использование более старого [**RFC 3164**](https://python-all.ru/3.14/howto/logging-cookbook.html), который появился в 2001 году. Когда `logging` был добавлен в Python в 2003 году, он поддерживал тогдашний (и единственный существующий) протокол. С момента выхода RFC 5424, из-за отсутствия его широкого распространения среди syslog-серверов, функциональность [`SysLogHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.handlers.SysLogHandler) не обновлялась.32223223RFC 5424 содержит полезные возможности, такие как поддержка структурированных данных. Если необходимо вести журналирование на syslog-сервер с поддержкой этого протокола, это можно сделать с помощью подкласса обработчика, который выглядит примерно так:32243225```python3226import datetime as dt3227import logging.handlers3228import re3229import socket3230import time32313232class SysLogHandler5424(logging.handlers.SysLogHandler):32333234 tz_offset = re.compile(r'([+-]\d{2})(\d{2})$')3235 escaped = re.compile(r'([\]"\\])')32363237 def __init__(self, *args, **kwargs):3238 self.msgid = kwargs.pop('msgid', None)3239 self.appname = kwargs.pop('appname', None)3240 super().__init__(*args, **kwargs)32413242 def format(self, record):3243 version = 13244 asctime = dt.datetime.fromtimestamp(record.created).isoformat()3245 m = self.tz_offset.match(time.strftime('%z'))3246 has_offset = False3247 if m and time.timezone:3248 hrs, mins = m.groups()3249 if int(hrs) or int(mins):3250 has_offset = True3251 if not has_offset:3252 asctime += 'Z'3253 else:3254 asctime += f'{hrs}:{mins}'3255 try:3256 hostname = socket.gethostname()3257 except Exception:3258 hostname = '-'3259 appname = self.appname or '-'3260 procid = record.process3261 msgid = '-'3262 msg = super().format(record)3263 sdata = '-'3264 if hasattr(record, 'structured_data'):3265 sd = record.structured_data3266 # Это должен быть словарь, где ключи – SD-ID, а значение –3267 # словарь, отображающий PARAM-NAME на PARAM-VALUE (обратитесь к RFC, чтобы узнать, что эти3268 # означают)3269 # Здесь нет проверки ошибок – это только для иллюстрации, и вы3270 # можете адаптировать этот код для использования в производственных средах3271 parts = []32723273 def replacer(m):3274 g = m.groups()3275 return '\\' + g[0]32763277 for sdid, dv in sd.items():3278 part = f'[{sdid}'3279 for k, v in dv.items():3280 s = str(v)3281 s = self.escaped.sub(replacer, s)3282 part += f' {k}="{s}"'3283 part += ']'3284 parts.append(part)3285 sdata = ''.join(parts)3286 return f'{version} {asctime} {hostname} {appname} {procid} {msgid} {sdata} {msg}'3287```32883289Чтобы полностью разобраться в приведённом коде, потребуется знакомство с RFC 5424. Возможно, ваши потребности будут несколько иными (например, в способе передачи структурированных данных в журнал). Тем не менее, приведённый код можно адаптировать под конкретные нужды. С таким обработчиком структурированные данные передаются, например, так:32903291```python3292sd = {3293 'foo@12345': {'bar': 'baz', 'baz': 'bozz', 'fizz': r'buzz'},3294 'foo@54321': {'rab': 'baz', 'zab': 'bozz', 'zzif': r'buzz'}3295}3296extra = {'structured_data': sd}3297i = 13298logger.debug('Message %d', i, extra=extra)3299```33003301## Как использовать объект Logger как выходной поток33023303Иногда возникает необходимость взаимодействовать со сторонним API, который ожидает объект, подобный файлу, для записи, но при этом нужно перенаправить вывод API в журнал. Это можно сделать с помощью класса, который оборачивает объект Logger, предоставляя файлоподобный интерфейс. Вот короткий скрипт, иллюстрирующий такой класс:33043305```python3306import logging33073308class LoggerWriter:3309 def __init__(self, logger, level):3310 self.logger = logger3311 self.level = level33123313 def write(self, message):3314 if message != '\n': # избегайте печати пустых строк, если хотите3315 self.logger.log(self.level, message)33163317 def flush(self):3318 # на самом деле ничего не делает, но может ожидаться от файлоподобного3319 # объекта – так что опционально в зависимости от вашей ситуации3320 pass33213322 def close(self):3323 # на самом деле ничего не делает, но может ожидаться от файлоподобного3324 # объекта – так что опционально в зависимости от вашей ситуации. Возможно, вы захотите3325 # установить флаг, чтобы последующие вызовы write вызывали исключение3326 pass33273328def main():3329 logging.basicConfig(level=logging.DEBUG)3330 logger = logging.getLogger('demo')3331 info_fp = LoggerWriter(logger, logging.INFO)3332 debug_fp = LoggerWriter(logger, logging.DEBUG)3333 print('An INFO message', file=info_fp)3334 print('A DEBUG message', file=debug_fp)33353336if __name__ == "__main__":3337 main()3338```33393340При запуске этот скрипт выводит33413342```text3343INFO:demo:An INFO message3344DEBUG:demo:A DEBUG message3345```33463347Можно также использовать `LoggerWriter` для перенаправления `sys.stdout` и `sys.stderr`, сделав примерно так:33483349```python3350import sys33513352sys.stdout = LoggerWriter(logger, logging.INFO)3353sys.stderr = LoggerWriter(logger, logging.WARNING)3354```33553356Это следует делать *после* настройки журналирования под свои нужды. В приведённом выше примере вызов [`basicConfig()`](https://python-all.ru/3.14/library/logging.html#logging.basicConfig) делает это (используя значение `sys.stderr` *до* того, как оно будет перезаписано экземпляром `LoggerWriter`). В результате получится примерно такой вывод:33573358```pycon3359>>> print('Foo')3360INFO:demo:Foo3361>>> print('Bar', file=sys.stderr)3362WARNING:demo:Bar3363>>>3364```33653366Разумеется, приведённые выше примеры показывают вывод в формате, используемом [`basicConfig()`](https://python-all.ru/3.14/library/logging.html#logging.basicConfig), но при настройке журналирования можно использовать другой форматтер.33673368Обратите внимание, что при такой схеме вы в значительной степени зависите от буферизации и порядка вызовов write, которые перехватываете. Например, при определении `LoggerWriter` выше, если есть такой фрагмент кода:33693370```python3371sys.stderr = LoggerWriter(logger, logging.WARNING)33721 / 03373```33743375то запуск скрипта даёт33763377```text3378WARNING:demo:Traceback (most recent call last):33793380WARNING:demo: File "/home/runner/cookbook-loggerwriter/test.py", line 53, in <module>33813382WARNING:demo:3383WARNING:demo:main()3384WARNING:demo: File "/home/runner/cookbook-loggerwriter/test.py", line 49, in main33853386WARNING:demo:3387WARNING:demo:1 / 03388WARNING:demo:ZeroDivisionError3389WARNING:demo::3390WARNING:demo:division by zero3391```33923393Как видите, такой вывод неидеален. Это происходит потому, что код, который пишет в `sys.stderr`, выполняет несколько записей, и каждая из них приводит к отдельной строке в журнале (например, три последние строки выше). Чтобы обойти эту проблему, нужно буферизовать данные и выводить строки журнала только при появлении символов новой строки. Давайте используем немного улучшенную реализацию `LoggerWriter`:33943395```python3396class BufferingLoggerWriter(LoggerWriter):3397 def __init__(self, logger, level):3398 super().__init__(logger, level)3399 self.buffer = ''34003401 def write(self, message):3402 if '\n' not in message:3403 self.buffer += message3404 else:3405 parts = message.split('\n')3406 if self.buffer:3407 s = self.buffer + parts.pop(0)3408 self.logger.log(self.level, s)3409 self.buffer = parts.pop()3410 for part in parts:3411 self.logger.log(self.level, part)3412```34133414Этот код просто буферизует данные до появления символа новой строки, после чего записывает полные строки. С таким подходом вывод становится лучше:34153416```text3417WARNING:demo:Traceback (most recent call last):3418WARNING:demo: File "/home/runner/cookbook-loggerwriter/main.py", line 55, in <module>3419WARNING:demo: main()3420WARNING:demo: File "/home/runner/cookbook-loggerwriter/main.py", line 52, in main3421WARNING:demo: 1/03422WARNING:demo:ZeroDivisionError: division by zero3423```34243425## Как единообразно обрабатывать символы новой строки в выводе журнала34263427Обычно записываемые в журнал сообщения (например, в консоль или файл) состоят из одной строки текста. Однако иногда возникает необходимость обрабатывать сообщения, содержащие несколько строк – будь то из-за того, что форматная строка логгера содержит символы новой строки, или сами данные содержат такие символы. Чтобы единообразно обрабатывать такие сообщения, при этом каждая строка в записанном сообщении форматировалась так, как если бы она была записана отдельно, можно использовать примесь-обработчик, как в следующем примере:34283429```python3430# Предположим, это находится в модуле mymixins.py3431import copy34323433class MultilineMixin:3434 def emit(self, record):3435 s = record.getMessage()3436 if '\n' not in s:3437 super().emit(record)3438 else:3439 lines = s.splitlines()3440 rec = copy.copy(record)3441 rec.args = None3442 for line in lines:3443 rec.msg = line3444 super().emit(rec)3445```34463447Использовать эту примесь можно, как в следующем скрипте:34483449```python3450import logging34513452from mymixins import MultilineMixin34533454logger = logging.getLogger(__name__)34553456class StreamHandler(MultilineMixin, logging.StreamHandler):3457 pass34583459if __name__ == '__main__':3460 logging.basicConfig(level=logging.DEBUG, format='%(asctime)s %(levelname)-9s %(message)s',3461 handlers = [StreamHandler()])3462 logger.debug('Single line')3463 logger.debug('Multiple lines:\nfool me once ...')3464 logger.debug('Another single line')3465 logger.debug('Multiple lines:\n%s', 'fool me ...\ncan\'t get fooled again')3466```34673468Скрипт при запуске выводит примерно следующее:34693470```text34712025-07-02 13:54:47,234 DEBUG Single line34722025-07-02 13:54:47,234 DEBUG Multiple lines:34732025-07-02 13:54:47,234 DEBUG fool me once ...34742025-07-02 13:54:47,234 DEBUG Another single line34752025-07-02 13:54:47,234 DEBUG Multiple lines:34762025-07-02 13:54:47,234 DEBUG fool me ...34772025-07-02 13:54:47,234 DEBUG can't get fooled again3478```34793480Если же вас беспокоит [внедрение в журнал (log injection)](https://python-all.ru/3.14/howto/logging-cookbook.html), можно использовать форматтер, экранирующий символы новой строки, как в следующем примере:34813482```python3483import logging34843485logger = logging.getLogger(__name__)34863487class EscapingFormatter(logging.Formatter):3488 def format(self, record):3489 s = super().format(record)3490 return s.replace('\n', r'\n')34913492if __name__ == '__main__':3493 h = logging.StreamHandler()3494 h.setFormatter(EscapingFormatter('%(asctime)s %(levelname)-9s %(message)s'))3495 logging.basicConfig(level=logging.DEBUG, handlers = [h])3496 logger.debug('Single line')3497 logger.debug('Multiple lines:\nfool me once ...')3498 logger.debug('Another single line')3499 logger.debug('Multiple lines:\n%s', 'fool me ...\ncan\'t get fooled again')3500```35013502Разумеется, можно применять любую схему экранирования, наиболее подходящую для ваших задач. При запуске скрипт должен выдать вывод, похожий на этот:35033504```text35052025-07-09 06:47:33,783 DEBUG Single line35062025-07-09 06:47:33,783 DEBUG Multiple lines:\nfool me once ...35072025-07-09 06:47:33,783 DEBUG Another single line35082025-07-09 06:47:33,783 DEBUG Multiple lines:\nfool me ...\ncan't get fooled again3509```35103511Поведение с экранированием не может быть установлено по умолчанию в stdlib, поскольку это нарушило бы обратную совместимость.35123513## Шаблоны, которых следует избегать35143515Хотя в предыдущих разделах были описаны способы решения задач, с которыми вы можете столкнуться, стоит упомянуть некоторые шаблоны использования, которые *бесполезны* и в большинстве случаев их следует избегать. Следующие разделы приведены в произвольном порядке.35163517### Многократное открытие одного и того же файла журнала35183519В Windows обычно не получится открыть один и тот же файл несколько раз, так как это приведёт к ошибке «файл используется другим процессом». Однако на платформах POSIX никаких ошибок при многократном открытии одного файла не возникнет. Это может произойти случайно, например:35203521- Добавление файлового обработчика более одного раза со ссылкой на один и тот же файл (например, из-за ошибки копирования/вставки/забыли изменить).3522- Открытие двух файлов, которые выглядят разными (у них разные имена), но на самом деле являются одним и тем же файлом, так как один – символическая ссылка на другой.3523- Порождение процесса (форк), после которого и родительский, и дочерний процесс имеют ссылку на один и тот же файл. Это может происходить, например, при использовании модуля [`multiprocessing`](https://python-all.ru/3.14/library/multiprocessing.html#module-multiprocessing).35243525Многократное открытие файла может *выглядеть* работающим большую часть времени, но на практике может привести к ряду проблем:35263527- Вывод логирования может искажаться, поскольку несколько потоков или процессов пытаются писать в один и тот же файл. Хотя логирование защищает от одновременного использования одного и того же экземпляра обработчика несколькими потоками, такой защиты нет, если одновременную запись пытаются выполнить два разных потока, использующие два разных экземпляра обработчика, которые указывают на один и тот же файл.3528- Попытка удалить файл (например, во время ротации) молча завершается неудачей, потому что есть другая ссылка на него. Это может привести к путанице и потере времени на отладку – записи журнала оказываются в неожиданных местах или полностью теряются. Или файл, который должен был быть перемещён, остаётся на месте и неожиданно растёт в размерах, несмотря на то что ротация по размеру якобы настроена.35293530Используйте методы, описанные в [Логирование в один файл из нескольких процессов](https://python-all.ru/3.14/howto/logging-cookbook.html#multiple-processes), чтобы обойти такие проблемы.35313532### Использование логгеров в качестве атрибутов класса или передача их в качестве параметров35333534Хотя могут быть необычные случаи, когда это необходимо, в целом в этом нет смысла, потому что логгеры – синглтоны. Код всегда может получить доступ к нужному экземпляру логгера по имени с помощью `logging.getLogger(name)`, поэтому передавать экземпляры повсюду и хранить их в качестве атрибутов экземпляра бессмысленно. Обратите внимание, что в других языках, таких как Java и C#, логгеры часто являются статическими атрибутами класса. Однако этот шаблон не имеет смысла в Python, где модуль (а не класс) является единицей декомпозиции программного обеспечения.35353536### Добавление обработчиков, отличных от [`NullHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.NullHandler), к логгеру в библиотеке35373538Настройка логирования путём добавления обработчиков, форматировщиков и фильтров – это ответственность разработчика приложения, а не разработчика библиотеки. Если вы поддерживаете библиотеку, убедитесь, что не добавляете обработчики ни к одному из своих логгеров, кроме экземпляра [`NullHandler`](https://python-all.ru/3.14/library/logging.handlers.html#logging.NullHandler).35393540### Создание большого количества логгеров35413542Логгеры – это синглтоны, которые никогда не освобождаются во время выполнения скрипта, поэтому создание большого количества логгеров приведёт к расходу памяти, которую затем нельзя освободить. Вместо того чтобы создавать логгер для каждого обрабатываемого файла или сетевого соединения, используйте [существующие механизмы](https://python-all.ru/3.14/howto/logging-cookbook.html#context-info) для передачи контекстной информации в ваши журналы и ограничьте создаваемые логгеры теми, которые описывают области вашего приложения (обычно модули, но иногда и с чуть большей детализацией).35433544## Другие ресурсы35453546> **См. также**3547>3548> **Модуль [`logging`](https://python-all.ru/3.14/library/logging.html#module-logging)**3549>3550> Справочник API для модуля logging.3551>3552> **Модуль [`logging.config`](https://python-all.ru/3.14/library/logging.config.html#module-logging.config)**3553>3554> API конфигурации для модуля logging.3555>3556> **Модуль [`logging.handlers`](https://python-all.ru/3.14/library/logging.handlers.html#module-logging.handlers)**3557>3558> Полезные обработчики, входящие в состав модуля logging.3559>3560> [Базовое руководство](https://python-all.ru/3.14/howto/logging.html#logging-basic-tutorial)3561>3562> [Продвинутое руководство](https://python-all.ru/3.14/howto/logging.html#logging-advanced-tutorial)3563