logging-cookbook.md
1> **Источник:** https://python-all.ru/3.10/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.10/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.10/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.10/library/logging.handlers.html#logging.handlers.SMTPHandler): отправка электронной почты может занимать много времени по ряду причин, не зависящих от разработчика (например, из-за плохой работы почтовой или сетевой инфраструктуры). Но почти любой сетевой обработчик может блокировать: даже операция [`SocketHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.SocketHandler) может выполнять DNS-запрос «под капотом», который оказывается слишком медленным (и этот запрос может быть глубоко в коде библиотеки сокетов, ниже уровня Python и вне вашего контроля).504505Одно из решений – использовать двухчастный подход. На первом этапе к логгерам, к которым обращаются из критичных по производительности потоков, следует подключать только [`QueueHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.QueueHandler). Они просто пишут в свою очередь, которую можно настроить на достаточно большую ёмкость или инициализировать без верхнего ограничения размера. Запись в очередь обычно выполняется быстро, хотя в коде желательно перехватывать исключение [`queue.Full`](https://python-all.ru/3.10/library/queue.html#queue.Full) на всякий случай. Если вы – разработчик библиотеки, в коде которой есть критичные по производительности потоки, обязательно задокументируйте это (вместе с рекомендацией подключать к вашим логгерам только `QueueHandlers`) для пользы других разработчиков, которые будут использовать ваш код.506507Вторая часть решения – [`QueueListener`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.QueueListener), который был разработан как аналог [`QueueHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.QueueHandler). [`QueueListener`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.QueueListener) устроен очень просто: ему передаётся очередь и несколько обработчиков, и он запускает внутренний поток, который слушает свою очередь на предмет LogRecords, отправленных из `QueueHandlers` (или любого другого источника `LogRecords`). `LogRecords` извлекаются из очереди и передаются обработчикам для обработки.508509Преимущество отдельного класса [`QueueListener`](https://python-all.ru/3.10/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.10/library/asyncio.html#module-asyncio). Поэтому, если в приложении используется асинхронный код, лучше всего применять описанный выше подход к логированию, чтобы любой блокирующий код выполнялся только в `QueueListener` потоке.540541Изменено в версии 3.5: До Python 3.5 [`QueueListener`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.QueueListener) всегда передавал каждое полученное из очереди сообщение каждому обработчику, с которыми был инициализирован. (Это объяснялось тем, что предполагалось, что фильтрация по уровню полностью выполняется на стороне наполнения очереди.) Начиная с версии 3.5 это поведение можно изменить, передав именованный аргумент `respect_handler_level=True` конструктору слушателя. Когда это сделано, слушатель сравнивает уровень каждого сообщения с уровнем обработчика и передаёт сообщение обработчику, только если это уместно.542543## Отправка и получение событий логирования по сети544545Допустим, вы хотите отправлять события логирования по сети и обрабатывать их на принимающей стороне. Простой способ – подключить экземпляр [`SocketHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.SocketHandler) к корневому логгеру на отправляющей стороне:546547```python548import logging, logging.handlers549550rootLogger = logging.getLogger('')551rootLogger.setLevel(logging.DEBUG)552socketHandler = logging.handlers.SocketHandler('localhost',553 logging.handlers.DEFAULT_TCP_LOGGING_PORT)554# Не нужно использовать форматтер, так как сокет-обработчик отправляет событие в виде неформатированного пикла.555# неформатированный pickle556rootLogger.addHandler(socketHandler)557558# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...559logging.info('Jackdaws love my big sphinx of quartz.')560561# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:562# приложение:563564logger1 = logging.getLogger('myapp.area1')565logger2 = logging.getLogger('myapp.area2')566567logger1.debug('Quick zephyrs blow, vexing daft Jim.')568logger1.info('How quickly daft jumping zebras vex.')569logger2.warning('Jail zesty vixen who grabbed pay from quack.')570logger2.error('The five boxing wizards jump quickly.')571```572573На принимающей стороне можно настроить приёмник с помощью модуля [`socketserver`](https://python-all.ru/3.10/library/socketserver.html#module-socketserver). Вот простой работающий пример:574575```python576import pickle577import logging578import logging.handlers579import socketserver580import struct581582class LogRecordStreamHandler(socketserver.StreamRequestHandler):583 """Обработчик для потокового запроса логирования.584585 Это по сути записывает запись, используя ту политику логирования, которая настроена локально.586 настроено локально.587 """588589 def handle(self):590 """591 Обрабатывает несколько запросов – каждый ожидается в формате: 4-байтовая длина, затем запись журнала в формате пикл.592 Записывает запись в соответствии с политикой, настроенной локально.593 согласно локально настроенной политике.594 """595 while True:596 chunk = self.connection.recv(4)597 if len(chunk) < 4:598 break599 slen = struct.unpack('>L', chunk)[0]600 chunk = self.connection.recv(slen)601 while len(chunk) < slen:602 chunk = chunk + self.connection.recv(slen - len(chunk))603 obj = self.unPickle(chunk)604 record = logging.makeLogRecord(obj)605 self.handleLogRecord(record)606607 def unPickle(self, data):608 return pickle.loads(data)609610 def handleLogRecord(self, record):611 # Если указано имя, используется именованный логгер, а не тот, что612 # подразумевается записью.613 if self.server.logname is not None:614 name = self.server.logname615 else:616 name = record.name617 logger = logging.getLogger(name)618 # Примечание: КАЖДАЯ запись попадает в журнал. Это связано с тем, что Logger.handle619 # обычно вызывается ПОСЛЕ фильтрации на уровне регистратора. Если требуется620 # выполнять фильтрацию, делайте это на стороне клиента, чтобы не тратить621 # циклы процессора и сетевую пропускную способность!622 logger.handle(record)623624class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):625 """626 Простой приёмник журнала на основе TCP-сокетов, подходящий для тестирования.627 """628629 allow_reuse_address = True630631 def __init__(self, host='localhost',632 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,633 handler=LogRecordStreamHandler):634 socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)635 self.abort = 0636 self.timeout = 1637 self.logname = None638639 def serve_until_stopped(self):640 import select641 abort = 0642 while not abort:643 rd, wr, ex = select.select([self.socket.fileno()],644 [], [],645 self.timeout)646 if rd:647 self.handle_request()648 abort = self.abort649650def main():651 logging.basicConfig(652 format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')653 tcpserver = LogRecordSocketReceiver()654 print('About to start TCP server...')655 tcpserver.serve_until_stopped()656657if __name__ == '__main__':658 main()659```660661Сначала запустите сервер, затем клиент. На стороне клиента в консоль ничего не выводится; на стороне сервера вы должны увидеть что-то вроде:662663```text664About to start TCP server...665 59 root INFO Jackdaws love my big sphinx of quartz.666 59 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim.667 69 myapp.area1 INFO How quickly daft jumping zebras vex.668 69 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack.669 69 myapp.area2 ERROR The five boxing wizards jump quickly.670```671672Обратите внимание, что в некоторых сценариях существуют проблемы безопасности с pickle. Если они вас затрагивают, вы можете использовать альтернативную схему сериализации, переопределив метод `makePickle()` и реализовав свою альтернативу там, а также адаптировав вышеприведённый скрипт для использования вашей альтернативной сериализации.673674### Запуск сокетного слушателя логирования в продакшене675676Для запуска слушателя логирования в продакшене может потребоваться инструмент управления процессами, такой как [Supervisor](https://python-all.ru/3.10/howto/logging-cookbook.html). [Вот Gist](https://python-all.ru/3.10/howto/logging-cookbook.html), который содержит минимальные файлы для запуска описанной выше функциональности с помощью Supervisor. Он состоит из следующих файлов:677678| Файл | Назначение |679| --- | --- |680| `prepare.sh` | Bash-скрипт для подготовки окружения к тестированию |681| `supervisor.conf` | Файл конфигурации Supervisor с записями для слушателя и многопроцессного веб-приложения |682| `ensure_app.sh` | Bash-скрипт для обеспечения работы Supervisor с указанной конфигурацией |683| `log_listener.py` | Программа сокетного слушателя, которая получает события логирования и записывает их в файл |684| `main.py` | Простое веб-приложение, которое выполняет логирование через сокет, подключённый к слушателю |685| `webapp.json` | JSON-файл конфигурации для веб-приложения |686| `client.py` | Python-скрипт для тестирования веб-приложения |687688Веб-приложение использует [Gunicorn](https://python-all.ru/3.10/howto/logging-cookbook.html) – популярный сервер веб-приложений, который запускает несколько рабочих процессов для обработки запросов. Данный пример показывает, как рабочие процессы могут писать в один и тот же файл журнала, не мешая друг другу – все они проходят через сокетный слушатель.689690Чтобы протестировать эти файлы, выполните следующие действия в среде POSIX:6916921. Скачайте [Gist](https://python-all.ru/3.10/howto/logging-cookbook.html) в виде ZIP-архива, используя кнопку Download ZIP.6932. Распакуйте указанные файлы из архива во временный каталог.6943. Во временном каталоге выполните `bash prepare.sh` для подготовки. При этом будут созданы подкаталог `run` для файлов, связанных с Supervisor, и журналов, а также подкаталог `venv` для виртуального окружения, в которое будут установлены `bottle`, `gunicorn` и `supervisor`.6954. Запустите `bash ensure_app.sh`, чтобы убедиться, что Supervisor работает с указанной выше конфигурацией.6965. Запустите `venv/bin/python client.py` для проверки веб-приложения, что приведёт к записи данных в журнал.6976. Проверьте файлы журналов в подкаталоге `run`. Вы должны увидеть самые свежие строки журнала в файлах, соответствующих шаблону `app.log*`. Они не будут в каком-либо определённом порядке, поскольку обрабатываются параллельно разными рабочими процессами недетерминированным образом.6987. Вы можете остановить слушатель и веб-приложение, выполнив `venv/bin/supervisorctl -c supervisor.conf shutdown`.699700Возможно, потребуется подправить файлы конфигурации в маловероятном случае, если настроенные порты конфликтуют с чем-либо ещё в вашей тестовой среде.701702## Добавление контекстной информации в вывод журнала703704Иногда требуется, чтобы вывод журнала содержал контекстную информацию в дополнение к параметрам, переданным в вызове логирования. Например, в сетевом приложении может быть желательно записывать в журнал информацию, специфичную для клиента (например, имя пользователя удалённого клиента или IP-адрес). Хотя для этого можно использовать параметр *extra*, не всегда удобно передавать информацию таким образом. Может возникнуть соблазн создавать экземпляры `Logger` для каждого соединения, но это плохая идея, поскольку такие экземпляры не собираются сборщиком мусора. Хотя на практике это не проблема, когда количество экземпляров `Logger` зависит от уровня детализации, используемого при логировании приложения, управление ими может стать сложным, если количество экземпляров `Logger` станет фактически неограниченным.705706### Использование LoggerAdapter для добавления контекстной информации707708Простой способ передавать контекстную информацию для вывода вместе с информацией о событиях логирования – использовать класс `LoggerAdapter`. Этот класс спроектирован так, чтобы выглядеть как `Logger`, что позволяет вызывать `debug()`, `info()`, `warning()`, `error()`, `exception()`, `critical()` и `log()`. Эти методы имеют те же сигнатуры, что и их аналоги в `Logger`, поэтому экземпляры обоих типов можно использовать взаимозаменяемо.709710При создании экземпляра `LoggerAdapter` вы передаёте ему экземпляр `Logger` и объект, подобный словарю, содержащий вашу контекстную информацию. Когда вы вызываете один из методов логирования на экземпляре `LoggerAdapter`, он делегирует вызов базовому экземпляру `Logger`, переданному в конструктор, и организует передачу контекстной информации в этом делегированном вызове. Вот фрагмент кода `LoggerAdapter`:711712```python713def debug(self, msg, /, *args, **kwargs):714 """715 Передаёт вызов отладки нижележащему регистратору после добавления716 контекстной информации из данного экземпляра адаптера.717 """718 msg, kwargs = self.process(msg, kwargs)719 self.logger.debug(msg, *args, **kwargs)720```721722Метод `process()` класса `LoggerAdapter` – это то место, где контекстная информация добавляется в вывод журнала. Ему передаются сообщение и именованные аргументы вызова логирования, а он возвращает (потенциально) изменённые версии для использования в вызове базового регистратора. В реализации по умолчанию этот метод оставляет сообщение без изменений, но вставляет ключ 'extra' в именованные аргументы, значением которого является объект, подобный словарю, переданный конструктору. Конечно, если вы передали именованный аргумент 'extra' в вызове адаптера, он будет молча перезаписан.723724Преимущество использования 'extra' в том, что значения из объекта, подобного словарю, сливаются в \_\_dict\_\_ экземпляра `LogRecord`, что позволяет использовать настроенные строки с экземплярами `Formatter`, которые знают о ключах этого объекта. Если вам нужен другой метод, например, добавить контекстную информацию в начало или конец строки сообщения, достаточно создать подкласс `LoggerAdapter` и переопределить `process()` для нужного поведения. Вот простой пример:725726```python727class CustomAdapter(logging.LoggerAdapter):728 """729 Данный пример адаптера ожидает, что переданный объект, подобный словарю, содержит730 ключ 'connid', значение которого в квадратных скобках добавляется к началу сообщения журнала.731 """732 def process(self, msg, kwargs):733 return '[%s] %s' % (self.extra['connid'], msg), kwargs734```735736который можно использовать так:737738```python739logger = logging.getLogger(__name__)740adapter = CustomAdapter(logger, {'connid': some_conn_id})741```742743Тогда все события, регистрируемые через адаптер, будут содержать значение `some_conn_id`, добавленное в начало сообщений журнала.744745#### Использование объектов, отличных от словарей, для передачи контекстной информации746747Необязательно передавать в `LoggerAdapter` именно словарь – можно передать экземпляр класса, реализующего `__getitem__` и `__iter__`, чтобы он выглядел как словарь для системы логирования. Это полезно, если нужно генерировать значения динамически (тогда как значения в словаре были бы постоянными).748749### Использование фильтров для добавления контекстной информации750751Вы также можете добавлять контекстную информацию в вывод журнала с помощью определённого пользователем `Filter`. Экземплярам `Filter` разрешено изменять `LogRecords`, переданный им, включая добавление дополнительных атрибутов, которые затем можно выводить с помощью подходящей форматной строки или, если необходимо, пользовательского `Formatter`.752753Например, в веб-приложении обрабатываемый запрос (или, по крайней мере, его интересные части) можно сохранить в потоковой локальной переменной ([`threading.local`](https://python-all.ru/3.10/library/threading.html#threading.local)), а затем из `Filter` получить к ней доступ, чтобы добавить, скажем, информацию из запроса – например, удалённый IP-адрес и имя пользователя – в `LogRecord`, используя имена атрибутов 'ip' и 'user', как в примере с `LoggerAdapter` выше. В этом случае можно использовать ту же форматную строку для получения вывода, аналогичного показанному выше. Вот пример скрипта:754755```python756import logging757from random import choice758759class ContextFilter(logging.Filter):760 """761 Это фильтр, который внедряет контекстную информацию в журнал.762763 Вместо использования реальной контекстной информации в данном примере используются случайные764 данные.765 """766767 USERS = ['jim', 'fred', 'sheila']768 IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']769770 def filter(self, record):771772 record.ip = choice(ContextFilter.IPS)773 record.user = choice(ContextFilter.USERS)774 return True775776if __name__ == '__main__':777 levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)778 logging.basicConfig(level=logging.DEBUG,779 format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')780 a1 = logging.getLogger('a.b.c')781 a2 = logging.getLogger('d.e.f')782783 f = ContextFilter()784 a1.addFilter(f)785 a2.addFilter(f)786 a1.debug('A debug message')787 a1.info('An info message with %s', 'some parameters')788 for x in range(10):789 lvl = choice(levels)790 lvlname = logging.getLevelName(lvl)791 a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')792```793794который при запуске выдаёт примерно следующее:795796```text7972010-09-06 22:38:15,292 a.b.c DEBUG IP: 123.231.231.123 User: fred A debug message7982010-09-06 22:38:15,300 a.b.c INFO IP: 192.168.0.1 User: sheila An info message with some parameters7992010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters8002010-09-06 22:38:15,300 d.e.f ERROR IP: 127.0.0.1 User: jim A message at ERROR level with 2 parameters8012010-09-06 22:38:15,300 d.e.f DEBUG IP: 127.0.0.1 User: sheila A message at DEBUG level with 2 parameters8022010-09-06 22:38:15,300 d.e.f ERROR IP: 123.231.231.123 User: fred A message at ERROR level with 2 parameters8032010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1 User: jim A message at CRITICAL level with 2 parameters8042010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters8052010-09-06 22:38:15,300 d.e.f DEBUG IP: 192.168.0.1 User: jim A message at DEBUG level with 2 parameters8062010-09-06 22:38:15,301 d.e.f ERROR IP: 127.0.0.1 User: sheila A message at ERROR level with 2 parameters8072010-09-06 22:38:15,301 d.e.f DEBUG IP: 123.231.231.123 User: fred A message at DEBUG level with 2 parameters8082010-09-06 22:38:15,301 d.e.f INFO IP: 123.231.231.123 User: fred A message at INFO level with 2 parameters809```810811## Использование `contextvars`812813Начиная с Python 3.7, модуль [`contextvars`](https://python-all.ru/3.10/library/contextvars.html#module-contextvars) предоставляет контекстно-локальное хранилище, которое работает как для [`threading`](https://python-all.ru/3.10/library/threading.html#module-threading), так и для [`asyncio`](https://python-all.ru/3.10/library/asyncio.html#module-asyncio) обработки. Этот тип хранилища может быть в целом предпочтительнее потоковых локальных переменных. Следующий пример показывает, как в многопоточной среде журналы могут наполняться контекстной информацией, например, атрибутами запросов, обрабатываемых веб-приложениями.814815Для иллюстрации предположим, что у вас есть разные веб-приложения, каждое независимо от других, но запущенные в одном процессе Python и использующие общую для них библиотеку. Как каждое из этих приложений может иметь собственный журнал, где все сообщения логирования из библиотеки (и другого кода обработки запросов) направляются в соответствующий файл журнала приложения, а также включают в журнал дополнительную контекстную информацию, такую как IP-адрес клиента, метод HTTP-запроса и имя пользователя?816817Предположим, что библиотеку можно смоделировать следующим кодом:818819```python820# webapplib.py821import logging822import time823824logger = logging.getLogger(__name__)825826def useful():827 # Просто представительное событие, зарегистрированное из библиотеки828 logger.debug('Hello from webapplib!')829 # Просто приостановить выполнение на некоторое время, чтобы дать возможность другим потокам поработать830 time.sleep(0.01)831```832833Мы можем смоделировать несколько веб-приложений с помощью двух простых классов, `Request` и `WebApp`. Они имитируют работу реальных многопоточных веб-приложений – каждый запрос обрабатывается отдельным потоком:834835```python836# main.py837import argparse838from contextvars import ContextVar839import logging840import os841from random import choice842import threading843import webapplib844845logger = logging.getLogger(__name__)846root = logging.getLogger()847root.setLevel(logging.DEBUG)848849class Request:850 """851 Простой фиктивный класс запроса, который просто хранит фиктивные метод HTTP-запроса,852 IP-адрес клиента и имя пользователя клиента853 """854 def __init__(self, method, ip, user):855 self.method = method856 self.ip = ip857 self.user = user858859# Фиктивный набор запросов, который будет использоваться в симуляции – мы будем просто выбирать860# из этого списка случайным образом. Обратите внимание, что все GET-запросы приходят с адресов 192.168.2.XXX861# адресов, тогда как POST-запросы – с адресов 192.16.3.XXX. В примере запросов представлены три пользователя862# представлены в примере запросов.863864REQUESTS = [865 Request('GET', '192.168.2.20', 'jim'),866 Request('POST', '192.168.3.20', 'fred'),867 Request('GET', '192.168.2.21', 'sheila'),868 Request('POST', '192.168.3.21', 'jim'),869 Request('GET', '192.168.2.22', 'fred'),870 Request('POST', '192.168.3.22', 'sheila'),871]872873# Обратите внимание, что строка форматирования содержит ссылки на контекстную информацию запроса874# такую как HTTP-метод, IP-адрес клиента и имя пользователя875876formatter = logging.Formatter('%(threadName)-11s %(appName)s %(name)-9s %(user)-6s %(ip)s %(method)-4s %(message)s')877878# Создаём контекстные переменные. Они будут заполнены в начале обработки запроса879# и использоваться в журналировании, которое выполняется в ходе этой обработки880881ctx_request = ContextVar('request')882ctx_appname = ContextVar('appname')883884class InjectingFilter(logging.Filter):885 """886 Фильтр, который внедряет в журналы контекстно-зависимую информацию и гарантирует,887 что в его журнал включается только информация для конкретного веб-приложения888 """889 def __init__(self, app):890 self.app = app891892 def filter(self, record):893 request = ctx_request.get()894 record.method = request.method895 record.ip = request.ip896 record.user = request.user897 record.appName = appName = ctx_appname.get()898 return appName == self.app.name899900class WebApp:901 """902 Фиктивный класс веб-приложения, который имеет собственный обработчик и фильтр для903 журнала, специфичного для веб-приложения.904 """905 def __init__(self, name):906 self.name = name907 handler = logging.FileHandler(name + '.log', 'w')908 f = InjectingFilter(self)909 handler.setFormatter(formatter)910 handler.addFilter(f)911 root.addHandler(handler)912 self.num_requests = 0913914 def process_request(self, request):915 """916 Это фиктивный метод обработки запроса. Он вызывается для917 отдельный поток для каждого запроса. Сохраняем информацию контекста в918 контекстные переменные перед тем, как делать что-либо ещё.919 """920 ctx_request.set(request)921 ctx_appname.set(self.name)922 self.num_requests += 1923 logger.debug('Request processing started')924 webapplib.useful()925 logger.debug('Request processing finished')926927def main():928 fn = os.path.splitext(os.path.basename(__file__))[0]929 adhf = argparse.ArgumentDefaultsHelpFormatter930 ap = argparse.ArgumentParser(formatter_class=adhf, prog=fn,931 description='Simulate a couple of web '932 'applications handling some '933 'requests, showing how request '934 'context can be used to '935 'populate logs')936 aa = ap.add_argument937 aa('--count', '-c', type=int, default=100, help='How many requests to simulate')938 options = ap.parse_args()939940 # Создаём фиктивные веб-приложения и помещаем их в список, из которого будем выбирать941 # случайным образом.942 app1 = WebApp('app1')943 app2 = WebApp('app2')944 apps = [app1, app2]945 threads = []946 # Добавляем общий обработчик, который будет перехватывать все события.947 handler = logging.FileHandler('app.log', 'w')948 handler.setFormatter(formatter)949 root.addHandler(handler)950951 # Генерируем вызовы для обработки запросов.952 for i in range(options.count):953 try:954 # Выбираем случайное приложение и запрос для него.955 app = choice(apps)956 request = choice(REQUESTS)957 # Обрабатываем запрос в его собственном потоке.958 t = threading.Thread(target=app.process_request, args=(request,))959 threads.append(t)960 t.start()961 except KeyboardInterrupt:962 break963964 # Ждём завершения потоков.965 for t in threads:966 t.join()967968 for app in apps:969 print('%s processed %s requests' % (app.name, app.num_requests))970971if __name__ == '__main__':972 main()973```974975Если запустить приведённый выше код, вы обнаружите, что примерно половина запросов попадает в `app1.log`, а остальные – в `app2.log`, и все запросы регистрируются в `app.log`. Каждый журнал, специфичный для веб-приложения, будет содержать только записи для этого приложения, а информация о запросе будет отображаться в журнале согласованно (т.е. информация каждого фиктивного запроса всегда будет появляться вместе в одной строке журнала). Это иллюстрируется следующим выводом оболочки:976977```shell978~/logging-contextual-webapp$ python main.py979app1 processed 51 requests980app2 processed 49 requests981~/logging-contextual-webapp$ wc -l *.log982 153 app1.log983 147 app2.log984 300 app.log985 600 total986~/logging-contextual-webapp$ head -3 app1.log987Thread-3 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started988Thread-3 (process_request) app1 webapplib jim 192.168.3.21 POST Hello from webapplib!989Thread-5 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started990~/logging-contextual-webapp$ head -3 app2.log991Thread-1 (process_request) app2 __main__ sheila 192.168.2.21 GET Request processing started992Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET Hello from webapplib!993Thread-2 (process_request) app2 __main__ jim 192.168.2.20 GET Request processing started994~/logging-contextual-webapp$ head app.log995Thread-1 (process_request) app2 __main__ sheila 192.168.2.21 GET Request processing started996Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET Hello from webapplib!997Thread-2 (process_request) app2 __main__ jim 192.168.2.20 GET Request processing started998Thread-3 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started999Thread-2 (process_request) app2 webapplib jim 192.168.2.20 GET Hello from webapplib!1000Thread-3 (process_request) app1 webapplib jim 192.168.3.21 POST Hello from webapplib!1001Thread-4 (process_request) app2 __main__ fred 192.168.2.22 GET Request processing started1002Thread-5 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1003Thread-4 (process_request) app2 webapplib fred 192.168.2.22 GET Hello from webapplib!1004Thread-6 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1005~/logging-contextual-webapp$ grep app1 app1.log | wc -l10061531007~/logging-contextual-webapp$ grep app2 app2.log | wc -l10081471009~/logging-contextual-webapp$ grep app1 app.log | wc -l10101531011~/logging-contextual-webapp$ grep app2 app.log | wc -l10121471013```10141015## Добавление контекстной информации в обработчиках10161017Каждый `Handler` имеет собственную цепочку фильтров. Если нужно добавить контекстную информацию в `LogRecord` без её утечки в другие обработчики, можно использовать фильтр, возвращающий новый `LogRecord` вместо изменения исходного на месте, как показано в следующем скрипте:10181019```python1020import copy1021import logging10221023def filter(record: logging.LogRecord):1024 record = copy.copy(record)1025 record.user = 'jim'1026 return record10271028if __name__ == '__main__':1029 logger = logging.getLogger()1030 logger.setLevel(logging.INFO)1031 handler = logging.StreamHandler()1032 formatter = logging.Formatter('%(message)s from %(user)-8s')1033 handler.setFormatter(formatter)1034 handler.addFilter(filter)1035 logger.addHandler(handler)10361037 logger.info('A log message')1038```10391040## Ведение журнала в один файл из нескольких процессов10411042Хотя модуль logging является потокобезопасным и запись в один файл из нескольких потоков в одном процессе *поддерживается*, запись в один файл из *нескольких процессов* *не* поддерживается, поскольку в Python нет стандартного способа сериализовать доступ к одному файлу из нескольких процессов. Если нужно вести журнал в один файл из нескольких процессов, один из способов – сделать так, чтобы все процессы записывали данные в `SocketHandler`, а отдельный процесс реализовывал сокет-сервер, который читает из сокета и записывает в файл. (Если хотите, можно выделить один поток в одном из существующих процессов для выполнения этой функции.) [В этом разделе](https://python-all.ru/3.10/howto/logging-cookbook.html#network-logging) подробно описывается данный подход и приводится рабочий приёмник сокета, который можно использовать как отправную точку для адаптации в своих приложениях.10431044Вы также можете написать собственный обработчик, который использует класс [`Lock`](https://python-all.ru/3.10/library/multiprocessing.html#multiprocessing.Lock) из модуля [`multiprocessing`](https://python-all.ru/3.10/library/multiprocessing.html#module-multiprocessing) для сериализации доступа к файлу из ваших процессов. Существующие `FileHandler` и подклассы в настоящее время не используют [`multiprocessing`](https://python-all.ru/3.10/library/multiprocessing.html#module-multiprocessing), хотя в будущем они могут это сделать. Обратите внимание, что в настоящее время модуль [`multiprocessing`](https://python-all.ru/3.10/library/multiprocessing.html#module-multiprocessing) не обеспечивает рабочую функциональность блокировки на всех платформах (см. [https://bugs.python.org/issue3770](https://python-all.ru/3.10/howto/logging-cookbook.html)).10451046В качестве альтернативы можно использовать `Queue` и [`QueueHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.QueueHandler) для отправки всех событий журналирования одному из процессов в вашем многопроцессном приложении. В следующем примере сценария показано, как это сделать; в примере отдельный процесс-слушатель ожидает события, отправленные другими процессами, и регистрирует их в соответствии со своей собственной конфигурацией журналирования. Хотя пример демонстрирует лишь один из способов (например, вместо отдельного процесса-слушателя можно использовать поток-слушатель – реализация будет аналогичной), он позволяет задать полностью разные конфигурации журналирования для слушателя и остальных процессов в вашем приложении и может быть использован как основа для кода, отвечающего вашим конкретным требованиям:10471048```python1049# Вам понадобятся эти импорты в вашем коде.1050import logging1051import logging.handlers1052import multiprocessing10531054# Следующие две строки импорта только для этой демонстрации.1055from random import choice, random1056import time10571058#1059# Поскольку нужно задать настройки логирования для слушателя и рабочих процессов, функции1060# слушателя и рабочего процесса принимают параметр configurer – вызываемый объект для1061# настройки логирования этого процесса. Эти функции также получают очередь, которую1062# используют для взаимодействия.1063#1064# На практике слушателя можно настроить как угодно, но заметьте: в этом простом1065# примере слушатель не применяет логику уровней или фильтров к полученным записям.1066# На практике эту логику, вероятно, стоит вынести в рабочие процессы, чтобы не1067# пересылать между процессами события, которые всё равно будут отфильтрованы.1068#1069# Размер файлов при ротации намеренно сделан небольшим, чтобы результат был хорошо виден.1070def listener_configurer():1071 root = logging.getLogger()1072 h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)1073 f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')1074 h.setFormatter(f)1075 root.addHandler(h)10761077# Это главный цикл процесса-слушателя: ждём события логирования1078# (LogRecords) в очереди и обрабатываем их; завершаем работу, когда получаем None вместо1079# LogRecord.1080def listener_process(queue, configurer):1081 configurer()1082 while True:1083 try:1084 record = queue.get()1085 if record is None: # Отправляем это как сигнал завершения, чтобы слушатель остановился.1086 break1087 logger = logging.getLogger(record.name)1088 logger.handle(record) # Никакой логики уровней и фильтров – просто делаем дело!1089 except Exception:1090 import sys, traceback1091 print('Whoops! Problem:', file=sys.stderr)1092 traceback.print_exc(file=sys.stderr)10931094# Массивы для случайного выбора в этой демонстрации.10951096LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,1097 logging.ERROR, logging.CRITICAL]10981099LOGGERS = ['a.b.c', 'd.e.f']11001101MESSAGES = [1102 'Random message #1',1103 'Random message #2',1104 'Random message #3',1105]11061107# Настройка рабочего процесса выполняется в начале его работы.1108# Обратите внимание: в Windows нельзя полагаться на семантику fork, поэтому каждый процесс1109# будет выполнять код настройки логирования при запуске.1110def worker_configurer(queue):1111 h = logging.handlers.QueueHandler(queue) # Нужен только один обработчик.1112 root = logging.getLogger()1113 root.addHandler(h)1114 # Отправляем все сообщения для демонстрации; никакой другой логики уровней или фильтров.1115 root.setLevel(logging.DEBUG)11161117# Это главный цикл рабочего процесса, который просто логирует десять событий с1118# случайные задержки перед завершением.1119# Сообщения print нужны лишь для того, чтобы было видно, что программа работает.1120def worker_process(queue, configurer):1121 configurer(queue)1122 name = multiprocessing.current_process().name1123 print('Worker started: %s' % name)1124 for i in range(10):1125 time.sleep(random())1126 logger = logging.getLogger(choice(LOGGERS))1127 level = choice(LEVELS)1128 message = choice(MESSAGES)1129 logger.log(level, message)1130 print('Worker finished: %s' % name)11311132# Здесь организуется демонстрация. Создать очередь, создать и запустить1133# слушатель, создать десять рабочих процессов и запустить их, дождаться их завершения,1134# затем отправить None в очередь, чтобы сообщить слушателю о завершении.1135def main():1136 queue = multiprocessing.Queue(-1)1137 listener = multiprocessing.Process(target=listener_process,1138 args=(queue, listener_configurer))1139 listener.start()1140 workers = []1141 for i in range(10):1142 worker = multiprocessing.Process(target=worker_process,1143 args=(queue, worker_configurer))1144 workers.append(worker)1145 worker.start()1146 for w in workers:1147 w.join()1148 queue.put_nowait(None)1149 listener.join()11501151if __name__ == '__main__':1152 main()1153```11541155Вариант приведённого выше сценария оставляет ведение журнала в главном процессе, в отдельном потоке:11561157```python1158import logging1159import logging.config1160import logging.handlers1161from multiprocessing import Process, Queue1162import random1163import threading1164import time11651166def logger_thread(q):1167 while True:1168 record = q.get()1169 if record is None:1170 break1171 logger = logging.getLogger(record.name)1172 logger.handle(record)11731174def worker_process(q):1175 qh = logging.handlers.QueueHandler(q)1176 root = logging.getLogger()1177 root.setLevel(logging.DEBUG)1178 root.addHandler(qh)1179 levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1180 logging.CRITICAL]1181 loggers = ['foo', 'foo.bar', 'foo.bar.baz',1182 'spam', 'spam.ham', 'spam.ham.eggs']1183 for i in range(100):1184 lvl = random.choice(levels)1185 logger = logging.getLogger(random.choice(loggers))1186 logger.log(lvl, 'Message no. %d', i)11871188if __name__ == '__main__':1189 q = Queue()1190 d = {1191 'version': 1,1192 'formatters': {1193 'detailed': {1194 'class': 'logging.Formatter',1195 'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1196 }1197 },1198 'handlers': {1199 'console': {1200 'class': 'logging.StreamHandler',1201 'level': 'INFO',1202 },1203 'file': {1204 'class': 'logging.FileHandler',1205 'filename': 'mplog.log',1206 'mode': 'w',1207 'formatter': 'detailed',1208 },1209 'foofile': {1210 'class': 'logging.FileHandler',1211 'filename': 'mplog-foo.log',1212 'mode': 'w',1213 'formatter': 'detailed',1214 },1215 'errors': {1216 'class': 'logging.FileHandler',1217 'filename': 'mplog-errors.log',1218 'mode': 'w',1219 'level': 'ERROR',1220 'formatter': 'detailed',1221 },1222 },1223 'loggers': {1224 'foo': {1225 'handlers': ['foofile']1226 }1227 },1228 'root': {1229 'level': 'DEBUG',1230 'handlers': ['console', 'file', 'errors']1231 },1232 }1233 workers = []1234 for i in range(5):1235 wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))1236 workers.append(wp)1237 wp.start()1238 logging.config.dictConfig(d)1239 lp = threading.Thread(target=logger_thread, args=(q,))1240 lp.start()1241 # На этом этапе главный процесс может заняться своей полезной работой1242 # Когда он с этим закончит, он может дождаться завершения рабочих процессов...1243 for wp in workers:1244 wp.join()1245 # А теперь указать потоку журналирования завершиться1246 q.put(None)1247 lp.join()1248```12491250Этот вариант показывает, как можно, например, применить конфигурацию для определённых регистраторов – например, регистратор `foo` имеет специальный обработчик, который сохраняет все события подсистемы `foo` в файл `mplog-foo.log`. Это будет использовано механизмом журналирования в главном процессе (даже если события журналирования генерируются в рабочих процессах) для направления сообщений к соответствующим местам назначения.12511252### Использование concurrent.futures.ProcessPoolExecutor12531254Если вы хотите использовать [`concurrent.futures.ProcessPoolExecutor`](https://python-all.ru/3.10/library/concurrent.futures.html#concurrent.futures.ProcessPoolExecutor) для запуска рабочих процессов, необходимо создать очередь немного иначе. Вместо12551256```python1257queue = multiprocessing.Queue(-1)1258```12591260следует использовать12611262```python1263queue = multiprocessing.Manager().Queue(-1) # также работает с примерами выше1264```12651266и затем можно заменить создание рабочего процесса с этого:12671268```python1269workers = []1270for i in range(10):1271 worker = multiprocessing.Process(target=worker_process,1272 args=(queue, worker_configurer))1273 workers.append(worker)1274 worker.start()1275for w in workers:1276 w.join()1277```12781279на это (не забудьте сначала импортировать [`concurrent.futures`](https://python-all.ru/3.10/library/concurrent.futures.html#module-concurrent.futures)):12801281```python1282with concurrent.futures.ProcessPoolExecutor(max_workers=10) as executor:1283 for i in range(10):1284 executor.submit(worker_process, queue, worker_configurer)1285```12861287### Развертывание веб-приложений с использованием Gunicorn и uWSGI12881289При развертывании веб-приложений с использованием [Gunicorn](https://python-all.ru/3.10/howto/logging-cookbook.html) или [uWSGI](https://python-all.ru/3.10/howto/logging-cookbook.html) (или аналогичных) создается несколько рабочих процессов для обработки клиентских запросов. В таких средах избегайте создания обработчиков, основанных на файлах, непосредственно в вашем веб-приложении. Вместо этого используйте [`SocketHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.SocketHandler) для логирования из веб-приложения в слушатель в отдельном процессе. Это можно настроить с помощью инструмента управления процессами, такого как Supervisor – см. [Запуск слушателя сокета логирования в производственной среде](https://python-all.ru/3.10/howto/logging-cookbook.html#running-a-logging-socket-listener-in-production) для получения дополнительной информации.12901291## Использование ротации файлов12921293Иногда требуется позволить файлу журнала расти до определённого размера, затем открыть новый файл и вести запись в него. Может потребоваться сохранять определённое количество таких файлов, и когда будет создано заданное число файлов, выполнять ротацию, чтобы и количество, и размер файлов оставались в заданных границах. Для такого сценария использования пакет logging предоставляет `RotatingFileHandler`:12941295```python1296import glob1297import logging1298import logging.handlers12991300LOG_FILENAME = 'logging_rotatingfile_example.out'13011302# Настроить конкретный регистратор с нужным уровнем вывода1303my_logger = logging.getLogger('MyLogger')1304my_logger.setLevel(logging.DEBUG)13051306# Добавить обработчик сообщений журнала в регистратор1307handler = logging.handlers.RotatingFileHandler(1308 LOG_FILENAME, maxBytes=20, backupCount=5)13091310my_logger.addHandler(handler)13111312# Записать несколько сообщений1313for i in range(20):1314 my_logger.debug('i = %d' % i)13151316# Посмотреть, какие файлы созданы1317logfiles = glob.glob('%s*' % LOG_FILENAME)13181319for filename in logfiles:1320 print(filename)1321```13221323В результате должно получиться 6 отдельных файлов, каждый из которых содержит часть истории журнала приложения:13241325```text1326logging_rotatingfile_example.out1327logging_rotatingfile_example.out.11328logging_rotatingfile_example.out.21329logging_rotatingfile_example.out.31330logging_rotatingfile_example.out.41331logging_rotatingfile_example.out.51332```13331334Самый свежий файл всегда называется `logging_rotatingfile_example.out`, и каждый раз при достижении ограничения по размеру он переименовывается с суффиксом `.1`. Каждый из существующих резервных файлов переименовывается с увеличением суффикса (`.1` становится `.2` и т.д.), а файл `.6` удаляется.13351336Разумеется, в этом примере размер файла журнала установлен слишком маленьким для наглядности. В реальности нужно установить *maxBytes* в подходящее значение.13371338## Использование альтернативных стилей форматирования13391340Когда журналирование было добавлено в стандартную библиотеку Python, единственным способом форматирования сообщений с переменным содержимым было использование %-форматирования. С тех пор в Python появились два новых подхода к форматированию: [`string.Template`](https://python-all.ru/3.10/library/string.html#string.Template) (добавлен в Python 2.4) и [`str.format()`](https://python-all.ru/3.10/library/stdtypes.html#str.format) (добавлен в Python 2.6).13411342Начиная с версии 3.2, модуль logging предоставляет улучшенную поддержку этих двух дополнительных стилей форматирования. Класс `Formatter` был расширен: добавлен дополнительный необязательный именованный параметр `style`. По умолчанию он равен `'%'`, но возможны также значения `'{'` и `'$'`, соответствующие двум другим стилям форматирования. Обратная совместимость сохраняется по умолчанию (как и следовало ожидать), но при явном указании параметра style появляется возможность задавать строки формата, работающие с [`str.format()`](https://python-all.ru/3.10/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.10/library/string.html#string.Template). Вот пример сеанса работы в консоли, демонстрирующий возможности:13431344```pycon1345>>> import logging1346>>> root = logging.getLogger()1347>>> root.setLevel(logging.DEBUG)1348>>> handler = logging.StreamHandler()1349>>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}',1350... style='{')1351>>> handler.setFormatter(bf)1352>>> root.addHandler(handler)1353>>> logger = logging.getLogger('foo.bar')1354>>> logger.debug('This is a DEBUG message')13552010-10-28 15:11:55,341 foo.bar DEBUG This is a DEBUG message1356>>> logger.critical('This is a CRITICAL message')13572010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message1358>>> df = logging.Formatter('$asctime $name ${levelname} $message',1359... style='$')1360>>> handler.setFormatter(df)1361>>> logger.debug('This is a DEBUG message')13622010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message1363>>> logger.critical('This is a CRITICAL message')13642010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message1365>>>1366```13671368Обратите внимание: форматирование сообщений журнала для конечного вывода в файлы совершенно не зависит от того, как конструируется отдельное сообщение. Оно по-прежнему может использовать %-форматирование, как показано ниже:13691370```python1371>>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')13722010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message1373>>>1374```13751376Вызовы функций журналирования (`logger.debug()`, `logger.info()` и т.д.) принимают только позиционные параметры для самого сообщения журнала; именованные параметры используются только для определения параметров обработки вызова (например, именованный параметр `exc_info` указывает, что нужно записать информацию о трассировке стека, или именованный параметр `extra` – добавить дополнительный контекст в журнал). Поэтому невозможно напрямую использовать синтаксис [`str.format()`](https://python-all.ru/3.10/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.10/library/string.html#string.Template) при вызовах, поскольку внутри пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Изменить это без нарушения обратной совместимости нельзя, так как все существующие вызовы logging в существующем коде используют %-формат строк.13771378Однако существует способ использовать {}- и $-форматирование для построения отдельных сообщений журнала. Напомним, что в качестве строки формата сообщения можно использовать произвольный объект, и пакет logging вызовет у этого объекта `str()` для получения фактической строки формата. Рассмотрим следующие два класса:13791380```python1381class BraceMessage:1382 def __init__(self, fmt, /, *args, **kwargs):1383 self.fmt = fmt1384 self.args = args1385 self.kwargs = kwargs13861387 def __str__(self):1388 return self.fmt.format(*self.args, **self.kwargs)13891390class DollarMessage:1391 def __init__(self, fmt, /, **kwargs):1392 self.fmt = fmt1393 self.kwargs = kwargs13941395 def __str__(self):1396 from string import Template1397 return Template(self.fmt).substitute(**self.kwargs)1398```13991400Любой из этих классов можно использовать вместо строки формата, чтобы разрешить применение {}- или $-форматирования для построения фактической части «message», которая появляется в отформатированном выводе журнала вместо «%(message)s», «{message}» или «$message». Это немного громоздко – использовать имена классов каждый раз при журналировании, но вполне приемлемо, если применить псевдоним, например \_\_ (двойное подчеркивание – не путать с \_, одинарным подчеркиванием, используемым как синоним/псевдоним для [`gettext.gettext()`](https://python-all.ru/3.10/library/gettext.html#gettext.gettext) или его аналогов).14011402Вышеуказанные классы не входят в состав Python, но их легко скопировать и вставить в свой код. Их можно использовать следующим образом (предполагая, что они объявлены в модуле с именем `wherever`):14031404```pycon1405>>> from wherever import BraceMessage as __1406>>> print(__('Message with {0} {name}', 2, name='placeholders'))1407Message with 2 placeholders1408>>> class Point: pass1409...1410>>> p = Point()1411>>> p.x = 0.51412>>> p.y = 0.51413>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})',1414... point=p))1415Message with coordinates: (0.50, 0.50)1416>>> from wherever import DollarMessage as __1417>>> print(__('Message with $num $what', num=2, what='placeholders'))1418Message with 2 placeholders1419>>>1420```14211422Хотя в приведённых выше примерах используется `print()` для демонстрации работы форматирования, в реальности для ведения журнала с помощью этого подхода следует использовать `logger.debug()` или аналогичную функцию.14231424Следует отметить, что этот подход не даёт значительного снижения производительности с этим подходом: фактическое форматирование происходит не тогда, когда вы делаете вызов регистрации, а когда (и если) регистрируемое сообщение действительно должно быть выведено в журнал с помощью обработчика. Поэтому единственное, что может сбить с толку, – это то, что скобки ставятся вокруг строки формата и аргументов, а не только вокруг строки формата. Это потому, что нотация \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов XXXMessage.14251426Если хотите, можно использовать `LoggerAdapter` для достижения аналогичного эффекта, как в следующем примере:14271428```python1429import logging14301431class Message:1432 def __init__(self, fmt, args):1433 self.fmt = fmt1434 self.args = args14351436 def __str__(self):1437 return self.fmt.format(*self.args)14381439class StyleAdapter(logging.LoggerAdapter):1440 def __init__(self, logger, extra=None):1441 super().__init__(logger, extra or {})14421443 def log(self, level, msg, /, *args, **kwargs):1444 if self.isEnabledFor(level):1445 msg, kwargs = self.process(msg, kwargs)1446 self.logger._log(level, Message(msg, args), (), **kwargs)14471448logger = StyleAdapter(logging.getLogger(__name__))14491450def main():1451 logger.debug('Hello, {}', 'world!')14521453if __name__ == '__main__':1454 logging.basicConfig(level=logging.DEBUG)1455 main()1456```14571458При запуске с Python 3.2 или новее указанный выше скрипт должен записать сообщение `Hello, world!`.14591460## Настройка `LogRecord`14611462Каждое событие журналирования представлено экземпляром [`LogRecord`](https://python-all.ru/3.10/library/logging.html#logging.LogRecord). Когда событие регистрируется и не отфильтровывается по уровню регистратора, создаётся [`LogRecord`](https://python-all.ru/3.10/library/logging.html#logging.LogRecord), заполняется информацией о событии и затем передаётся обработчикам для этого регистратора (и его предков, вплоть до регистратора, в котором дальнейшее распространение по иерархии отключено). До Python 3.2 было только два места, где выполнялось это создание:14631464- [`Logger.makeRecord()`](https://python-all.ru/3.10/library/logging.html#logging.Logger.makeRecord), который вызывается в обычном процессе регистрации события. Он напрямую вызывал [`LogRecord`](https://python-all.ru/3.10/library/logging.html#logging.LogRecord) для создания экземпляра.1465- [`makeLogRecord()`](https://python-all.ru/3.10/library/logging.html#logging.makeLogRecord), которая вызывается со словарем, содержащим атрибуты для добавления в LogRecord. Обычно она вызывается, когда подходящий словарь был получен по сети (например, в виде pickle через [`SocketHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.SocketHandler) или в формате JSON через [`HTTPHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.HTTPHandler)).14661467Обычно это означало, что если требуется выполнить какие-либо специальные действия с [`LogRecord`](https://python-all.ru/3.10/library/logging.html#logging.LogRecord), приходилось делать одно из следующего.14681469- Создать собственный подкласс [`Logger`](https://python-all.ru/3.10/library/logging.html#logging.Logger), который переопределяет [`Logger.makeRecord()`](https://python-all.ru/3.10/library/logging.html#logging.Logger.makeRecord), и установить его с помощью [`setLoggerClass()`](https://python-all.ru/3.10/library/logging.html#logging.setLoggerClass) до того, как будут созданы какие-либо логгеры, которые вас интересуют.1470- Добавить [`Filter`](https://python-all.ru/3.10/library/logging.html#logging.Filter) к логгеру или обработчику, который выполняет необходимые специальные манипуляции при вызове его метода [`filter()`](https://python-all.ru/3.10/library/logging.html#logging.Filter.filter).14711472Первый подход был бы несколько громоздким в сценарии, где (скажем) несколько разных библиотек хотели бы делать разные вещи. Каждая попыталась бы установить свой собственный подкласс [`Logger`](https://python-all.ru/3.10/library/logging.html#logging.Logger), и та, которая сделала это последней, победила бы.14731474Второй подход достаточно хорошо работает во многих случаях, но не позволяет, например, использовать специализированный подкласс [`LogRecord`](https://python-all.ru/3.10/library/logging.html#logging.LogRecord). Разработчики библиотек могут установить подходящий фильтр на своих логгерах, но им приходилось бы помнить об этом каждый раз, когда они добавляют новый логгер (что они делают, просто добавляя новые пакеты или модули и выполняя14751476```python1477logger = logging.getLogger(__name__)1478```14791480на уровне модуля). Вероятно, это одна из тех вещей, о которых нужно помнить. Разработчики также могли бы добавить фильтр к [`NullHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.NullHandler), прикрепленному к их корневому логгеру, но он не будет вызываться, если разработчик приложения прикрепит обработчик к логгеру библиотеки нижнего уровня – так что вывод от этого обработчика не будет отражать намерений разработчика библиотеки.14811482В Python 3.2 и новее создание [`LogRecord`](https://python-all.ru/3.10/library/logging.html#logging.LogRecord) осуществляется через фабрику, которую можно указать. Фабрика – это просто вызываемый объект, который можно установить с помощью [`setLogRecordFactory()`](https://python-all.ru/3.10/library/logging.html#logging.setLogRecordFactory) и запросить с помощью [`getLogRecordFactory()`](https://python-all.ru/3.10/library/logging.html#logging.getLogRecordFactory). Фабрика вызывается с той же сигнатурой, что и конструктор [`LogRecord`](https://python-all.ru/3.10/library/logging.html#logging.LogRecord), поскольку [`LogRecord`](https://python-all.ru/3.10/library/logging.html#logging.LogRecord) является значением по умолчанию для фабрики.14831484Этот подход позволяет пользовательской фабрике контролировать все аспекты создания LogRecord. Например, можно вернуть подкласс или просто добавить несколько дополнительных атрибутов к записи после ее создания, используя шаблон, подобный следующему:14851486```python1487old_factory = logging.getLogRecordFactory()14881489def record_factory(*args, **kwargs):1490 record = old_factory(*args, **kwargs)1491 record.custom_attribute = 0xdecafbad1492 return record14931494logging.setLogRecordFactory(record_factory)1495```14961497Этот шаблон позволяет разным библиотекам объединять фабрики в цепочку, и пока они не перезаписывают атрибуты друг друга или случайно не перезаписывают стандартные атрибуты, никаких сюрпризов быть не должно. Однако следует иметь в виду, что каждое звено цепочки добавляет накладные расходы во время выполнения ко всем операциям логирования, и эту технику следует использовать только тогда, когда использование [`Filter`](https://python-all.ru/3.10/library/logging.html#logging.Filter) не дает желаемого результата.14981499## Создание подкласса QueueHandler – пример с ZeroMQ15001501Можно использовать подкласс `QueueHandler` для отправки сообщений в очереди других типов, например, в сокет ZeroMQ «publish». В приведенном ниже примере сокет создается отдельно и передается обработчику (в качестве его «очереди»):15021503```python1504import zmq # с использованием pyzmq, привязки Python к ZeroMQ1505import json # для переносимой сериализации записей15061507ctx = zmq.Context()1508sock = zmq.Socket(ctx, zmq.PUB) # или zmq.PUSH, или другое подходящее значение1509sock.bind('tcp://*:5556') # или где угодно15101511class ZeroMQSocketHandler(QueueHandler):1512 def enqueue(self, record):1513 self.queue.send_json(record.__dict__)15141515handler = ZeroMQSocketHandler(sock)1516```15171518Конечно, есть и другие способы организации этого, например, передача данных, необходимых обработчику для создания сокета:15191520```python1521class ZeroMQSocketHandler(QueueHandler):1522 def __init__(self, uri, socktype=zmq.PUB, ctx=None):1523 self.ctx = ctx or zmq.Context()1524 socket = zmq.Socket(self.ctx, socktype)1525 socket.bind(uri)1526 super().__init__(socket)15271528 def enqueue(self, record):1529 self.queue.send_json(record.__dict__)15301531 def close(self):1532 self.queue.close()1533```15341535## Создание подкласса QueueListener – пример с ZeroMQ15361537Можно также создать подкласс `QueueListener` для получения сообщений из очередей других типов, например, из сокета ZeroMQ «subscribe». Вот пример:15381539```python1540class ZeroMQSocketListener(QueueListener):1541 def __init__(self, uri, /, *handlers, **kwargs):1542 self.ctx = kwargs.get('ctx') or zmq.Context()1543 socket = zmq.Socket(self.ctx, zmq.SUB)1544 socket.setsockopt_string(zmq.SUBSCRIBE, '') # подписаться на всё1545 socket.connect(uri)1546 super().__init__(socket, *handlers, **kwargs)15471548 def dequeue(self):1549 msg = self.queue.recv_json()1550 return logging.makeLogRecord(msg)1551```15521553> **См. также**1554>1555> **Модуль [`logging`](https://python-all.ru/3.10/library/logging.html#module-logging)**1556>1557> Справочник API для модуля logging.1558>1559> **Модуль [`logging.config`](https://python-all.ru/3.10/library/logging.config.html#module-logging.config)**1560>1561> API конфигурации для модуля logging.1562>1563> **Модуль [`logging.handlers`](https://python-all.ru/3.10/library/logging.handlers.html#module-logging.handlers)**1564>1565> Полезные обработчики, входящие в состав модуля logging.1566>1567> [Базовое руководство по логированию](https://python-all.ru/3.10/howto/logging.html#logging-basic-tutorial)1568>1569> [Более продвинутое руководство по логированию](https://python-all.ru/3.10/howto/logging.html#logging-advanced-tutorial)15701571## Пример конфигурации на основе словаря15721573Ниже приведен пример словаря конфигурации логирования – он взят из [документации проекта Django](https://python-all.ru/3.10/howto/logging-cookbook.html). Этот словарь передается в [`dictConfig()`](https://python-all.ru/3.10/library/logging.config.html#logging.config.dictConfig) для применения конфигурации:15741575```python1576LOGGING = {1577 'version': 1,1578 'disable_existing_loggers': True,1579 'formatters': {1580 'verbose': {1581 'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'1582 },1583 'simple': {1584 'format': '%(levelname)s %(message)s'1585 },1586 },1587 'filters': {1588 'special': {1589 '()': 'project.logging.SpecialFilter',1590 'foo': 'bar',1591 }1592 },1593 'handlers': {1594 'null': {1595 'level':'DEBUG',1596 'class':'django.utils.log.NullHandler',1597 },1598 'console':{1599 'level':'DEBUG',1600 'class':'logging.StreamHandler',1601 'formatter': 'simple'1602 },1603 'mail_admins': {1604 'level': 'ERROR',1605 'class': 'django.utils.log.AdminEmailHandler',1606 'filters': ['special']1607 }1608 },1609 'loggers': {1610 'django': {1611 'handlers':['null'],1612 'propagate': True,1613 'level':'INFO',1614 },1615 'django.request': {1616 'handlers': ['mail_admins'],1617 'level': 'ERROR',1618 'propagate': False,1619 },1620 'myproject.custom': {1621 'handlers': ['console', 'mail_admins'],1622 'level': 'INFO',1623 'filters': ['special']1624 }1625 }1626}1627```16281629Для получения дополнительной информации об этой конфигурации можно обратиться к [соответствующему разделу](https://python-all.ru/3.10/howto/logging-cookbook.html) документации Django.16301631## Использование ротатора и средства именования для настройки обработки ротации журналов16321633Пример того, как можно определить именователя и ротатора, приведен в следующем исполняемом скрипте, который показывает сжатие gzip файла журнала:16341635```python1636import gzip1637import logging1638import logging.handlers1639import os1640import shutil16411642def namer(name):1643 return name + ".gz"16441645def rotator(source, dest):1646 with open(source, 'rb') as f_in:1647 with gzip.open(dest, 'wb') as f_out:1648 shutil.copyfileobj(f_in, f_out)1649 os.remove(source)16501651rh = logging.handlers.RotatingFileHandler('rotated.log', maxBytes=128, backupCount=5)1652rh.rotator = rotator1653rh.namer = namer16541655root = logging.getLogger()1656root.setLevel(logging.INFO)1657root.addHandler(rh)1658f = logging.Formatter('%(asctime)s %(message)s')1659rh.setFormatter(f)1660for i in range(1000):1661 root.info(f'Message no. {i + 1}')1662```16631664После запуска будут созданы шесть новых файлов, пять из которых сжаты:16651666```console1667$ ls rotated.log*1668rotated.log rotated.log.2.gz rotated.log.4.gz1669rotated.log.1.gz rotated.log.3.gz rotated.log.5.gz1670$ zcat rotated.log.1.gz16712023-01-20 02:28:17,767 Message no. 99616722023-01-20 02:28:17,767 Message no. 99716732023-01-20 02:28:17,767 Message no. 9981674```16751676## Более сложный пример с многопроцессностью16771678Следующий рабочий пример показывает, как можно использовать логирование с многопроцессностью с помощью файлов конфигурации. Конфигурации довольно просты, но служат иллюстрацией того, как можно реализовать более сложные в реальном сценарии многопроцессной обработки.16791680В примере главный процесс порождает процесс-слушатель и несколько рабочих процессов. Каждый из главного процесса, слушателя и рабочих имеет три отдельные конфигурации (все рабочие используют одну и ту же конфигурацию). Видно ведение журнала в главном процессе, как рабочие пишут в QueueHandler, а слушатель реализует QueueListener и более сложную конфигурацию ведения журнала, и организует отправку событий, полученных через очередь, обработчикам, указанным в конфигурации. Обратите внимание, что эти конфигурации чисто иллюстративные, но этот пример можно адаптировать под свой сценарий.16811682Вот скрипт – строки документации и комментарии, надеюсь, поясняют, как он работает:16831684```python1685import logging1686import logging.config1687import logging.handlers1688from multiprocessing import Process, Queue, Event, current_process1689import os1690import random1691import time16921693class MyHandler:1694 """1695 Простой обработчик для событий логирования. Он выполняется в процессе-слушателе и1696 распределяет события по логгерам на основе имени в полученной записи,1697 которые затем передаются системой логирования обработчикам,1698 настроенным для этих логгеров.1699 """17001701 def handle(self, record):1702 if record.name == "root":1703 logger = logging.getLogger()1704 else:1705 logger = logging.getLogger(record.name)17061707 if logger.isEnabledFor(record.levelno):1708 # Имя процесса преобразуется только для того, чтобы показать, что это слушатель1709 # выполняет логирование в файлы и консоль.1710 record.processName = '%s (for %s)' % (current_process().name, record.processName)1711 logger.handle(record)17121713def listener_process(q, stop_event, config):1714 """1715 Это можно было бы сделать в главном процессе, но сделано в отдельном1716 процессе для наглядности.17171718 Это инициализирует логирование согласно указанной конфигурации1719 запускает слушатель и ожидает сигнала от главного процесса о завершении1720 через событие. Затем слушатель останавливается, и процесс завершается.1721 """1722 logging.config.dictConfig(config)1723 listener = logging.handlers.QueueListener(q, MyHandler())1724 listener.start()1725 if os.name == 'posix':1726 # В POSIX логгер setup уже был настроен в1727 # родительском процессе, но должен был быть отключён после вызова1728 # dictConfig.1729 # В Windows, поскольку fork не используется, логгер setup не будет1730 # существовать в дочернем процессе, поэтому он будет создан, и сообщение1731 # появится – отсюда и конструкция "if posix".1732 logger = logging.getLogger('setup')1733 logger.critical('Should not appear, because of disabled logger ...')1734 stop_event.wait()1735 listener.stop()17361737def worker_process(config):1738 """1739 Некоторое количество таких процессов порождается для иллюстрации. На1740 практике это могла бы быть разнородная группа процессов, а не1741 идентичные друг другу.17421743 Это инициализирует логирование согласно указанной конфигурации1744 и записывает сотню сообщений со случайными уровнями в случайно выбранные1745 логгеры.17461747 Добавлена небольшая задержка, чтобы дать другим процессам шанс выполниться. Это1748 не является строго необходимым, но позволяет немного перемешать вывод от разных1749 процессов больше, чем если бы её не было.1750 """1751 logging.config.dictConfig(config)1752 levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1753 logging.CRITICAL]1754 loggers = ['foo', 'foo.bar', 'foo.bar.baz',1755 'spam', 'spam.ham', 'spam.ham.eggs']1756 if os.name == 'posix':1757 # В POSIX логгер setup уже был настроен в1758 # родительском процессе, но должен был быть отключён после вызова1759 # dictConfig.1760 # В Windows, поскольку fork не используется, логгер setup не будет1761 # существовать в дочернем процессе, поэтому он будет создан, и сообщение1762 # появится – отсюда и конструкция "if posix".1763 logger = logging.getLogger('setup')1764 logger.critical('Should not appear, because of disabled logger ...')1765 for i in range(100):1766 lvl = random.choice(levels)1767 logger = logging.getLogger(random.choice(loggers))1768 logger.log(lvl, 'Message no. %d', i)1769 time.sleep(0.01)17701771def main():1772 q = Queue()1773 # Главный процесс получает простую конфигурацию, которая выводит информацию в консоль.1774 config_initial = {1775 'version': 1,1776 'handlers': {1777 'console': {1778 'class': 'logging.StreamHandler',1779 'level': 'INFO'1780 }1781 },1782 'root': {1783 'handlers': ['console'],1784 'level': 'DEBUG'1785 }1786 }1787 # Конфигурация рабочего процесса представляет собой QueueHandler, прикреплённый к1788 # корневому логгеру, что позволяет отправлять все сообщения в очередь.1789 # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1790 # родительском процессе. Это необходимо в POSIX, потому что логгер будет1791 # присутствовать в дочернем процессе после вызова fork().1792 config_worker = {1793 'version': 1,1794 'disable_existing_loggers': True,1795 'handlers': {1796 'queue': {1797 'class': 'logging.handlers.QueueHandler',1798 'queue': q1799 }1800 },1801 'root': {1802 'handlers': ['queue'],1803 'level': 'DEBUG'1804 }1805 }1806 # Конфигурация процесса-слушателя показывает, что вся гибкость1807 # конфигурации логирования доступна для отправки событий обработчикам так, как1808 # требуется.1809 # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1810 # родительском процессе. Это необходимо в POSIX, потому что логгер будет1811 # присутствовать в дочернем процессе после вызова fork().1812 config_listener = {1813 'version': 1,1814 'disable_existing_loggers': True,1815 'formatters': {1816 'detailed': {1817 'class': 'logging.Formatter',1818 'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1819 },1820 'simple': {1821 'class': 'logging.Formatter',1822 'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1823 }1824 },1825 'handlers': {1826 'console': {1827 'class': 'logging.StreamHandler',1828 'formatter': 'simple',1829 'level': 'INFO'1830 },1831 'file': {1832 'class': 'logging.FileHandler',1833 'filename': 'mplog.log',1834 'mode': 'w',1835 'formatter': 'detailed'1836 },1837 'foofile': {1838 'class': 'logging.FileHandler',1839 'filename': 'mplog-foo.log',1840 'mode': 'w',1841 'formatter': 'detailed'1842 },1843 'errors': {1844 'class': 'logging.FileHandler',1845 'filename': 'mplog-errors.log',1846 'mode': 'w',1847 'formatter': 'detailed',1848 'level': 'ERROR'1849 }1850 },1851 'loggers': {1852 'foo': {1853 'handlers': ['foofile']1854 }1855 },1856 'root': {1857 'handlers': ['console', 'file', 'errors'],1858 'level': 'DEBUG'1859 }1860 }1861 # Записываем несколько начальных событий, просто чтобы показать, что логирование в родительском процессе работает1862 # нормально.1863 logging.config.dictConfig(config_initial)1864 logger = logging.getLogger('setup')1865 logger.info('About to create workers ...')1866 workers = []1867 for i in range(5):1868 wp = Process(target=worker_process, name='worker %d' % (i + 1),1869 args=(config_worker,))1870 workers.append(wp)1871 wp.start()1872 logger.info('Started worker: %s', wp.name)1873 logger.info('About to create listener ...')1874 stop_event = Event()1875 lp = Process(target=listener_process, name='listener',1876 args=(q, stop_event, config_listener))1877 lp.start()1878 logger.info('Started listener')1879 # Теперь ожидаем завершения работы рабочих процессов.1880 for wp in workers:1881 wp.join()1882 # Все рабочие процессы завершены, теперь можно остановить прослушивание.1883 # Логирование в родительском процессе всё ещё работает нормально.1884 logger.info('Telling listener to stop ...')1885 stop_event.set()1886 lp.join()1887 logger.info('All done.')18881889if __name__ == '__main__':1890 main()1891```18921893## Вставка BOM в сообщения, отправляемые в SysLogHandler18941895[**RFC 5424**](https://python-all.ru/3.10/howto/logging-cookbook.html) требует, чтобы сообщение Unicode отправлялось демону syslog в виде набора байтов, имеющего следующую структуру: необязательный чисто ASCII-компонент, за которым следует метка порядка байтов UTF-8 (BOM), а затем Unicode, закодированный в UTF-8. (См. [**соответствующий раздел спецификации**](https://python-all.ru/3.10/howto/logging-cookbook.html).)18961897В Python 3.1 в [`SysLogHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.SysLogHandler) был добавлен код для вставки BOM в сообщение, но, к сожалению, он был реализован некорректно: BOM появлялся в начале сообщения и, следовательно, не допускал наличия чисто ASCII-компонента перед ним.18981899Поскольку такое поведение ошибочно, некорректный код вставки BOM удаляется из Python 3.2.4 и более поздних версий. Однако он не заменяется, и если требуется создавать сообщения, соответствующие [**RFC 5424**](https://python-all.ru/3.10/howto/logging-cookbook.html), которые включают BOM, необязательную чисто ASCII-последовательность перед ним и произвольный Unicode после него, закодированный в UTF-8, то необходимо сделать следующее:190019011. Необходимо присоединить экземпляр [`Formatter`](https://python-all.ru/3.10/library/logging.html#logging.Formatter) к экземпляру [`SysLogHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.SysLogHandler), указав строку формата, например:19021903 ```python1904 'ASCII section\ufeffUnicode section'1905 ```19061907 Кодовая точка Unicode U+FEFF при кодировании в UTF-8 будет представлена как метка порядка байтов UTF-8 – строка байтов `b'\xef\xbb\xbf'`.19082. ASCII-часть следует заменить на любые подходящие заполнители, но необходимо следить, чтобы данные, которые появляются там после подстановки, всегда были в ASCII (таким образом, они останутся без изменений после кодирования UTF-8).19093. Unicode-часть следует заменить на любые заполнители; если данные после подстановки содержат символы за пределами диапазона ASCII, это нормально – они будут закодированы в UTF-8.19101911Отформатированное сообщение *будет* закодировано в UTF-8 с помощью `SysLogHandler`. Если следовать приведённым выше правилам, можно создавать сообщения, соответствующие [**RFC 5424**](https://python-all.ru/3.10/howto/logging-cookbook.html). Если этого не делать, модуль logging может не жаловаться, но сообщения не будут соответствовать RFC 5424, и демон syslog может выражать недовольство.19121913## Реализация структурированного ведения журнала19141915Хотя большинство сообщений журнала предназначены для чтения человеком и поэтому не предназначены для машинного разбора, могут возникнуть ситуации, когда требуется выводить сообщения в структурированном формате, *который* может быть разобран программой (без необходимости в сложных регулярных выражениях). Это легко достигается с помощью пакета logging. Существует несколько способов, но ниже приведён простой подход, использующий JSON для сериализации события в машиночитаемом виде.19161917```python1918import json1919import logging19201921class StructuredMessage:1922 def __init__(self, message, /, **kwargs):1923 self.message = message1924 self.kwargs = kwargs19251926 def __str__(self):1927 return '%s >>> %s' % (self.message, json.dumps(self.kwargs))19281929_ = StructuredMessage # необязательно, для улучшения читаемости19301931logging.basicConfig(level=logging.INFO, format='%(message)s')1932logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))1933```19341935Если запустить приведённый выше скрипт, он выведет:19361937```text1938message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}1939```19401941Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.19421943Если требуется более специализированная обработка, можно использовать пользовательский кодировщик JSON, как в следующем полном примере:19441945```python1946import json1947import logging19481949class Encoder(json.JSONEncoder):1950 def default(self, o):1951 if isinstance(o, set):1952 return tuple(o)1953 elif isinstance(o, str):1954 return o.encode('unicode_escape').decode('ascii')1955 return super().default(o)19561957class StructuredMessage:1958 def __init__(self, message, /, **kwargs):1959 self.message = message1960 self.kwargs = kwargs19611962 def __str__(self):1963 s = Encoder().encode(self.kwargs)1964 return '%s >>> %s' % (self.message, s)19651966_ = StructuredMessage # необязательно, для улучшения читаемости19671968def main():1969 logging.basicConfig(level=logging.INFO, format='%(message)s')1970 logging.info(_('message 1', set_value={1, 2, 3}, snowman='\u2603'))19711972if __name__ == '__main__':1973 main()1974```19751976При запуске приведённого выше скрипта он выведет:19771978```text1979message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}1980```19811982Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.19831984## Настройка обработчиков с помощью [`dictConfig()`](https://python-all.ru/3.10/library/logging.config.html#logging.config.dictConfig)19851986Иногда требуется настроить обработчики логирования особым образом, и при использовании [`dictConfig()`](https://python-all.ru/3.10/library/logging.config.html#logging.config.dictConfig) это можно сделать без создания подклассов. Например, может потребоваться установить владельца файла журнала. В POSIX это легко сделать с помощью [`shutil.chown()`](https://python-all.ru/3.10/library/shutil.html#shutil.chown), но файловые обработчики в стандартной библиотеке не предоставляют встроенной поддержки. Можно настроить создание обработчика с помощью обычной функции, такой как:19871988```python1989def owned_file_handler(filename, mode='a', encoding=None, owner=None):1990 if owner:1991 if not os.path.exists(filename):1992 open(filename, 'a').close()1993 shutil.chown(filename, *owner)1994 return logging.FileHandler(filename, mode, encoding)1995```19961997Затем в конфигурации логирования, передаваемой в [`dictConfig()`](https://python-all.ru/3.10/library/logging.config.html#logging.config.dictConfig), можно указать, что обработчик должен быть создан вызовом этой функции:19981999```python2000LOGGING = {2001 'version': 1,2002 'disable_existing_loggers': False,2003 'formatters': {2004 'default': {2005 'format': '%(asctime)s %(levelname)s %(name)s %(message)s'2006 },2007 },2008 'handlers': {2009 'file':{2010 # Значения ниже извлекаются из этого словаря и2011 # используются для создания обработчика, установки его уровня и2012 # его форматтера.2013 '()': owned_file_handler,2014 'level':'DEBUG',2015 'formatter': 'default',2016 # Значения ниже передаются вызываемому объекту-создателю обработчика2017 # в качестве именованных аргументов.2018 'owner': ['pulse', 'pulse'],2019 'filename': 'chowntest.log',2020 'mode': 'w',2021 'encoding': 'utf-8',2022 },2023 },2024 'root': {2025 'handlers': ['file'],2026 'level': 'DEBUG',2027 },2028}2029```20302031В этом примере для иллюстрации права владения устанавливаются с использованием пользователя и группы `pulse`. Собирая всё вместе в рабочий скрипт, `chowntest.py`:20322033```python2034import logging, logging.config, os, shutil20352036def owned_file_handler(filename, mode='a', encoding=None, owner=None):2037 if owner:2038 if not os.path.exists(filename):2039 open(filename, 'a').close()2040 shutil.chown(filename, *owner)2041 return logging.FileHandler(filename, mode, encoding)20422043LOGGING = {2044 'version': 1,2045 'disable_existing_loggers': False,2046 'formatters': {2047 'default': {2048 'format': '%(asctime)s %(levelname)s %(name)s %(message)s'2049 },2050 },2051 'handlers': {2052 'file':{2053 # Значения ниже извлекаются из этого словаря и2054 # используются для создания обработчика, установки его уровня и2055 # его форматтера.2056 '()': owned_file_handler,2057 'level':'DEBUG',2058 'formatter': 'default',2059 # Значения ниже передаются вызываемому объекту-создателю обработчика2060 # в качестве именованных аргументов.2061 'owner': ['pulse', 'pulse'],2062 'filename': 'chowntest.log',2063 'mode': 'w',2064 'encoding': 'utf-8',2065 },2066 },2067 'root': {2068 'handlers': ['file'],2069 'level': 'DEBUG',2070 },2071}20722073logging.config.dictConfig(LOGGING)2074logger = logging.getLogger('mylogger')2075logger.debug('A debug message')2076```20772078Для запуска, вероятно, потребуется выполнить от имени `root`:20792080```console2081$ sudo python3.3 chowntest.py2082$ cat chowntest.log20832013-11-05 09:34:51,128 DEBUG mylogger A debug message2084$ ls -l chowntest.log2085-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log2086```20872088Обратите внимание, что в этом примере используется Python 3.3, потому что в нём появился [`shutil.chown()`](https://python-all.ru/3.10/library/shutil.html#shutil.chown). Этот подход должен работать с любой версией Python, поддерживающей [`dictConfig()`](https://python-all.ru/3.10/library/logging.config.html#logging.config.dictConfig) – а именно Python 2.7, 3.2 или новее. В версиях до 3.3 потребовалось бы реализовать фактическую смену владельца, например, с помощью [`os.chown()`](https://python-all.ru/3.10/library/os.html#os.chown).20892090На практике функция создания обработчика может находиться в служебном модуле где-нибудь в вашем проекте. Вместо строки в конфигурации:20912092```python2093'()': owned_file_handler,2094```20952096можно использовать, например:20972098```python2099'()': 'ext://project.util.owned_file_handler',2100```21012102где `project.util` можно заменить на фактическое имя пакета, в котором находится функция. В приведённом рабочем скрипте должно сработать использование `'ext://__main__.owned_file_handler'`. Здесь фактический вызываемый объект разрешается с помощью [`dictConfig()`](https://python-all.ru/3.10/library/logging.config.html#logging.config.dictConfig) из спецификации `ext://`.21032104Этот пример, надеюсь, также показывает, как можно реализовать другие типы изменений файлов – например, установку определённых битов разрешений POSIX – аналогичным образом, с помощью [`os.chmod()`](https://python-all.ru/3.10/library/os.html#os.chmod).21052106Разумеется, этот подход можно распространить и на другие типы обработчиков, помимо [`FileHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.FileHandler) – например, на один из вращающихся файловых обработчиков или на совершенно другой тип обработчика.21072108## Использование определённых стилей форматирования во всём приложении21092110В Python 3.2 у [`Formatter`](https://python-all.ru/3.10/library/logging.html#logging.Formatter) появился именованный параметр `style`, который, хотя по умолчанию для обратной совместимости он равен `%`, позволяет указать `{` или `$` для поддержки подходов к форматированию, поддерживаемых [`str.format()`](https://python-all.ru/3.10/library/stdtypes.html#str.format) и [`string.Template`](https://python-all.ru/3.10/library/string.html#string.Template). Обратите внимание, что это управляет форматированием сообщений журнала для окончательного вывода в журнал и совершенно не зависит от того, как конструируется отдельное сообщение журнала.21112112Вызовы логирования ([`debug()`](https://python-all.ru/3.10/library/logging.html#logging.Logger.debug), [`info()`](https://python-all.ru/3.10/library/logging.html#logging.Logger.info) и т.д.) принимают только позиционные параметры для самого сообщения журнала, а именованные параметры используются только для определения параметров обработки вызова (например, именованный параметр `exc_info` для указания, что нужно записывать информацию о трассировке, или именованный параметр `extra` для указания дополнительной контекстной информации, добавляемой в журнал). Таким образом, нельзя напрямую выполнять вызовы логирования с использованием синтаксиса [`str.format()`](https://python-all.ru/3.10/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.10/library/string.html#string.Template), потому что внутри пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Изменить это без нарушения обратной совместимости было бы невозможно, поскольку все существующие вызовы логирования в коде используют строки с %-форматированием.21132114Высказывались предложения связывать стили форматирования с конкретными регистраторами, но этот подход также сталкивается с проблемами обратной совместимости, поскольку любой существующий код может использовать данное имя регистратора и %-форматирование.21152116Чтобы логирование работало совместимо между любыми сторонними библиотеками и вашим кодом, решения о форматировании необходимо принимать на уровне отдельного вызова логирования. Это открывает несколько способов, которыми можно реализовать альтернативные стили форматирования.21172118### Использование фабрик LogRecord21192120В Python 3.2, вместе с упомянутыми выше изменениями [`Formatter`](https://python-all.ru/3.10/library/logging.html#logging.Formatter), пакет logging получил возможность позволять пользователям устанавливать свои собственные подклассы [`LogRecord`](https://python-all.ru/3.10/library/logging.html#logging.LogRecord) с помощью функции [`setLogRecordFactory()`](https://python-all.ru/3.10/library/logging.html#logging.setLogRecordFactory). Вы можете использовать это, чтобы установить свой собственный подкласс [`LogRecord`](https://python-all.ru/3.10/library/logging.html#logging.LogRecord), который делает правильные вещи, переопределяя метод [`getMessage()`](https://python-all.ru/3.10/library/logging.html#logging.LogRecord.getMessage). В реализации базового класса этого метода происходит форматирование `msg % args`, и именно здесь можно подставить альтернативное форматирование; однако следует быть осторожным, чтобы поддерживать все стили форматирования и разрешить %-форматирование по умолчанию для обеспечения совместимости с другим кодом. Также следует позаботиться о вызове `str(self.msg)`, как это делает базовая реализация.21212122Обратитесь к справочной документации по [`setLogRecordFactory()`](https://python-all.ru/3.10/library/logging.html#logging.setLogRecordFactory) и [`LogRecord`](https://python-all.ru/3.10/library/logging.html#logging.LogRecord) для получения дополнительной информации.21232124### Использование пользовательских объектов сообщений21252126Есть еще один, возможно, более простой способ использовать {}- и $-форматирование для построения отдельных сообщений лога. Вы, возможно, помните (из раздела [Использование произвольных объектов в качестве сообщений](https://python-all.ru/3.10/howto/logging.html#arbitrary-object-messages)), что при логировании можно использовать произвольный объект в качестве строки формата сообщения, и пакет logging вызовет [`str()`](https://python-all.ru/3.10/library/stdtypes.html#str) для этого объекта, чтобы получить фактическую строку формата. Рассмотрим следующие два класса:21272128```python2129class BraceMessage:2130 def __init__(self, fmt, /, *args, **kwargs):2131 self.fmt = fmt2132 self.args = args2133 self.kwargs = kwargs21342135 def __str__(self):2136 return self.fmt.format(*self.args, **self.kwargs)21372138class DollarMessage:2139 def __init__(self, fmt, /, **kwargs):2140 self.fmt = fmt2141 self.kwargs = kwargs21422143 def __str__(self):2144 from string import Template2145 return Template(self.fmt).substitute(**self.kwargs)2146```21472148Любой из них можно использовать вместо строки формата, чтобы разрешить {}- или $-форматирование для построения фактической части «message», которая появляется в форматированном выводе лога вместо «%(message)s», «{message}» или «$message». Если вам кажется неудобным использовать имена классов каждый раз при логировании, вы можете сделать это более приятным, используя псевдоним, такой как `M` или `_` для сообщения (или, возможно, `__`, если вы используете `_` для локализации).21492150Примеры этого подхода приведены ниже. Во-первых, форматирование с помощью [`str.format()`](https://python-all.ru/3.10/library/stdtypes.html#str.format):21512152```python2153>>> __ = BraceMessage2154>>> print(__('Message with {0} {1}', 2, 'placeholders'))2155Message with 2 placeholders2156>>> class Point: pass2157...2158>>> p = Point()2159>>> p.x = 0.52160>>> p.y = 0.52161>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))2162Message with coordinates: (0.50, 0.50)2163```21642165Во-вторых, форматирование с помощью [`string.Template`](https://python-all.ru/3.10/library/string.html#string.Template):21662167```python2168>>> __ = DollarMessage2169>>> print(__('Message with $num $what', num=2, what='placeholders'))2170Message with 2 placeholders2171>>>2172```21732174Стоит отметить, что при таком подходе вы не платите значительных потерь производительности: фактическое форматирование происходит не при вызове логирования, а когда (и если) сообщение лога действительно должно быть выведено в лог обработчиком. Так что единственная необычная вещь, которая может вас сбить с толку, это то, что круглые скобки ставятся вокруг строки формата и аргументов, а не только вокруг строки формата. Это потому, что нотация \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов `XXXMessage`, показанных выше.21752176## Настройка фильтров с помощью [`dictConfig()`](https://python-all.ru/3.10/library/logging.config.html#logging.config.dictConfig)21772178*Можно* настраивать фильтры с помощью [`dictConfig()`](https://python-all.ru/3.10/library/logging.config.html#logging.config.dictConfig), хотя с первого взгляда может быть неочевидно, как это сделать (поэтому и дан этот рецепт). Поскольку [`Filter`](https://python-all.ru/3.10/library/logging.html#logging.Filter) – единственный класс фильтра, включенный в стандартную библиотеку, и вряд ли он удовлетворит многие требования (он присутствует только как базовый класс), вам, как правило, потребуется определить свой собственный подкласс [`Filter`](https://python-all.ru/3.10/library/logging.html#logging.Filter) с переопределенным методом [`filter()`](https://python-all.ru/3.10/library/logging.html#logging.Filter.filter). Для этого укажите ключ `()` в словаре конфигурации для фильтра, указав вызываемый объект, который будет использоваться для создания фильтра (класс – наиболее очевидный вариант, но вы можете предоставить любой вызываемый объект, возвращающий экземпляр [`Filter`](https://python-all.ru/3.10/library/logging.html#logging.Filter)). Вот полный пример:21792180```python2181import logging2182import logging.config2183import sys21842185class MyFilter(logging.Filter):2186 def __init__(self, param=None):2187 self.param = param21882189 def filter(self, record):2190 if self.param is None:2191 allow = True2192 else:2193 allow = self.param not in record.msg2194 if allow:2195 record.msg = 'changed: ' + record.msg2196 return allow21972198LOGGING = {2199 'version': 1,2200 'filters': {2201 'myfilter': {2202 '()': MyFilter,2203 'param': 'noshow',2204 }2205 },2206 'handlers': {2207 'console': {2208 'class': 'logging.StreamHandler',2209 'filters': ['myfilter']2210 }2211 },2212 'root': {2213 'level': 'DEBUG',2214 'handlers': ['console']2215 },2216}22172218if __name__ == '__main__':2219 logging.config.dictConfig(LOGGING)2220 logging.debug('hello')2221 logging.debug('hello - noshow')2222```22232224Этот пример показывает, как можно передавать конфигурационные данные вызываемому объекту, который создает экземпляр, в виде именованных параметров. При запуске приведенный выше скрипт выведет:22252226```text2227changed: hello2228```22292230что показывает, что фильтр работает в соответствии с настройками.22312232Несколько дополнительных моментов, на которые стоит обратить внимание:22332234- Если вы не можете сослаться на вызываемый объект напрямую в конфигурации (например, если он находится в другом модуле, и вы не можете импортировать его напрямую в том месте, где находится словарь конфигурации), вы можете использовать форму `ext://...`, как описано в разделе [Доступ к внешним объектам](https://python-all.ru/3.10/library/logging.config.html#logging-config-dict-externalobj). Например, в приведенном выше примере можно было использовать текст `'ext://__main__.MyFilter'` вместо `MyFilter`.2235- Помимо фильтров, этот метод также можно использовать для настройки пользовательских обработчиков и форматтеров. Смотрите раздел [Пользовательские объекты](https://python-all.ru/3.10/library/logging.config.html#logging-config-dict-userdef) для получения дополнительной информации о том, как logging поддерживает использование пользовательских объектов в своей конфигурации, а также см. другой рецепт из этой книги рецептов [Настройка обработчиков с помощью dictConfig()](https://python-all.ru/3.10/howto/logging-cookbook.html#custom-handlers) выше.22362237## Настраиваемое форматирование исключений22382239Могут возникнуть ситуации, когда вы захотите настроить форматирование исключений – для примера, предположим, вы хотите ровно одну строку на каждое событие лога, даже если присутствует информация об исключении. Вы можете сделать это с помощью пользовательского класса форматтера, как показано в следующем примере:22402241```python2242import logging22432244class OneLineExceptionFormatter(logging.Formatter):2245 def formatException(self, exc_info):2246 """2247 Форматировать исключение так, чтобы оно выводилось одной строкой.2248 """2249 result = super().formatException(exc_info)2250 return repr(result) # или форматировать одной строкой по своему усмотрению22512252 def format(self, record):2253 s = super().format(record)2254 if record.exc_text:2255 s = s.replace('\n', '') + '|'2256 return s22572258def configure_logging():2259 fh = logging.FileHandler('output.txt', 'w')2260 f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',2261 '%d/%m/%Y %H:%M:%S')2262 fh.setFormatter(f)2263 root = logging.getLogger()2264 root.setLevel(logging.DEBUG)2265 root.addHandler(fh)22662267def main():2268 configure_logging()2269 logging.info('Sample message')2270 try:2271 x = 1 / 02272 except ZeroDivisionError as e:2273 logging.exception('ZeroDivisionError: %s', e)22742275if __name__ == '__main__':2276 main()2277```22782279При запуске это создает файл ровно с двумя строками:22802281```text228228/01/2015 07:21:23|INFO|Sample message|228328/01/2015 07:21:23|ERROR|ZeroDivisionError: integer division or modulo by zero|'Traceback (most recent call last):\n File "logtest7.py", line 30, in main\n x = 1 / 0\nZeroDivisionError: integer division or modulo by zero'|2284```22852286Хотя описанный выше подход упрощен, он показывает путь к тому, как можно форматировать информацию об исключениях по своему вкусу. Модуль [`traceback`](https://python-all.ru/3.10/library/traceback.html#module-traceback) может быть полезен для более специализированных нужд.22872288## Озвучивание сообщений лога22892290Могут быть ситуации, когда желательно выводить сообщения лога в звуковом, а не визуальном формате. Это легко сделать, если в вашей системе доступна функция преобразования текста в речь (TTS), даже если у нее нет привязки к Python. Большинство TTS-систем имеют программу командной строки, которую можно запустить, и ее можно вызвать из обработчика с помощью [`subprocess`](https://python-all.ru/3.10/library/subprocess.html#module-subprocess). Здесь предполагается, что программы командной строки TTS не будут ожидать взаимодействия с пользователем или занимать много времени для завершения, и что частота сообщений лога не будет настолько высокой, чтобы перегружать пользователя сообщениями, и что допустимо проговаривать сообщения по одному, а не одновременно. В приведенном ниже примере реализации ожидается, пока одно сообщение не будет произнесено, прежде чем обрабатывать следующее, и это может заставить другие обработчики ждать. Вот короткий пример, демонстрирующий подход, который предполагает, что доступен TTS-пакет `espeak`:22912292```python2293import logging2294import subprocess2295import sys22962297class TTSHandler(logging.Handler):2298 def emit(self, record):2299 msg = self.format(record)2300 # Говорить медленно женским английским голосом.2301 cmd = ['espeak', '-s150', '-ven+f3', msg]2302 p = subprocess.Popen(cmd, stdout=subprocess.PIPE,2303 stderr=subprocess.STDOUT)2304 # дождаться завершения программы2305 p.communicate()23062307def configure_logging():2308 h = TTSHandler()2309 root = logging.getLogger()2310 root.addHandler(h)2311 # стандартный форматтер просто возвращает сообщение2312 root.setLevel(logging.DEBUG)23132314def main():2315 logging.info('Hello')2316 logging.debug('Goodbye')23172318if __name__ == '__main__':2319 configure_logging()2320 sys.exit(main())2321```23222323При запуске этот скрипт должен сказать «Hello», а затем «Goodbye» женским голосом.23242325Описанный выше подход, конечно, можно адаптировать для других TTS-систем и даже для других систем, которые могут обрабатывать сообщения через внешние программы, запускаемые из командной строки.23262327## Буферизация сообщений лога и условный вывод23282329Могут возникнуть ситуации, когда вы хотите записывать сообщения во временную область и выводить их только при наступлении определенного условия. Например, вы можете начать запись отладочных событий в функции, и если функция завершится без ошибок, вы не захотите засорять лог собранной отладочной информацией, но если возникнет ошибка, вы захотите вывести всю отладочную информацию вместе с ошибкой.23302331Вот пример, показывающий, как это можно сделать с помощью декоратора для ваших функций, где вы хотите, чтобы логирование вело себя таким образом. Он использует [`logging.handlers.MemoryHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.MemoryHandler), который позволяет буферизовать зарегистрированные события до наступления некоторого условия, после чего буферизованные события `flushed` – передаются другому обработчику (обработчику `target`) для обработки. По умолчанию `MemoryHandler` сбрасывается, когда его буфер заполняется или встречается событие, уровень которого больше или равен указанному порогу. Вы можете использовать этот рецепт с более специализированным подклассом `MemoryHandler`, если хотите настроить поведение сброса.23322333Пример скрипта содержит простую функцию `foo`, которая просто перебирает все уровни логирования, записывая в `sys.stderr` информацию о том, какой уровень будет использоваться, а затем регистрирует сообщение на этом уровне. Вы можете передать параметр в `foo`, который, если равен true, будет регистрировать на уровнях ERROR и CRITICAL – в противном случае он регистрирует только на уровнях DEBUG, INFO и WARNING.23342335Скрипт просто настраивает декорирование `foo` декоратором, который будет выполнять необходимое условное логирование. Декоратор принимает регистратор в качестве параметра и подключает обработчик памяти на время вызова декорированной функции. Декоратор можно дополнительно параметризовать с помощью целевого обработчика, уровня, при котором должен происходить сброс, и емкости буфера (количество буферизируемых записей). По умолчанию они равны [`StreamHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.StreamHandler), который пишет в `sys.stderr`, `logging.ERROR` и `100` соответственно.23362337Вот скрипт:23382339```python2340import logging2341from logging.handlers import MemoryHandler2342import sys23432344logger = logging.getLogger(__name__)2345logger.addHandler(logging.NullHandler())23462347def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):2348 if target_handler is None:2349 target_handler = logging.StreamHandler()2350 if flush_level is None:2351 flush_level = logging.ERROR2352 if capacity is None:2353 capacity = 1002354 handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)23552356 def decorator(fn):2357 def wrapper(*args, **kwargs):2358 logger.addHandler(handler)2359 try:2360 return fn(*args, **kwargs)2361 except Exception:2362 logger.exception('call failed')2363 raise2364 finally:2365 super(MemoryHandler, handler).flush()2366 logger.removeHandler(handler)2367 return wrapper23682369 return decorator23702371def write_line(s):2372 sys.stderr.write('%s\n' % s)23732374def foo(fail=False):2375 write_line('about to log at DEBUG ...')2376 logger.debug('Actually logged at DEBUG')2377 write_line('about to log at INFO ...')2378 logger.info('Actually logged at INFO')2379 write_line('about to log at WARNING ...')2380 logger.warning('Actually logged at WARNING')2381 if fail:2382 write_line('about to log at ERROR ...')2383 logger.error('Actually logged at ERROR')2384 write_line('about to log at CRITICAL ...')2385 logger.critical('Actually logged at CRITICAL')2386 return fail23872388decorated_foo = log_if_errors(logger)(foo)23892390if __name__ == '__main__':2391 logger.setLevel(logging.DEBUG)2392 write_line('Calling undecorated foo with False')2393 assert not foo(False)2394 write_line('Calling undecorated foo with True')2395 assert foo(True)2396 write_line('Calling decorated foo with False')2397 assert not decorated_foo(False)2398 write_line('Calling decorated foo with True')2399 assert decorated_foo(True)2400```24012402При запуске этого скрипта отобразится следующий вывод:24032404```text2405Calling undecorated foo with False2406about to log at DEBUG ...2407about to log at INFO ...2408about to log at WARNING ...2409Calling undecorated foo with True2410about to log at DEBUG ...2411about to log at INFO ...2412about to log at WARNING ...2413about to log at ERROR ...2414about to log at CRITICAL ...2415Calling decorated foo with False2416about to log at DEBUG ...2417about to log at INFO ...2418about to log at WARNING ...2419Calling decorated foo with True2420about to log at DEBUG ...2421about to log at INFO ...2422about to log at WARNING ...2423about to log at ERROR ...2424Actually logged at DEBUG2425Actually logged at INFO2426Actually logged at WARNING2427Actually logged at ERROR2428about to log at CRITICAL ...2429Actually logged at CRITICAL2430```24312432Как видно, фактический вывод журнала происходит только при регистрации события, уровень которого ERROR или выше, но в этом случае также регистрируются все предыдущие события с более низкими уровнями.24332434Конечно, можно использовать обычные средства декорирования:24352436```python2437@log_if_errors(logger)2438def foo(fail=False):2439 ...2440```24412442## Отправка сообщений журнала по электронной почте с буферизацией24432444Чтобы проиллюстрировать, как можно отправлять сообщения журнала по электронной почте, так чтобы заданное количество сообщений отправлялось за одно письмо, можно создать подкласс [`BufferingHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.BufferingHandler). В приведённом ниже примере, который можно адаптировать под свои нужды, предоставляется простая тестовая обвязка, позволяющая запустить скрипт с аргументами командной строки, указывающими, что обычно необходимо для отправки через SMTP. (Запустите загруженный скрипт с аргументом `-h`, чтобы увидеть обязательные и необязательные аргументы.)24452446```python2447import logging2448import logging.handlers2449import smtplib24502451class BufferingSMTPHandler(logging.handlers.BufferingHandler):2452 def __init__(self, mailhost, port, username, password, fromaddr, toaddrs,2453 subject, capacity):2454 logging.handlers.BufferingHandler.__init__(self, capacity)2455 self.mailhost = mailhost2456 self.mailport = port2457 self.username = username2458 self.password = password2459 self.fromaddr = fromaddr2460 if isinstance(toaddrs, str):2461 toaddrs = [toaddrs]2462 self.toaddrs = toaddrs2463 self.subject = subject2464 self.setFormatter(logging.Formatter("%(asctime)s %(levelname)-5s %(message)s"))24652466 def flush(self):2467 if len(self.buffer) > 0:2468 try:2469 smtp = smtplib.SMTP(self.mailhost, self.mailport)2470 smtp.starttls()2471 smtp.login(self.username, self.password)2472 msg = "From: %s\r\nTo: %s\r\nSubject: %s\r\n\r\n" % (self.fromaddr, ','.join(self.toaddrs), self.subject)2473 for record in self.buffer:2474 s = self.format(record)2475 msg = msg + s + "\r\n"2476 smtp.sendmail(self.fromaddr, self.toaddrs, msg)2477 smtp.quit()2478 except Exception:2479 if logging.raiseExceptions:2480 raise2481 self.buffer = []24822483if __name__ == '__main__':2484 import argparse24852486 ap = argparse.ArgumentParser()2487 aa = ap.add_argument2488 aa('host', metavar='HOST', help='SMTP server')2489 aa('--port', '-p', type=int, default=587, help='SMTP port')2490 aa('user', metavar='USER', help='SMTP username')2491 aa('password', metavar='PASSWORD', help='SMTP password')2492 aa('to', metavar='TO', help='Addressee for emails')2493 aa('sender', metavar='SENDER', help='Sender email address')2494 aa('--subject', '-s',2495 default='Test Logging email from Python logging module (buffering)',2496 help='Subject of email')2497 options = ap.parse_args()2498 logger = logging.getLogger()2499 logger.setLevel(logging.DEBUG)2500 h = BufferingSMTPHandler(options.host, options.port, options.user,2501 options.password, options.sender,2502 options.to, options.subject, 10)2503 logger.addHandler(h)2504 for i in range(102):2505 logger.info("Info index = %d", i)2506 h.flush()2507 h.close()2508```25092510Если запустить этот скрипт и SMTP-сервер настроен правильно, то будет отправлено одиннадцать писем указанному адресату. Первые десять писем будут содержать по десять сообщений журнала, а одиннадцатое – два сообщения. В сумме получается 102 сообщения, как указано в скрипте.25112512## Форматирование времени с использованием UTC (GMT) через конфигурацию25132514Иногда требуется форматировать время в UTC, что можно сделать с помощью класса `UTCFormatter`, показанного ниже:25152516```python2517import logging2518import time25192520class UTCFormatter(logging.Formatter):2521 converter = time.gmtime2522```25232524и затем можно использовать `UTCFormatter` в своём коде вместо [`Formatter`](https://python-all.ru/3.10/library/logging.html#logging.Formatter). Если требуется сделать это через конфигурацию, можно воспользоваться API [`dictConfig()`](https://python-all.ru/3.10/library/logging.config.html#logging.config.dictConfig), как показано в следующем полном примере:25252526```python2527import logging2528import logging.config2529import time25302531class UTCFormatter(logging.Formatter):2532 converter = time.gmtime25332534LOGGING = {2535 'version': 1,2536 'disable_existing_loggers': False,2537 'formatters': {2538 'utc': {2539 '()': UTCFormatter,2540 'format': '%(asctime)s %(message)s',2541 },2542 'local': {2543 'format': '%(asctime)s %(message)s',2544 }2545 },2546 'handlers': {2547 'console1': {2548 'class': 'logging.StreamHandler',2549 'formatter': 'utc',2550 },2551 'console2': {2552 'class': 'logging.StreamHandler',2553 'formatter': 'local',2554 },2555 },2556 'root': {2557 'handlers': ['console1', 'console2'],2558 }2559}25602561if __name__ == '__main__':2562 logging.config.dictConfig(LOGGING)2563 logging.warning('The local time is %s', time.asctime())2564```25652566При запуске этого скрипта он должен вывести примерно следующее:25672568```text25692015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 201525702015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 20152571```25722573показывая, как время форматируется как в местном времени, так и в UTC, по одному для каждого обработчика.25742575## Использование контекстного менеджера для выборочного журналирования25762577Бывают ситуации, когда полезно временно изменить конфигурацию журналирования, а затем вернуть её обратно после выполнения каких-то действий. Для этого контекстный менеджер – самый очевидный способ сохранить и восстановить контекст журналирования. Вот простой пример такого контекстного менеджера, который позволяет по желанию изменить уровень журналирования и добавить обработчик журнала исключительно в области действия контекстного менеджера:25782579```python2580import logging2581import sys25822583class LoggingContext:2584 def __init__(self, logger, level=None, handler=None, close=True):2585 self.logger = logger2586 self.level = level2587 self.handler = handler2588 self.close = close25892590 def __enter__(self):2591 if self.level is not None:2592 self.old_level = self.logger.level2593 self.logger.setLevel(self.level)2594 if self.handler:2595 self.logger.addHandler(self.handler)25962597 def __exit__(self, et, ev, tb):2598 if self.level is not None:2599 self.logger.setLevel(self.old_level)2600 if self.handler:2601 self.logger.removeHandler(self.handler)2602 if self.handler and self.close:2603 self.handler.close()2604 # неявный возврат None => не подавлять исключения2605```26062607Если указать значение уровня, уровень регистратора устанавливается на это значение в области действия блока with, охватываемого контекстным менеджером. Если указать обработчик, он добавляется к регистратору при входе в блок и удаляется при выходе из блока. Также можно попросить менеджер закрыть обработчик при выходе из блока – это можно сделать, если обработчик больше не нужен.26082609Чтобы проиллюстрировать, как это работает, можно добавить следующий блок кода к предыдущему:26102611```python2612if __name__ == '__main__':2613 logger = logging.getLogger('foo')2614 logger.addHandler(logging.StreamHandler())2615 logger.setLevel(logging.INFO)2616 logger.info('1. This should appear just once on stderr.')2617 logger.debug('2. This should not appear.')2618 with LoggingContext(logger, level=logging.DEBUG):2619 logger.debug('3. This should appear once on stderr.')2620 logger.debug('4. This should not appear.')2621 h = logging.StreamHandler(sys.stdout)2622 with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):2623 logger.debug('5. This should appear twice - once on stderr and once on stdout.')2624 logger.info('6. This should appear just once on stderr.')2625 logger.debug('7. This should not appear.')2626```26272628Изначально устанавливаем уровень регистратора равным `INFO`, поэтому сообщение №1 отображается, а сообщение №2 – нет. Затем временно меняем уровень на `DEBUG` в следующем блоке `with`, и сообщение №3 отображается. После выхода из блока уровень регистратора восстанавливается до `INFO`, поэтому сообщение №4 не отображается. В следующем блоке `with` снова устанавливаем уровень `DEBUG`, но также добавляем обработчик, записывающий в `sys.stdout`. Таким образом, сообщение №5 отображается дважды на консоли (один раз через `stderr` и один раз через `stdout`). После завершения оператора `with` состояние возвращается к исходному, поэтому сообщение №6 отображается (как сообщение №1), а сообщение №7 – нет (как сообщение №2).26292630Если запустить полученный скрипт, результат будет следующим:26312632```console2633$ python logctx.py26341. This should appear just once on stderr.26353. This should appear once on stderr.26365. This should appear twice - once on stderr and once on stdout.26375. This should appear twice - once on stderr and once on stdout.26386. This should appear just once on stderr.2639```26402641Если запустить его снова, но перенаправить `stderr` в `/dev/null`, мы увидим следующее, что является единственным сообщением, записанным в `stdout`:26422643```console2644$ python logctx.py 2>/dev/null26455. This should appear twice - once on stderr and once on stdout.2646```26472648Ещё раз, но перенаправляя `stdout` в `/dev/null`, получаем:26492650```console2651$ python logctx.py >/dev/null26521. This should appear just once on stderr.26533. This should appear once on stderr.26545. This should appear twice - once on stderr and once on stdout.26556. This should appear just once on stderr.2656```26572658В этом случае сообщение №5, выведенное в `stdout`, не отображается, как и ожидалось.26592660Разумеется, описанный подход можно обобщить, например, для временного подключения фильтров журналирования. Обратите внимание, что приведённый выше код работает как в Python 2, так и в Python 3.26612662## Шаблон для запуска CLI-приложения26632664Вот пример, показывающий, как можно:26652666- Использовать уровень журналирования на основе аргументов командной строки2667- Перенаправлять вызовы к нескольким подкомандам в отдельных файлах, все с журналированием на одном уровне согласованным образом2668- Использовать простую минимальную конфигурацию26692670Предположим, у нас есть приложение командной строки, которое останавливает, запускает или перезапускает некоторые службы. Для иллюстрации это может быть организовано в виде файла `app.py`, который является главным скриптом приложения, с отдельными командами, реализованными в `start.py`, `stop.py` и `restart.py`. Предположим также, что мы хотим управлять степенью подробности вывода приложения через аргумент командной строки с значением по умолчанию `logging.INFO`. Вот один из способов, как мог бы быть написан `app.py`:26712672```python2673import argparse2674import importlib2675import logging2676import os2677import sys26782679def main(args=None):2680 scriptname = os.path.basename(__file__)2681 parser = argparse.ArgumentParser(scriptname)2682 levels = ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')2683 parser.add_argument('--log-level', default='INFO', choices=levels)2684 subparsers = parser.add_subparsers(dest='command',2685 help='Available commands:')2686 start_cmd = subparsers.add_parser('start', help='Start a service')2687 start_cmd.add_argument('name', metavar='NAME',2688 help='Name of service to start')2689 stop_cmd = subparsers.add_parser('stop',2690 help='Stop one or more services')2691 stop_cmd.add_argument('names', metavar='NAME', nargs='+',2692 help='Name of service to stop')2693 restart_cmd = subparsers.add_parser('restart',2694 help='Restart one or more services')2695 restart_cmd.add_argument('names', metavar='NAME', nargs='+',2696 help='Name of service to restart')2697 options = parser.parse_args()2698 # весь код для отправки команд мог бы быть в этом файле. Для целей2699 # только в целях иллюстрации каждая команда реализована в отдельном модуле.2700 try:2701 mod = importlib.import_module(options.command)2702 cmd = getattr(mod, 'command')2703 except (ImportError, AttributeError):2704 print('Unable to find the code for command \'%s\'' % options.command)2705 return 12706 # Здесь можно было бы сделать по-хитрому и загрузить конфигурацию из файла или словаря2707 logging.basicConfig(level=options.log_level,2708 format='%(levelname)s %(name)s %(message)s')2709 cmd(options)27102711if __name__ == '__main__':2712 sys.exit(main())2713```27142715А команды `start`, `stop` и `restart` могут быть реализованы в отдельных модулях, например, для запуска:27162717```python2718# start.py2719import logging27202721logger = logging.getLogger(__name__)27222723def command(options):2724 logger.debug('About to start %s', options.name)2725 # здесь происходит фактическая обработка команды...2726 logger.info('Started the \'%s\' service.', options.name)2727```27282729и аналогично для остановки:27302731```python2732# stop.py2733import logging27342735logger = logging.getLogger(__name__)27362737def command(options):2738 n = len(options.names)2739 if n == 1:2740 plural = ''2741 services = '\'%s\'' % options.names[0]2742 else:2743 plural = 's'2744 services = ', '.join('\'%s\'' % name for name in options.names)2745 i = services.rfind(', ')2746 services = services[:i] + ' and ' + services[i + 2:]2747 logger.debug('About to stop %s', services)2748 # здесь происходит фактическая обработка команды...2749 logger.info('Stopped the %s service%s.', services, plural)2750```27512752и аналогично для перезапуска:27532754```python2755# restart.py2756import logging27572758logger = logging.getLogger(__name__)27592760def command(options):2761 n = len(options.names)2762 if n == 1:2763 plural = ''2764 services = '\'%s\'' % options.names[0]2765 else:2766 plural = 's'2767 services = ', '.join('\'%s\'' % name for name in options.names)2768 i = services.rfind(', ')2769 services = services[:i] + ' and ' + services[i + 2:]2770 logger.debug('About to restart %s', services)2771 # здесь происходит фактическая обработка команды...2772 logger.info('Restarted the %s service%s.', services, plural)2773```27742775Если запустить это приложение с уровнем журналирования по умолчанию, мы получим примерно такой вывод:27762777```console2778$ python app.py start foo2779INFO start Started the 'foo' service.27802781$ python app.py stop foo bar2782INFO stop Stopped the 'foo' and 'bar' services.27832784$ python app.py restart foo bar baz2785INFO restart Restarted the 'foo', 'bar' and 'baz' services.2786```27872788Первое слово – уровень журналирования, а второе – имя модуля или пакета, в котором было зарегистрировано событие.27892790Если изменить уровень журналирования, можно изменить объём информации, отправляемой в журнал. Например, чтобы получить больше информации:27912792```console2793$ python app.py --log-level DEBUG start foo2794DEBUG start About to start foo2795INFO start Started the 'foo' service.27962797$ python app.py --log-level DEBUG stop foo bar2798DEBUG stop About to stop 'foo' and 'bar'2799INFO stop Stopped the 'foo' and 'bar' services.28002801$ python app.py --log-level DEBUG restart foo bar baz2802DEBUG restart About to restart 'foo', 'bar' and 'baz'2803INFO restart Restarted the 'foo', 'bar' and 'baz' services.2804```28052806А если нужно меньше:28072808```console2809$ python app.py --log-level WARNING start foo2810$ python app.py --log-level WARNING stop foo bar2811$ python app.py --log-level WARNING restart foo bar baz2812```28132814В этом случае команды ничего не выводят в консоль, поскольку ни одно сообщение уровня `WARNING` и выше ими не записывается.28152816## Графический интерфейс Qt для журналирования28172818Время от времени возникает вопрос о том, как организовать логирование в GUI-приложении. Фреймворк [Qt](https://python-all.ru/3.10/howto/logging-cookbook.html) – популярная кроссплатформенная UI-среда с привязками к Python через библиотеки [PySide2](https://python-all.ru/3.10/howto/logging-cookbook.html) или [PyQt5](https://python-all.ru/3.10/howto/logging-cookbook.html).28192820В следующем примере показано, как выполнять журналирование в графический интерфейс Qt. Он представляет простой класс `QtHandler`, который принимает вызываемый объект – слот главного потока, обновляющий GUI. Также создаётся рабочий поток, чтобы продемонстрировать возможность журналирования как из самого интерфейса (через кнопку для ручной записи), так и из фонового рабочего потока (который в данном случае просто выводит сообщения со случайными уровнями и случайными короткими задержками).28212822Рабочий поток реализован с помощью класса `QThread` из Qt, а не модуля [`threading`](https://python-all.ru/3.10/library/threading.html#module-threading), поскольку бывают ситуации, когда необходимо использовать `QThread`, который обеспечивает лучшую интеграцию с другими компонентами `Qt`.28232824Код должен работать с последними версиями `PySide2` или `PyQt5`. Вы сможете адаптировать подход для более старых версий Qt. Обратитесь к комментариям в фрагменте кода за более подробной информацией.28252826```python2827import datetime2828import logging2829import random2830import sys2831import time28322833# Обработка мелких различий между PySide2 и PyQt52834try:2835 from PySide2 import QtCore, QtGui, QtWidgets2836 Signal = QtCore.Signal2837 Slot = QtCore.Slot2838except ImportError:2839 from PyQt5 import QtCore, QtGui, QtWidgets2840 Signal = QtCore.pyqtSignal2841 Slot = QtCore.pyqtSlot28422843logger = logging.getLogger(__name__)28442845#2846# Сигналы должны содержаться в QObject или подклассе, чтобы корректно2847# инициализироваться.2848#2849class Signaller(QtCore.QObject):2850 signal = Signal(str, logging.LogRecord)28512852#2853# Вывод в графический интерфейс Qt должен происходить только в главном потоке. Поэтому данный2854# обработчик спроектирован так, чтобы принимать функцию-слот, настроенную на выполнение в главном2855# потоке. В этом примере функция принимает строковый аргумент, который является2856# отформатированным сообщением лога, и запись лога, которая его породила. Отформатированная2857# строка – это просто удобство; можно отформатировать строку для вывода любым способом2858# в самой функции-слоте.2859#2860# Функцию-слот можно настроить на любые нужные обновления GUI. Обработчик2861# не знает и не заботится о конкретных элементах интерфейса.2862#2863class QtHandler(logging.Handler):2864 def __init__(self, slotfunc, *args, **kwargs):2865 super().__init__(*args, **kwargs)2866 self.signaller = Signaller()2867 self.signaller.signal.connect(slotfunc)28682869 def emit(self, record):2870 s = self.format(record)2871 self.signaller.signal.emit(s, record)28722873#2874# В этом примере используются QThreads, что означает, что потоки на уровне Python2875# называются как-то вроде "Dummy-1". Функция ниже получает имя Qt2876# текущего потока.2877#2878def ctname():2879 return QtCore.QThread.currentThread().objectName()28802881#2882# Используется для генерации случайных уровней для логирования.2883#2884LEVELS = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,2885 logging.CRITICAL)28862887#2888# Этот класс-воркер представляет работу, выполняемую в потоке, отдельном от2889# главного потока. Поток запускается на выполнение работы по нажатию кнопки,2890# которая соединяется со слотом в воркере.2891#2892# Поскольку значение threadName по умолчанию в LogRecord не очень полезно, мы добавляем2893# qThreadName, содержащий имя QThread, вычисленное выше, и передаём это2894# значение в словаре "extra", который используется для обновления LogRecord с помощью2895# имя QThread.2896#2897# Этот пример рабочего просто выводит сообщения последовательно, перемежая их случайными задержками порядка нескольких секунд.2898# Позволяет потоку выполняться до прерывания. Это обеспечивает достаточно чистую остановку потока.2899#2900class Worker(QtCore.QObject):2901 @Slot()2902 def start(self):2903 extra = {'qThreadName': ctname() }2904 logger.debug('Started work', extra=extra)2905 i = 12906 # Реализует простой пользовательский интерфейс для этого примера из кулинарной книги. Он содержит:2907 # * Окно текстового редактора только для чтения, которое содержит форматированные сообщения журнала2908 while not QtCore.QThread.currentThread().isInterruptionRequested():2909 delay = 0.5 + random.random() * 22910 time.sleep(delay)2911 level = random.choice(LEVELS)2912 logger.log(level, 'Message after delay of %3.1f: %d', delay, i, extra=extra)2913 i += 129142915#2916# * Кнопка запуска работы и записи в журнал в отдельном потоке2917#2918# * Кнопка записи чего-либо из основного потока2919# * Кнопка очистки окна журнала2920# Устанавливает моноширинный шрифт, принятый по умолчанию на платформе2921# для Qt62922#2923class Window(QtWidgets.QWidget):29242925 COLORS = {2926 logging.DEBUG: 'black',2927 logging.INFO: 'blue',2928 logging.WARNING: 'orange',2929 logging.ERROR: 'red',2930 logging.CRITICAL: 'purple',2931 }29322933 def __init__(self, app):2934 super().__init__()2935 self.app = app2936 self.textedit = te = QtWidgets.QPlainTextEdit(self)2937 # Устанавливает моноширинный шрифт по умолчанию для платформы2938 f = QtGui.QFont('nosuchfont')2939 f.setStyleHint(f.Monospace)2940 te.setFont(f)2941 te.setReadOnly(True)2942 PB = QtWidgets.QPushButton2943 self.work_button = PB('Start background work', self)2944 self.log_button = PB('Log a message at a random level', self)2945 self.clear_button = PB('Clear log window', self)2946 self.handler = h = QtHandler(self.update_status)2947 # Размещает все виджеты2948 fs = '%(asctime)s %(qThreadName)-12s %(levelname)-8s %(message)s'2949 formatter = logging.Formatter(fs)2950 h.setFormatter(formatter)2951 logger.addHandler(h)2952 # Подключает слоты и сигналы, не относящиеся к рабочему2953 app.aboutToQuit.connect(self.force_quit)29542955 # Запускает новый рабочий поток и подключает слоты для рабочего2956 layout = QtWidgets.QVBoxLayout(self)2957 layout.addWidget(te)2958 layout.addWidget(self.work_button)2959 layout.addWidget(self.log_button)2960 layout.addWidget(self.clear_button)2961 self.setFixedSize(900, 400)29622963 # После запуска кнопка должна быть отключена2964 self.log_button.clicked.connect(self.manual_update)2965 self.clear_button.clicked.connect(self.clear_display)29662967 # Запустить новый рабочий поток и подключить слоты для рабочего2968 self.start_thread()2969 self.work_button.clicked.connect(self.worker.start)2970 # Это запустит цикл событий в рабочем потоке2971 self.work_button.clicked.connect(lambda : self.work_button.setEnabled(False))29722973 def start_thread(self):2974 self.worker = Worker()2975 self.worker_thread = QtCore.QThread()2976 self.worker.setObjectName('Worker')2977 self.worker_thread.setObjectName('WorkerThread') # Просто скажите рабочему остановиться, затем скажите ему выйти и дождитесь этого2978 self.worker.moveToThread(self.worker_thread)2979 # Для использования при закрытии окна2980 self.worker_thread.start()29812982 def kill_thread(self):2983 # Функции ниже обновляют интерфейс и выполняются в основном потоке, поскольку слоты настроены именно там2984 # Эта функция использует переданное форматированное сообщение, но также использует информацию из записи, чтобы отформатировать сообщение подходящим цветом в соответствии с его серьёзностью (уровнем).2985 self.worker_thread.requestInterruption()2986 if self.worker_thread.isRunning():2987 self.worker_thread.quit()2988 self.worker_thread.wait()2989 else:2990 print('worker has already exited.')29912992 def force_quit(self):2993 # Для использования при закрытии окна2994 if self.worker_thread.isRunning():2995 self.kill_thread()29962997 # Функции ниже обновляют пользовательский интерфейс и выполняются в главном потоке, потому что2998 # здесь настраиваются слоты29993000 @Slot(str, logging.LogRecord)3001 def update_status(self, status, record):3002 color = self.COLORS.get(record.levelno, 'black')3003 s = '<pre><font color="%s">%s</font></pre>' % (color, status)3004 self.textedit.appendHtml(s)30053006 @Slot()3007 def manual_update(self):3008 # Эта функция использует переданное форматированное сообщение, а также использует3009 # информацию из записи для форматирования сообщения в подходящий3010 # цвет в соответствии с его серьёзностью (уровнем).3011 level = random.choice(LEVELS)3012 extra = {'qThreadName': ctname() }3013 logger.log(level, 'Manually logged!', extra=extra)30143015 @Slot()3016 def clear_display(self):3017 self.textedit.clear()30183019def main():3020 QtCore.QThread.currentThread().setObjectName('MainThread')3021 logging.getLogger().setLevel(logging.DEBUG)3022 app = QtWidgets.QApplication(sys.argv)3023 example = Window(app)3024 example.show()3025 sys.exit(app.exec_())30263027if __name__=='__main__':3028 main()3029```30303031## Журналирование в syslog с поддержкой RFC 542430323033Хотя [**RFC 5424**](https://python-all.ru/3.10/howto/logging-cookbook.html) датируется 2009 годом, большинство syslog-серверов по умолчанию настроены на использование более старого [**RFC 3164**](https://python-all.ru/3.10/howto/logging-cookbook.html), который берёт начало в 2001 году. Когда `logging` был добавлен в Python в 2003 году, он поддерживал более ранний (и единственный существовавший на тот момент) протокол. С момента выхода RFC 5424, поскольку он не получил широкого распространения в syslog-серверах, функциональность [`SysLogHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.handlers.SysLogHandler) не обновлялась.30343035RFC 5424 содержит полезные возможности, такие как поддержка структурированных данных. Если необходимо вести журналирование на syslog-сервер с поддержкой этого протокола, это можно сделать с помощью подкласса обработчика, который выглядит примерно так:30363037```python3038import datetime3039import logging.handlers3040import re3041import socket3042import time30433044class SysLogHandler5424(logging.handlers.SysLogHandler):30453046 tz_offset = re.compile(r'([+-]\d{2})(\d{2})$')3047 escaped = re.compile(r'([\]"\\])')30483049 def __init__(self, *args, **kwargs):3050 self.msgid = kwargs.pop('msgid', None)3051 self.appname = kwargs.pop('appname', None)3052 super().__init__(*args, **kwargs)30533054 def format(self, record):3055 version = 13056 asctime = datetime.datetime.fromtimestamp(record.created).isoformat()3057 m = self.tz_offset.match(time.strftime('%z'))3058 has_offset = False3059 if m and time.timezone:3060 hrs, mins = m.groups()3061 if int(hrs) or int(mins):3062 has_offset = True3063 if not has_offset:3064 asctime += 'Z'3065 else:3066 asctime += f'{hrs}:{mins}'3067 try:3068 hostname = socket.gethostname()3069 except Exception:3070 hostname = '-'3071 appname = self.appname or '-'3072 procid = record.process3073 msgid = '-'3074 msg = super().format(record)3075 sdata = '-'3076 if hasattr(record, 'structured_data'):3077 sd = record.structured_data3078 # Это должен быть словарь, где ключи – SD-ID, а значение –3079 # словарь, отображающий PARAM-NAME на PARAM-VALUE (обратитесь к RFC, чтобы узнать, что эти3080 # означают)3081 # Здесь нет проверки ошибок – это только для иллюстрации, и вы3082 # можете адаптировать этот код для использования в производственных средах3083 parts = []30843085 def replacer(m):3086 g = m.groups()3087 return '\\' + g[0]30883089 for sdid, dv in sd.items():3090 part = f'[{sdid}'3091 for k, v in dv.items():3092 s = str(v)3093 s = self.escaped.sub(replacer, s)3094 part += f' {k}="{s}"'3095 part += ']'3096 parts.append(part)3097 sdata = ''.join(parts)3098 return f'{version} {asctime} {hostname} {appname} {procid} {msgid} {sdata} {msg}'3099```31003101Чтобы полностью разобраться в приведённом коде, потребуется знакомство с RFC 5424. Возможно, ваши потребности будут несколько иными (например, в способе передачи структурированных данных в журнал). Тем не менее, приведённый код можно адаптировать под конкретные нужды. С таким обработчиком структурированные данные передаются, например, так:31023103```python3104sd = {3105 'foo@12345': {'bar': 'baz', 'baz': 'bozz', 'fizz': r'buzz'},3106 'foo@54321': {'rab': 'baz', 'zab': 'bozz', 'zzif': r'buzz'}3107}3108extra = {'structured_data': sd}3109i = 13110logger.debug('Message %d', i, extra=extra)3111```31123113## Как использовать объект Logger как выходной поток31143115Иногда возникает необходимость взаимодействовать со сторонним API, который ожидает объект, подобный файлу, для записи, но при этом нужно перенаправить вывод API в журнал. Это можно сделать с помощью класса, который оборачивает объект Logger, предоставляя файлоподобный интерфейс. Вот короткий скрипт, иллюстрирующий такой класс:31163117```python3118import logging31193120class LoggerWriter:3121 def __init__(self, logger, level):3122 self.logger = logger3123 self.level = level31243125 def write(self, message):3126 if message != '\n': # избегайте печати пустых строк, если хотите3127 self.logger.log(self.level, message)31283129 def flush(self):3130 # на самом деле ничего не делает, но может ожидаться от файлоподобного3131 # объекта – так что опционально в зависимости от вашей ситуации3132 pass31333134 def close(self):3135 # на самом деле ничего не делает, но может ожидаться от файлоподобного3136 # объекта – так что опционально в зависимости от вашей ситуации. Возможно, вы захотите3137 # установить флаг, чтобы последующие вызовы write вызывали исключение3138 pass31393140def main():3141 logging.basicConfig(level=logging.DEBUG)3142 logger = logging.getLogger('demo')3143 info_fp = LoggerWriter(logger, logging.INFO)3144 debug_fp = LoggerWriter(logger, logging.DEBUG)3145 print('An INFO message', file=info_fp)3146 print('A DEBUG message', file=debug_fp)31473148if __name__ == "__main__":3149 main()3150```31513152При запуске этот скрипт выводит31533154```text3155INFO:demo:An INFO message3156DEBUG:demo:A DEBUG message3157```31583159Можно также использовать `LoggerWriter` для перенаправления `sys.stdout` и `sys.stderr`, сделав примерно так:31603161```python3162import sys31633164sys.stdout = LoggerWriter(logger, logging.INFO)3165sys.stderr = LoggerWriter(logger, logging.WARNING)3166```31673168Это следует делать *после* настройки журналирования под свои нужды. В приведённом выше примере вызов [`basicConfig()`](https://python-all.ru/3.10/library/logging.html#logging.basicConfig) делает это (используя значение `sys.stderr` *до* того, как оно будет перезаписано экземпляром `LoggerWriter`). В результате получится примерно такой вывод:31693170```pycon3171>>> print('Foo')3172INFO:demo:Foo3173>>> print('Bar', file=sys.stderr)3174WARNING:demo:Bar3175>>>3176```31773178Конечно, приведённые выше примеры показывают вывод в формате, используемом [`basicConfig()`](https://python-all.ru/3.10/library/logging.html#logging.basicConfig), но вы можете использовать другой форматтер при настройке логирования.31793180Обратите внимание, что при такой схеме вы в значительной степени зависите от буферизации и порядка вызовов write, которые перехватываете. Например, при определении `LoggerWriter` выше, если есть такой фрагмент кода:31813182```python3183sys.stderr = LoggerWriter(logger, logging.WARNING)31841 / 03185```31863187то запуск скрипта даёт31883189```text3190WARNING:demo:Traceback (most recent call last):31913192WARNING:demo: File "/home/runner/cookbook-loggerwriter/test.py", line 53, in <module>31933194WARNING:demo:3195WARNING:demo:main()3196WARNING:demo: File "/home/runner/cookbook-loggerwriter/test.py", line 49, in main31973198WARNING:demo:3199WARNING:demo:1 / 03200WARNING:demo:ZeroDivisionError3201WARNING:demo::3202WARNING:demo:division by zero3203```32043205Как видно, такой вывод неидеален. Это происходит потому, что базовый код, который пишет в `sys.stderr`, выполняет несколько записей, каждая из которых приводит к отдельной строке лога (например, последние три строки выше). Чтобы обойти эту проблему, нужно буферизовать данные и выводить строки лога только при появлении символов новой строки. Давайте используем немного улучшенную реализацию `LoggerWriter`:32063207```python3208class BufferingLoggerWriter(LoggerWriter):3209 def __init__(self, logger, level):3210 super().__init__(logger, level)3211 self.buffer = ''32123213 def write(self, message):3214 if '\n' not in message:3215 self.buffer += message3216 else:3217 parts = message.split('\n')3218 if self.buffer:3219 s = self.buffer + parts.pop(0)3220 self.logger.log(self.level, s)3221 self.buffer = parts.pop()3222 for part in parts:3223 self.logger.log(self.level, part)3224```32253226Этот код просто буферизует данные до появления символа новой строки, после чего записывает полные строки. С таким подходом вывод становится лучше:32273228```text3229WARNING:demo:Traceback (most recent call last):3230WARNING:demo: File "/home/runner/cookbook-loggerwriter/main.py", line 55, in <module>3231WARNING:demo: main()3232WARNING:demo: File "/home/runner/cookbook-loggerwriter/main.py", line 52, in main3233WARNING:demo: 1/03234WARNING:demo:ZeroDivisionError: division by zero3235```32363237## Шаблоны, которых следует избегать32383239Хотя в предыдущих разделах были описаны способы решения задач, с которыми вы можете столкнуться, стоит упомянуть некоторые шаблоны использования, которые *бесполезны* и в большинстве случаев их следует избегать. Следующие разделы приведены в произвольном порядке.32403241### Многократное открытие одного и того же файла журнала32423243В Windows обычно не получится открыть один и тот же файл несколько раз, так как это приведёт к ошибке «файл используется другим процессом». Однако на платформах POSIX никаких ошибок при многократном открытии одного файла не возникнет. Это может произойти случайно, например:32443245- Добавление файлового обработчика более одного раза со ссылкой на один и тот же файл (например, из-за ошибки копирования/вставки/забыли изменить).3246- Открытие двух файлов, которые выглядят разными (у них разные имена), но на самом деле являются одним и тем же файлом, так как один – символическая ссылка на другой.3247- Порождение процесса (форк), после которого и родительский, и дочерний процесс имеют ссылку на один и тот же файл. Это может происходить, например, при использовании модуля [`multiprocessing`](https://python-all.ru/3.10/library/multiprocessing.html#module-multiprocessing).32483249Многократное открытие файла может *выглядеть* работающим большую часть времени, но на практике может привести к ряду проблем:32503251- Вывод логирования может искажаться, поскольку несколько потоков или процессов пытаются писать в один и тот же файл. Хотя логирование защищает от одновременного использования одного и того же экземпляра обработчика несколькими потоками, такой защиты нет, если одновременную запись пытаются выполнить два разных потока, использующие два разных экземпляра обработчика, которые указывают на один и тот же файл.3252- Попытка удалить файл (например, во время ротации) молча завершается неудачей, потому что есть другая ссылка на него. Это может привести к путанице и потере времени на отладку – записи журнала оказываются в неожиданных местах или полностью теряются. Или файл, который должен был быть перемещён, остаётся на месте и неожиданно растёт в размерах, несмотря на то что ротация по размеру якобы настроена.32533254Используйте методы, описанные в [Логирование в один файл из нескольких процессов](https://python-all.ru/3.10/howto/logging-cookbook.html#multiple-processes), чтобы обойти такие проблемы.32553256### Использование логгеров в качестве атрибутов класса или передача их в качестве параметров32573258Хотя могут быть необычные случаи, когда это необходимо, в целом в этом нет смысла, потому что логгеры – синглтоны. Код всегда может получить доступ к нужному экземпляру логгера по имени с помощью `logging.getLogger(name)`, поэтому передавать экземпляры повсюду и хранить их в качестве атрибутов экземпляра бессмысленно. Обратите внимание, что в других языках, таких как Java и C#, логгеры часто являются статическими атрибутами класса. Однако этот шаблон не имеет смысла в Python, где модуль (а не класс) является единицей декомпозиции программного обеспечения.32593260### Добавление обработчиков, отличных от `NullHandler`, к логгеру в библиотеке32613262Настройка логирования путём добавления обработчиков, форматировщиков и фильтров – это ответственность разработчика приложения, а не разработчика библиотеки. Если вы поддерживаете библиотеку, убедитесь, что не добавляете обработчики ни к одному из своих логгеров, кроме экземпляра [`NullHandler`](https://python-all.ru/3.10/library/logging.handlers.html#logging.NullHandler).32633264### Создание большого количества логгеров32653266Логгеры – это синглтоны, которые никогда не освобождаются во время выполнения скрипта, поэтому создание большого количества логгеров приведёт к расходу памяти, которую затем нельзя освободить. Вместо того чтобы создавать логгер для каждого обрабатываемого файла или сетевого соединения, используйте [существующие механизмы](https://python-all.ru/3.10/howto/logging-cookbook.html#context-info) для передачи контекстной информации в ваши журналы и ограничьте создаваемые логгеры теми, которые описывают области вашего приложения (обычно модули, но иногда и с чуть большей детализацией).32673268## Другие ресурсы32693270> **См. также**3271>3272> **Модуль [`logging`](https://python-all.ru/3.10/library/logging.html#module-logging)**3273>3274> Справочник API для модуля logging.3275>3276> **Модуль [`logging.config`](https://python-all.ru/3.10/library/logging.config.html#module-logging.config)**3277>3278> API конфигурации для модуля logging.3279>3280> **Модуль [`logging.handlers`](https://python-all.ru/3.10/library/logging.handlers.html#module-logging.handlers)**3281>3282> Полезные обработчики, входящие в состав модуля logging.3283>3284> [Базовое руководство](https://python-all.ru/3.10/howto/logging.html#logging-basic-tutorial)3285>3286> [Продвинутое руководство](https://python-all.ru/3.10/howto/logging.html#logging-advanced-tutorial)3287