logging-cookbook.md
1> **Источник:** https://python-all.ru/3.11/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.11/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.11/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.11/library/logging.handlers.html#logging.handlers.SMTPHandler): отправка электронной почты может занимать много времени по ряду причин, не зависящих от разработчика (например, из-за плохой работы почтовой или сетевой инфраструктуры). Но почти любой сетевой обработчик может блокировать: даже операция [`SocketHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.SocketHandler) может выполнять DNS-запрос «под капотом», который оказывается слишком медленным (и этот запрос может быть глубоко в коде библиотеки сокетов, ниже уровня Python и вне вашего контроля).504505Одно из решений – использовать двухчастный подход. На первом этапе к логгерам, к которым обращаются из критичных по производительности потоков, следует подключать только [`QueueHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.QueueHandler). Они просто пишут в свою очередь, которую можно настроить на достаточно большую ёмкость или инициализировать без верхнего ограничения размера. Запись в очередь обычно выполняется быстро, хотя в коде желательно перехватывать исключение [`queue.Full`](https://python-all.ru/3.11/library/queue.html#queue.Full) на всякий случай. Если вы – разработчик библиотеки, в коде которой есть критичные по производительности потоки, обязательно задокументируйте это (вместе с рекомендацией подключать к вашим логгерам только `QueueHandlers`) для пользы других разработчиков, которые будут использовать ваш код.506507Вторая часть решения – [`QueueListener`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.QueueListener), который был разработан как аналог [`QueueHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.QueueHandler). [`QueueListener`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.QueueListener) устроен очень просто: ему передаётся очередь и несколько обработчиков, и он запускает внутренний поток, который слушает свою очередь на предмет LogRecords, отправленных из `QueueHandlers` (или любого другого источника `LogRecords`). `LogRecords` извлекаются из очереди и передаются обработчикам для обработки.508509Преимущество отдельного класса [`QueueListener`](https://python-all.ru/3.11/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.11/library/asyncio.html#module-asyncio). Поэтому, если в приложении используется асинхронный код, лучше всего применять описанный выше подход к логированию, чтобы любой блокирующий код выполнялся только в `QueueListener` потоке.540541Изменено в версии 3.5: До Python 3.5 [`QueueListener`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.QueueListener) всегда передавал каждое полученное из очереди сообщение каждому обработчику, с которыми был инициализирован. (Это объяснялось тем, что предполагалось, что фильтрация по уровню полностью выполняется на стороне наполнения очереди.) Начиная с версии 3.5 это поведение можно изменить, передав именованный аргумент `respect_handler_level=True` конструктору слушателя. Когда это сделано, слушатель сравнивает уровень каждого сообщения с уровнем обработчика и передаёт сообщение обработчику, только если это уместно.542543## Отправка и получение событий логирования по сети544545Допустим, вы хотите отправлять события логирования по сети и обрабатывать их на принимающей стороне. Простой способ – подключить экземпляр [`SocketHandler`](https://python-all.ru/3.11/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.11/library/socketserver.html#module-socketserver). Вот простой работающий пример:574575```python576import pickle577import logging578import logging.handlers579import socketserver580import struct581582class LogRecordStreamHandler(socketserver.StreamRequestHandler):583 """Обработчик для потокового запроса логирования.584585 Это по сути записывает запись, используя ту политику логирования, которая настроена локально.586 настроено локально.587 """588589 def handle(self):590 """591 Обрабатывает несколько запросов – каждый ожидается в формате: 4-байтовая длина, затем запись журнала в формате пикл.592 Записывает запись в соответствии с политикой, настроенной локально.593 согласно локально настроенной политике.594 """595 while True:596 chunk = self.connection.recv(4)597 if len(chunk) < 4:598 break599 slen = struct.unpack('>L', chunk)[0]600 chunk = self.connection.recv(slen)601 while len(chunk) < slen:602 chunk = chunk + self.connection.recv(slen - len(chunk))603 obj = self.unPickle(chunk)604 record = logging.makeLogRecord(obj)605 self.handleLogRecord(record)606607 def unPickle(self, data):608 return pickle.loads(data)609610 def handleLogRecord(self, record):611 # Если указано имя, используется именованный логгер, а не тот, что612 # подразумевается записью.613 if self.server.logname is not None:614 name = self.server.logname615 else:616 name = record.name617 logger = logging.getLogger(name)618 # Примечание: КАЖДАЯ запись попадает в журнал. Это связано с тем, что Logger.handle619 # обычно вызывается ПОСЛЕ фильтрации на уровне регистратора. Если требуется620 # выполнять фильтрацию, делайте это на стороне клиента, чтобы не тратить621 # циклы процессора и сетевую пропускную способность!622 logger.handle(record)623624class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):625 """626 Простой приёмник журнала на основе TCP-сокетов, подходящий для тестирования.627 """628629 allow_reuse_address = True630631 def __init__(self, host='localhost',632 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,633 handler=LogRecordStreamHandler):634 socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)635 self.abort = 0636 self.timeout = 1637 self.logname = None638639 def serve_until_stopped(self):640 import select641 abort = 0642 while not abort:643 rd, wr, ex = select.select([self.socket.fileno()],644 [], [],645 self.timeout)646 if rd:647 self.handle_request()648 abort = self.abort649650def main():651 logging.basicConfig(652 format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')653 tcpserver = LogRecordSocketReceiver()654 print('About to start TCP server...')655 tcpserver.serve_until_stopped()656657if __name__ == '__main__':658 main()659```660661Сначала запустите сервер, затем клиент. На стороне клиента в консоль ничего не выводится; на стороне сервера вы должны увидеть что-то вроде:662663```text664About to start TCP server...665 59 root INFO Jackdaws love my big sphinx of quartz.666 59 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim.667 69 myapp.area1 INFO How quickly daft jumping zebras vex.668 69 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack.669 69 myapp.area2 ERROR The five boxing wizards jump quickly.670```671672Обратите внимание, что в некоторых сценариях существуют проблемы безопасности с pickle. Если они вас затрагивают, вы можете использовать альтернативную схему сериализации, переопределив метод [`makePickle()`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.SocketHandler.makePickle) и реализовав свою альтернативу там, а также адаптировав вышеприведённый скрипт для использования вашей альтернативной сериализации.673674### Запуск сокетного слушателя логирования в продакшене675676Для запуска слушателя логирования в продакшене может потребоваться инструмент управления процессами, такой как [Supervisor](https://python-all.ru/3.11/howto/logging-cookbook.html). [Вот Gist](https://python-all.ru/3.11/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.11/howto/logging-cookbook.html) – популярный сервер веб-приложений, который запускает несколько рабочих процессов для обработки запросов. Данный пример показывает, как рабочие процессы могут писать в один и тот же файл журнала, не мешая друг другу – все они проходят через сокетный слушатель.689690Чтобы протестировать эти файлы, выполните следующие действия в среде POSIX:6916921. Скачайте [Gist](https://python-all.ru/3.11/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`](https://python-all.ru/3.11/library/logging.html#logging.Logger) для каждого соединения, но это плохая идея, поскольку такие экземпляры не собираются сборщиком мусора. Хотя на практике это не проблема, когда количество экземпляров [`Logger`](https://python-all.ru/3.11/library/logging.html#logging.Logger) зависит от уровня детализации, используемого при логировании приложения, управление ими может стать сложным, если количество экземпляров [`Logger`](https://python-all.ru/3.11/library/logging.html#logging.Logger) станет фактически неограниченным.705706### Использование LoggerAdapter для добавления контекстной информации707708Простой способ передавать контекстную информацию для вывода вместе с информацией о событиях логирования – использовать класс [`LoggerAdapter`](https://python-all.ru/3.11/library/logging.html#logging.LoggerAdapter). Этот класс спроектирован так, чтобы выглядеть как [`Logger`](https://python-all.ru/3.11/library/logging.html#logging.Logger), что позволяет вызывать [`debug()`](https://python-all.ru/3.11/library/logging.html#logging.debug), [`info()`](https://python-all.ru/3.11/library/logging.html#logging.info), [`warning()`](https://python-all.ru/3.11/library/logging.html#logging.warning), [`error()`](https://python-all.ru/3.11/library/logging.html#logging.error), [`exception()`](https://python-all.ru/3.11/library/logging.html#logging.exception), [`critical()`](https://python-all.ru/3.11/library/logging.html#logging.critical) и [`log()`](https://python-all.ru/3.11/library/logging.html#logging.log). Эти методы имеют те же сигнатуры, что и их аналоги в [`Logger`](https://python-all.ru/3.11/library/logging.html#logging.Logger), поэтому экземпляры обоих типов можно использовать взаимозаменяемо.709710При создании экземпляра [`LoggerAdapter`](https://python-all.ru/3.11/library/logging.html#logging.LoggerAdapter) вы передаёте ему экземпляр [`Logger`](https://python-all.ru/3.11/library/logging.html#logging.Logger) и объект, подобный словарю, содержащий вашу контекстную информацию. Когда вы вызываете один из методов логирования на экземпляре [`LoggerAdapter`](https://python-all.ru/3.11/library/logging.html#logging.LoggerAdapter), он делегирует вызов базовому экземпляру [`Logger`](https://python-all.ru/3.11/library/logging.html#logging.Logger), переданному в конструктор, и организует передачу контекстной информации в этом делегированном вызове. Вот фрагмент кода [`LoggerAdapter`](https://python-all.ru/3.11/library/logging.html#logging.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()`](https://python-all.ru/3.11/library/logging.html#logging.LoggerAdapter.process) класса [`LoggerAdapter`](https://python-all.ru/3.11/library/logging.html#logging.LoggerAdapter) – это то место, где контекстная информация добавляется в вывод журнала. Ему передаются сообщение и именованные аргументы вызова логирования, а он возвращает (потенциально) изменённые версии для использования в вызове базового регистратора. В реализации по умолчанию этот метод оставляет сообщение без изменений, но вставляет ключ 'extra' в именованные аргументы, значением которого является объект, подобный словарю, переданный конструктору. Конечно, если вы передали именованный аргумент 'extra' в вызове адаптера, он будет молча перезаписан.723724Преимущество использования 'extra' в том, что значения из объекта, подобного словарю, сливаются в \_\_dict\_\_ экземпляра [`LogRecord`](https://python-all.ru/3.11/library/logging.html#logging.LogRecord), что позволяет использовать настроенные строки с экземплярами [`Formatter`](https://python-all.ru/3.11/library/logging.html#logging.Formatter), которые знают о ключах этого объекта. Если вам нужен другой метод, например, добавить контекстную информацию в начало или конец строки сообщения, достаточно создать подкласс [`LoggerAdapter`](https://python-all.ru/3.11/library/logging.html#logging.LoggerAdapter) и переопределить [`process()`](https://python-all.ru/3.11/library/logging.html#logging.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`](https://python-all.ru/3.11/library/logging.html#logging.LoggerAdapter) именно словарь – можно передать экземпляр класса, реализующего `__getitem__` и `__iter__`, чтобы он выглядел как словарь для системы логирования. Это полезно, если нужно генерировать значения динамически (тогда как значения в словаре были бы постоянными).748749### Использование фильтров для добавления контекстной информации750751Вы также можете добавлять контекстную информацию в вывод журнала с помощью определённого пользователем [`Filter`](https://python-all.ru/3.11/library/logging.html#logging.Filter). Экземплярам `Filter` разрешено изменять `LogRecords`, переданный им, включая добавление дополнительных атрибутов, которые затем можно выводить с помощью подходящей форматной строки или, если необходимо, пользовательского [`Formatter`](https://python-all.ru/3.11/library/logging.html#logging.Formatter).752753Например, в веб-приложении обрабатываемый запрос (или, по крайней мере, его интересные части) можно сохранить в потоковой локальной переменной ([`threading.local`](https://python-all.ru/3.11/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.11/library/contextvars.html#module-contextvars) предоставляет контекстно-локальное хранилище, которое работает как для [`threading`](https://python-all.ru/3.11/library/threading.html#module-threading), так и для [`asyncio`](https://python-all.ru/3.11/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`](https://python-all.ru/3.11/library/logging.html#logging.Handler) имеет собственную цепочку фильтров. Если нужно добавить контекстную информацию в [`LogRecord`](https://python-all.ru/3.11/library/logging.html#logging.LogRecord) без её утечки в другие обработчики, можно использовать фильтр, возвращающий новый [`LogRecord`](https://python-all.ru/3.11/library/logging.html#logging.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.11/library/logging.handlers.html#logging.handlers.SocketHandler), а отдельный процесс реализовывал сокет-сервер, который читает из сокета и записывает в файл. (Если хотите, можно выделить один поток в одном из существующих процессов для выполнения этой функции.) [В этом разделе](https://python-all.ru/3.11/howto/logging-cookbook.html#network-logging) подробно описывается данный подход и приводится рабочий приёмник сокета, который можно использовать как отправную точку для адаптации в своих приложениях.10431044Вы также можете написать собственный обработчик, который использует класс [`Lock`](https://python-all.ru/3.11/library/multiprocessing.html#multiprocessing.Lock) из модуля [`multiprocessing`](https://python-all.ru/3.11/library/multiprocessing.html#module-multiprocessing) для сериализации доступа к файлу из ваших процессов. Существующие [`FileHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.FileHandler) и подклассы в настоящее время не используют [`multiprocessing`](https://python-all.ru/3.11/library/multiprocessing.html#module-multiprocessing), хотя в будущем они могут это сделать. Обратите внимание, что в настоящее время модуль [`multiprocessing`](https://python-all.ru/3.11/library/multiprocessing.html#module-multiprocessing) не обеспечивает рабочую функциональность блокировки на всех платформах (см. [https://bugs.python.org/issue3770](https://python-all.ru/3.11/howto/logging-cookbook.html)).10451046В качестве альтернативы можно использовать `Queue` и [`QueueHandler`](https://python-all.ru/3.11/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.11/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.11/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.11/howto/logging-cookbook.html) или [uWSGI](https://python-all.ru/3.11/howto/logging-cookbook.html) (или аналогичных) создается несколько рабочих процессов для обработки клиентских запросов. В таких средах избегайте создания обработчиков, основанных на файлах, непосредственно в вашем веб-приложении. Вместо этого используйте [`SocketHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.SocketHandler) для логирования из веб-приложения в слушатель в отдельном процессе. Это можно настроить с помощью инструмента управления процессами, такого как Supervisor – см. [Запуск слушателя сокета логирования в производственной среде](https://python-all.ru/3.11/howto/logging-cookbook.html#running-a-logging-socket-listener-in-production) для получения дополнительной информации.12901291## Использование ротации файлов12921293Иногда требуется позволить файлу журнала расти до определённого размера, затем открыть новый файл и вести запись в него. Может потребоваться сохранять определённое количество таких файлов, и когда будет создано заданное число файлов, выполнять ротацию, чтобы и количество, и размер файлов оставались в заданных границах. Для такого сценария использования пакет logging предоставляет [`RotatingFileHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.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.11/library/string.html#string.Template) (добавлен в Python 2.4) и [`str.format()`](https://python-all.ru/3.11/library/stdtypes.html#str.format) (добавлен в Python 2.6).13411342Начиная с версии 3.2, модуль logging предоставляет улучшенную поддержку этих двух дополнительных стилей форматирования. Класс [`Formatter`](https://python-all.ru/3.11/library/logging.html#logging.Formatter) был расширен: добавлен дополнительный необязательный именованный параметр `style`. По умолчанию он равен `'%'`, но возможны также значения `'{'` и `'$'`, соответствующие двум другим стилям форматирования. Обратная совместимость сохраняется по умолчанию (как и следовало ожидать), но при явном указании параметра style появляется возможность задавать строки формата, работающие с [`str.format()`](https://python-all.ru/3.11/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.11/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.11/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.11/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.11/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`](https://python-all.ru/3.11/library/logging.html#logging.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 log(self, level, msg, /, *args, stacklevel=1, **kwargs):1441 if self.isEnabledFor(level):1442 msg, kwargs = self.process(msg, kwargs)1443 self.logger.log(level, Message(msg, args), **kwargs,1444 stacklevel=stacklevel+1)14451446logger = StyleAdapter(logging.getLogger(__name__))14471448def main():1449 logger.debug('Hello, {}', 'world!')14501451if __name__ == '__main__':1452 logging.basicConfig(level=logging.DEBUG)1453 main()1454```14551456Приведённый выше сценарий должен записать в журнал сообщение `Hello, world!` при запуске с Python 3.8 или новее.14571458## Настройка `LogRecord`14591460Каждое событие журналирования представлено экземпляром [`LogRecord`](https://python-all.ru/3.11/library/logging.html#logging.LogRecord). Когда событие регистрируется и не отфильтровывается по уровню регистратора, создаётся [`LogRecord`](https://python-all.ru/3.11/library/logging.html#logging.LogRecord), заполняется информацией о событии и затем передаётся обработчикам для этого регистратора (и его предков, вплоть до регистратора, в котором дальнейшее распространение по иерархии отключено). До Python 3.2 было только два места, где выполнялось это создание:14611462- [`Logger.makeRecord()`](https://python-all.ru/3.11/library/logging.html#logging.Logger.makeRecord), который вызывается в обычном процессе регистрации события. Он напрямую вызывал [`LogRecord`](https://python-all.ru/3.11/library/logging.html#logging.LogRecord) для создания экземпляра.1463- [`makeLogRecord()`](https://python-all.ru/3.11/library/logging.html#logging.makeLogRecord), которая вызывается со словарем, содержащим атрибуты для добавления в LogRecord. Обычно она вызывается, когда подходящий словарь был получен по сети (например, в виде pickle через [`SocketHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.SocketHandler) или в формате JSON через [`HTTPHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.HTTPHandler)).14641465Обычно это означало, что если требуется выполнить какие-либо специальные действия с [`LogRecord`](https://python-all.ru/3.11/library/logging.html#logging.LogRecord), приходилось делать одно из следующего.14661467- Создать собственный подкласс [`Logger`](https://python-all.ru/3.11/library/logging.html#logging.Logger), который переопределяет [`Logger.makeRecord()`](https://python-all.ru/3.11/library/logging.html#logging.Logger.makeRecord), и установить его с помощью [`setLoggerClass()`](https://python-all.ru/3.11/library/logging.html#logging.setLoggerClass) до того, как будут созданы какие-либо логгеры, которые вас интересуют.1468- Добавить [`Filter`](https://python-all.ru/3.11/library/logging.html#logging.Filter) к логгеру или обработчику, который выполняет необходимые специальные манипуляции при вызове его метода [`filter()`](https://python-all.ru/3.11/library/logging.html#logging.Filter.filter).14691470Первый подход был бы несколько громоздким в сценарии, где (скажем) несколько разных библиотек хотели бы делать разные вещи. Каждая попыталась бы установить свой собственный подкласс [`Logger`](https://python-all.ru/3.11/library/logging.html#logging.Logger), и та, которая сделала это последней, победила бы.14711472Второй подход достаточно хорошо работает во многих случаях, но не позволяет, например, использовать специализированный подкласс [`LogRecord`](https://python-all.ru/3.11/library/logging.html#logging.LogRecord). Разработчики библиотек могут установить подходящий фильтр на своих логгерах, но им приходилось бы помнить об этом каждый раз, когда они добавляют новый логгер (что они делают, просто добавляя новые пакеты или модули и выполняя14731474```python1475logger = logging.getLogger(__name__)1476```14771478на уровне модуля). Вероятно, это одна из тех вещей, о которых нужно помнить. Разработчики также могли бы добавить фильтр к [`NullHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.NullHandler), прикрепленному к их корневому логгеру, но он не будет вызываться, если разработчик приложения прикрепит обработчик к логгеру библиотеки нижнего уровня – так что вывод от этого обработчика не будет отражать намерений разработчика библиотеки.14791480В Python 3.2 и новее создание [`LogRecord`](https://python-all.ru/3.11/library/logging.html#logging.LogRecord) осуществляется через фабрику, которую можно указать. Фабрика – это просто вызываемый объект, который можно установить с помощью [`setLogRecordFactory()`](https://python-all.ru/3.11/library/logging.html#logging.setLogRecordFactory) и запросить с помощью [`getLogRecordFactory()`](https://python-all.ru/3.11/library/logging.html#logging.getLogRecordFactory). Фабрика вызывается с той же сигнатурой, что и конструктор [`LogRecord`](https://python-all.ru/3.11/library/logging.html#logging.LogRecord), поскольку [`LogRecord`](https://python-all.ru/3.11/library/logging.html#logging.LogRecord) является значением по умолчанию для фабрики.14811482Этот подход позволяет пользовательской фабрике контролировать все аспекты создания LogRecord. Например, можно вернуть подкласс или просто добавить несколько дополнительных атрибутов к записи после ее создания, используя шаблон, подобный следующему:14831484```python1485old_factory = logging.getLogRecordFactory()14861487def record_factory(*args, **kwargs):1488 record = old_factory(*args, **kwargs)1489 record.custom_attribute = 0xdecafbad1490 return record14911492logging.setLogRecordFactory(record_factory)1493```14941495Этот шаблон позволяет разным библиотекам объединять фабрики в цепочку, и пока они не перезаписывают атрибуты друг друга или случайно не перезаписывают стандартные атрибуты, никаких сюрпризов быть не должно. Однако следует иметь в виду, что каждое звено цепочки добавляет накладные расходы во время выполнения ко всем операциям логирования, и эту технику следует использовать только тогда, когда использование [`Filter`](https://python-all.ru/3.11/library/logging.html#logging.Filter) не дает желаемого результата.14961497## Создание подклассов QueueHandler и QueueListener – пример с ZeroMQ14981499### Подкласс `QueueHandler`15001501Можно использовать подкласс [`QueueHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.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`15361537Можно также создать подкласс [`QueueListener`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.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## Создание подклассов QueueHandler и QueueListener – пример с `pynng`15541555Подобно предыдущему разделу, можно реализовать слушатель и обработчик с помощью [pynng](https://python-all.ru/3.11/howto/logging-cookbook.html), Python-привязки к [NNG](https://python-all.ru/3.11/howto/logging-cookbook.html), позиционируемого как духовный преемник ZeroMQ. Следующие фрагменты демонстрируют – их можно опробовать в окружении, где установлен `pynng`. Для разнообразия сперва представим слушатель.15561557### Подкласс `QueueListener`15581559```python1560import json1561import logging1562import logging.handlers15631564import pynng15651566DEFAULT_ADDR = "tcp://localhost:13232"15671568interrupted = False15691570class NNGSocketListener(logging.handlers.QueueListener):15711572 def __init__(self, uri, /, *handlers, **kwargs):1573 # Установить тайм-аут для возможности прерывания и открыть1574 # сокет подписчика1575 socket = pynng.Sub0(listen=uri, recv_timeout=500)1576 # Подписка b'' соответствует всем темам1577 topics = kwargs.pop('topics', None) or b''1578 socket.subscribe(topics)1579 # Используем сокет как очередь1580 super().__init__(socket, *handlers, **kwargs)15811582 def dequeue(self, block):1583 data = None1584 # Продолжать цикл, пока не прерван и не получены данные через1585 # сокет1586 while not interrupted:1587 try:1588 data = self.queue.recv(block=block)1589 break1590 except pynng.Timeout:1591 pass1592 except pynng.Closed: # иногда срабатывает при нажатии Ctrl-C1593 break1594 if data is None:1595 return None1596 # Получить событие журнала, отправленное издателем1597 event = json.loads(data.decode('utf-8'))1598 return logging.makeLogRecord(event)15991600 def enqueue_sentinel(self):1601 # Не используется в этой реализации, так как сокет на самом деле не является1602 # очередь1603 pass16041605logging.getLogger('pynng').propagate = False1606listener = NNGSocketListener(DEFAULT_ADDR, logging.StreamHandler(), topics=b'')1607listener.start()1608print('Press Ctrl-C to stop.')1609try:1610 while True:1611 pass1612except KeyboardInterrupt:1613 interrupted = True1614finally:1615 listener.stop()1616```16171618### Подкласс `QueueHandler`16191620```python1621import json1622import logging1623import logging.handlers1624import time1625import random16261627import pynng16281629DEFAULT_ADDR = "tcp://localhost:13232"16301631class NNGSocketHandler(logging.handlers.QueueHandler):16321633 def __init__(self, uri):1634 socket = pynng.Pub0(dial=uri, send_timeout=500)1635 super().__init__(socket)16361637 def enqueue(self, record):1638 # Отправить запись в виде JSON с кодировкой UTF-81639 d = dict(record.__dict__)1640 data = json.dumps(d)1641 self.queue.send(data.encode('utf-8'))16421643 def close(self):1644 self.queue.close()16451646logging.getLogger('pynng').propagate = False1647handler = NNGSocketHandler(DEFAULT_ADDR)1648logging.basicConfig(level=logging.DEBUG,1649 handlers=[logging.StreamHandler(), handler],1650 format='%(levelname)-8s %(name)10s %(message)s')1651levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1652 logging.CRITICAL)1653logger_names = ('myapp', 'myapp.lib1', 'myapp.lib2')1654msgno = 11655while True:1656 # Просто случайным образом выбирать несколько регистраторов и уровней и вести запись1657 level = random.choice(levels)1658 logger = logging.getLogger(random.choice(logger_names))1659 logger.log(level, 'Message no. %5d' % msgno)1660 msgno += 11661 delay = random.random() * 2 + 0.51662 time.sleep(delay)1663```16641665Два вышеупомянутых фрагмента можно запустить в отдельных командных оболочках.16661667## Пример конфигурации на основе словаря16681669Ниже приведен пример словаря конфигурации логирования – он взят из [документации проекта Django](https://python-all.ru/3.11/howto/logging-cookbook.html). Этот словарь передается в [`dictConfig()`](https://python-all.ru/3.11/library/logging.config.html#logging.config.dictConfig) для применения конфигурации:16701671```python1672LOGGING = {1673 'version': 1,1674 'disable_existing_loggers': False,1675 'formatters': {1676 'verbose': {1677 'format': '{levelname} {asctime} {module} {process:d} {thread:d} {message}',1678 'style': '{',1679 },1680 'simple': {1681 'format': '{levelname} {message}',1682 'style': '{',1683 },1684 },1685 'filters': {1686 'special': {1687 '()': 'project.logging.SpecialFilter',1688 'foo': 'bar',1689 },1690 },1691 'handlers': {1692 'console': {1693 'level': 'INFO',1694 'class': 'logging.StreamHandler',1695 'formatter': 'simple',1696 },1697 'mail_admins': {1698 'level': 'ERROR',1699 'class': 'django.utils.log.AdminEmailHandler',1700 'filters': ['special']1701 }1702 },1703 'loggers': {1704 'django': {1705 'handlers': ['console'],1706 'propagate': True,1707 },1708 'django.request': {1709 'handlers': ['mail_admins'],1710 'level': 'ERROR',1711 'propagate': False,1712 },1713 'myproject.custom': {1714 'handlers': ['console', 'mail_admins'],1715 'level': 'INFO',1716 'filters': ['special']1717 }1718 }1719}1720```17211722Для получения дополнительной информации об этой конфигурации можно обратиться к [соответствующему разделу](https://python-all.ru/3.11/howto/logging-cookbook.html) документации Django.17231724## Использование ротатора и средства именования для настройки обработки ротации журналов17251726Пример того, как можно определить именователя и ротатора, приведен в следующем исполняемом скрипте, который показывает сжатие gzip файла журнала:17271728```python1729import gzip1730import logging1731import logging.handlers1732import os1733import shutil17341735def namer(name):1736 return name + ".gz"17371738def rotator(source, dest):1739 with open(source, 'rb') as f_in:1740 with gzip.open(dest, 'wb') as f_out:1741 shutil.copyfileobj(f_in, f_out)1742 os.remove(source)17431744rh = logging.handlers.RotatingFileHandler('rotated.log', maxBytes=128, backupCount=5)1745rh.rotator = rotator1746rh.namer = namer17471748root = logging.getLogger()1749root.setLevel(logging.INFO)1750root.addHandler(rh)1751f = logging.Formatter('%(asctime)s %(message)s')1752rh.setFormatter(f)1753for i in range(1000):1754 root.info(f'Message no. {i + 1}')1755```17561757После запуска будут созданы шесть новых файлов, пять из которых сжаты:17581759```console1760$ ls rotated.log*1761rotated.log rotated.log.2.gz rotated.log.4.gz1762rotated.log.1.gz rotated.log.3.gz rotated.log.5.gz1763$ zcat rotated.log.1.gz17642023-01-20 02:28:17,767 Message no. 99617652023-01-20 02:28:17,767 Message no. 99717662023-01-20 02:28:17,767 Message no. 9981767```17681769## Более сложный пример с многопроцессностью17701771Следующий рабочий пример показывает, как можно использовать логирование с многопроцессностью с помощью файлов конфигурации. Конфигурации довольно просты, но служат иллюстрацией того, как можно реализовать более сложные в реальном сценарии многопроцессной обработки.17721773В примере главный процесс порождает процесс-слушатель и несколько рабочих процессов. Каждый из главного процесса, слушателя и рабочих имеет три отдельные конфигурации (все рабочие используют одну и ту же конфигурацию). Видно ведение журнала в главном процессе, как рабочие пишут в QueueHandler, а слушатель реализует QueueListener и более сложную конфигурацию ведения журнала, и организует отправку событий, полученных через очередь, обработчикам, указанным в конфигурации. Обратите внимание, что эти конфигурации чисто иллюстративные, но этот пример можно адаптировать под свой сценарий.17741775Вот скрипт – строки документации и комментарии, надеюсь, поясняют, как он работает:17761777```python1778import logging1779import logging.config1780import logging.handlers1781from multiprocessing import Process, Queue, Event, current_process1782import os1783import random1784import time17851786class MyHandler:1787 """1788 Простой обработчик для событий логирования. Он выполняется в процессе-слушателе и1789 распределяет события по логгерам на основе имени в полученной записи,1790 которые затем передаются системой логирования обработчикам,1791 настроенным для этих логгеров.1792 """17931794 def handle(self, record):1795 if record.name == "root":1796 logger = logging.getLogger()1797 else:1798 logger = logging.getLogger(record.name)17991800 if logger.isEnabledFor(record.levelno):1801 # Имя процесса преобразуется только для того, чтобы показать, что это слушатель1802 # выполняет логирование в файлы и консоль.1803 record.processName = '%s (for %s)' % (current_process().name, record.processName)1804 logger.handle(record)18051806def listener_process(q, stop_event, config):1807 """1808 Это можно было бы сделать в главном процессе, но сделано в отдельном1809 процессе для наглядности.18101811 Это инициализирует логирование согласно указанной конфигурации1812 запускает слушатель и ожидает сигнала от главного процесса о завершении1813 через событие. Затем слушатель останавливается, и процесс завершается.1814 """1815 logging.config.dictConfig(config)1816 listener = logging.handlers.QueueListener(q, MyHandler())1817 listener.start()1818 if os.name == 'posix':1819 # В POSIX логгер setup уже был настроен в1820 # родительском процессе, но должен был быть отключён после вызова1821 # dictConfig.1822 # В Windows, поскольку fork не используется, логгер setup не будет1823 # существовать в дочернем процессе, поэтому он будет создан, и сообщение1824 # появится – отсюда и конструкция "if posix".1825 logger = logging.getLogger('setup')1826 logger.critical('Should not appear, because of disabled logger ...')1827 stop_event.wait()1828 listener.stop()18291830def worker_process(config):1831 """1832 Некоторое количество таких процессов порождается для иллюстрации. На1833 практике это могла бы быть разнородная группа процессов, а не1834 идентичные друг другу.18351836 Это инициализирует логирование согласно указанной конфигурации1837 и записывает сотню сообщений со случайными уровнями в случайно выбранные1838 логгеры.18391840 Добавлена небольшая задержка, чтобы дать другим процессам шанс выполниться. Это1841 не является строго необходимым, но позволяет немного перемешать вывод от разных1842 процессов больше, чем если бы её не было.1843 """1844 logging.config.dictConfig(config)1845 levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1846 logging.CRITICAL]1847 loggers = ['foo', 'foo.bar', 'foo.bar.baz',1848 'spam', 'spam.ham', 'spam.ham.eggs']1849 if os.name == 'posix':1850 # В POSIX логгер setup уже был настроен в1851 # родительском процессе, но должен был быть отключён после вызова1852 # dictConfig.1853 # В Windows, поскольку fork не используется, логгер setup не будет1854 # существовать в дочернем процессе, поэтому он будет создан, и сообщение1855 # появится – отсюда и конструкция "if posix".1856 logger = logging.getLogger('setup')1857 logger.critical('Should not appear, because of disabled logger ...')1858 for i in range(100):1859 lvl = random.choice(levels)1860 logger = logging.getLogger(random.choice(loggers))1861 logger.log(lvl, 'Message no. %d', i)1862 time.sleep(0.01)18631864def main():1865 q = Queue()1866 # Главный процесс получает простую конфигурацию, которая выводит информацию в консоль.1867 config_initial = {1868 'version': 1,1869 'handlers': {1870 'console': {1871 'class': 'logging.StreamHandler',1872 'level': 'INFO'1873 }1874 },1875 'root': {1876 'handlers': ['console'],1877 'level': 'DEBUG'1878 }1879 }1880 # Конфигурация рабочего процесса представляет собой QueueHandler, прикреплённый к1881 # корневому логгеру, что позволяет отправлять все сообщения в очередь.1882 # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1883 # родительском процессе. Это необходимо в POSIX, потому что логгер будет1884 # присутствовать в дочернем процессе после вызова fork().1885 config_worker = {1886 'version': 1,1887 'disable_existing_loggers': True,1888 'handlers': {1889 'queue': {1890 'class': 'logging.handlers.QueueHandler',1891 'queue': q1892 }1893 },1894 'root': {1895 'handlers': ['queue'],1896 'level': 'DEBUG'1897 }1898 }1899 # Конфигурация процесса-слушателя показывает, что вся гибкость1900 # конфигурации логирования доступна для отправки событий обработчикам так, как1901 # требуется.1902 # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1903 # родительском процессе. Это необходимо в POSIX, потому что логгер будет1904 # присутствовать в дочернем процессе после вызова fork().1905 config_listener = {1906 'version': 1,1907 'disable_existing_loggers': True,1908 'formatters': {1909 'detailed': {1910 'class': 'logging.Formatter',1911 'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1912 },1913 'simple': {1914 'class': 'logging.Formatter',1915 'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1916 }1917 },1918 'handlers': {1919 'console': {1920 'class': 'logging.StreamHandler',1921 'formatter': 'simple',1922 'level': 'INFO'1923 },1924 'file': {1925 'class': 'logging.FileHandler',1926 'filename': 'mplog.log',1927 'mode': 'w',1928 'formatter': 'detailed'1929 },1930 'foofile': {1931 'class': 'logging.FileHandler',1932 'filename': 'mplog-foo.log',1933 'mode': 'w',1934 'formatter': 'detailed'1935 },1936 'errors': {1937 'class': 'logging.FileHandler',1938 'filename': 'mplog-errors.log',1939 'mode': 'w',1940 'formatter': 'detailed',1941 'level': 'ERROR'1942 }1943 },1944 'loggers': {1945 'foo': {1946 'handlers': ['foofile']1947 }1948 },1949 'root': {1950 'handlers': ['console', 'file', 'errors'],1951 'level': 'DEBUG'1952 }1953 }1954 # Записываем несколько начальных событий, просто чтобы показать, что логирование в родительском процессе работает1955 # нормально.1956 logging.config.dictConfig(config_initial)1957 logger = logging.getLogger('setup')1958 logger.info('About to create workers ...')1959 workers = []1960 for i in range(5):1961 wp = Process(target=worker_process, name='worker %d' % (i + 1),1962 args=(config_worker,))1963 workers.append(wp)1964 wp.start()1965 logger.info('Started worker: %s', wp.name)1966 logger.info('About to create listener ...')1967 stop_event = Event()1968 lp = Process(target=listener_process, name='listener',1969 args=(q, stop_event, config_listener))1970 lp.start()1971 logger.info('Started listener')1972 # Теперь ожидаем завершения работы рабочих процессов.1973 for wp in workers:1974 wp.join()1975 # Все рабочие процессы завершены, теперь можно остановить прослушивание.1976 # Логирование в родительском процессе всё ещё работает нормально.1977 logger.info('Telling listener to stop ...')1978 stop_event.set()1979 lp.join()1980 logger.info('All done.')19811982if __name__ == '__main__':1983 main()1984```19851986## Вставка BOM в сообщения, отправляемые в SysLogHandler19871988[**RFC 5424**](https://python-all.ru/3.11/howto/logging-cookbook.html) требует, чтобы сообщение Unicode отправлялось демону syslog в виде набора байтов, имеющего следующую структуру: необязательный чисто ASCII-компонент, за которым следует метка порядка байтов UTF-8 (BOM), а затем Unicode, закодированный в UTF-8. (См. [**соответствующий раздел спецификации**](https://python-all.ru/3.11/howto/logging-cookbook.html).)19891990В Python 3.1 в [`SysLogHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.SysLogHandler) был добавлен код для вставки BOM в сообщение, но, к сожалению, он был реализован некорректно: BOM появлялся в начале сообщения и, следовательно, не допускал наличия чисто ASCII-компонента перед ним.19911992Поскольку такое поведение ошибочно, некорректный код вставки BOM удаляется из Python 3.2.4 и более поздних версий. Однако он не заменяется, и если требуется создавать сообщения, соответствующие [**RFC 5424**](https://python-all.ru/3.11/howto/logging-cookbook.html), которые включают BOM, необязательную чисто ASCII-последовательность перед ним и произвольный Unicode после него, закодированный в UTF-8, то необходимо сделать следующее:199319941. Необходимо присоединить экземпляр [`Formatter`](https://python-all.ru/3.11/library/logging.html#logging.Formatter) к экземпляру [`SysLogHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.SysLogHandler), указав строку формата, например:19951996 ```python1997 'ASCII section\ufeffUnicode section'1998 ```19992000 Кодовая точка Unicode U+FEFF при кодировании в UTF-8 будет представлена как метка порядка байтов UTF-8 – строка байтов `b'\xef\xbb\xbf'`.20012. ASCII-часть следует заменить на любые подходящие заполнители, но необходимо следить, чтобы данные, которые появляются там после подстановки, всегда были в ASCII (таким образом, они останутся без изменений после кодирования UTF-8).20023. Unicode-часть следует заменить на любые заполнители; если данные после подстановки содержат символы за пределами диапазона ASCII, это нормально – они будут закодированы в UTF-8.20032004Отформатированное сообщение *будет* закодировано в UTF-8 с помощью `SysLogHandler`. Если следовать приведённым выше правилам, можно создавать сообщения, соответствующие [**RFC 5424**](https://python-all.ru/3.11/howto/logging-cookbook.html). Если этого не делать, модуль logging может не жаловаться, но сообщения не будут соответствовать RFC 5424, и демон syslog может выражать недовольство.20052006## Реализация структурированного ведения журнала20072008Хотя большинство сообщений журнала предназначены для чтения человеком и поэтому не предназначены для машинного разбора, могут возникнуть ситуации, когда требуется выводить сообщения в структурированном формате, *который* может быть разобран программой (без необходимости в сложных регулярных выражениях). Это легко достигается с помощью пакета logging. Существует несколько способов, но ниже приведён простой подход, использующий JSON для сериализации события в машиночитаемом виде.20092010```python2011import json2012import logging20132014class StructuredMessage:2015 def __init__(self, message, /, **kwargs):2016 self.message = message2017 self.kwargs = kwargs20182019 def __str__(self):2020 return '%s >>> %s' % (self.message, json.dumps(self.kwargs))20212022_ = StructuredMessage # необязательно, для улучшения читаемости20232024logging.basicConfig(level=logging.INFO, format='%(message)s')2025logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))2026```20272028Если запустить приведённый выше скрипт, он выведет:20292030```text2031message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}2032```20332034Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.20352036Если требуется более специализированная обработка, можно использовать пользовательский кодировщик JSON, как в следующем полном примере:20372038```python2039import json2040import logging20412042class Encoder(json.JSONEncoder):2043 def default(self, o):2044 if isinstance(o, set):2045 return tuple(o)2046 elif isinstance(o, str):2047 return o.encode('unicode_escape').decode('ascii')2048 return super().default(o)20492050class StructuredMessage:2051 def __init__(self, message, /, **kwargs):2052 self.message = message2053 self.kwargs = kwargs20542055 def __str__(self):2056 s = Encoder().encode(self.kwargs)2057 return '%s >>> %s' % (self.message, s)20582059_ = StructuredMessage # необязательно, для улучшения читаемости20602061def main():2062 logging.basicConfig(level=logging.INFO, format='%(message)s')2063 logging.info(_('message 1', set_value={1, 2, 3}, snowman='\u2603'))20642065if __name__ == '__main__':2066 main()2067```20682069При запуске приведённого выше скрипта он выведет:20702071```text2072message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}2073```20742075Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.20762077## Настройка обработчиков с помощью [`dictConfig()`](https://python-all.ru/3.11/library/logging.config.html#logging.config.dictConfig)20782079Иногда требуется настроить обработчики логирования особым образом, и при использовании [`dictConfig()`](https://python-all.ru/3.11/library/logging.config.html#logging.config.dictConfig) это можно сделать без создания подклассов. Например, может потребоваться установить владельца файла журнала. В POSIX это легко сделать с помощью [`shutil.chown()`](https://python-all.ru/3.11/library/shutil.html#shutil.chown), но файловые обработчики в стандартной библиотеке не предоставляют встроенной поддержки. Можно настроить создание обработчика с помощью обычной функции, такой как:20802081```python2082def owned_file_handler(filename, mode='a', encoding=None, owner=None):2083 if owner:2084 if not os.path.exists(filename):2085 open(filename, 'a').close()2086 shutil.chown(filename, *owner)2087 return logging.FileHandler(filename, mode, encoding)2088```20892090Затем в конфигурации логирования, передаваемой в [`dictConfig()`](https://python-all.ru/3.11/library/logging.config.html#logging.config.dictConfig), можно указать, что обработчик должен быть создан вызовом этой функции:20912092```python2093LOGGING = {2094 'version': 1,2095 'disable_existing_loggers': False,2096 'formatters': {2097 'default': {2098 'format': '%(asctime)s %(levelname)s %(name)s %(message)s'2099 },2100 },2101 'handlers': {2102 'file':{2103 # Значения ниже извлекаются из этого словаря и2104 # используются для создания обработчика, установки его уровня и2105 # его форматтера.2106 '()': owned_file_handler,2107 'level':'DEBUG',2108 'formatter': 'default',2109 # Значения ниже передаются вызываемому объекту-создателю обработчика2110 # в качестве именованных аргументов.2111 'owner': ['pulse', 'pulse'],2112 'filename': 'chowntest.log',2113 'mode': 'w',2114 'encoding': 'utf-8',2115 },2116 },2117 'root': {2118 'handlers': ['file'],2119 'level': 'DEBUG',2120 },2121}2122```21232124В этом примере для иллюстрации права владения устанавливаются с использованием пользователя и группы `pulse`. Собирая всё вместе в рабочий скрипт, `chowntest.py`:21252126```python2127import logging, logging.config, os, shutil21282129def owned_file_handler(filename, mode='a', encoding=None, owner=None):2130 if owner:2131 if not os.path.exists(filename):2132 open(filename, 'a').close()2133 shutil.chown(filename, *owner)2134 return logging.FileHandler(filename, mode, encoding)21352136LOGGING = {2137 'version': 1,2138 'disable_existing_loggers': False,2139 'formatters': {2140 'default': {2141 'format': '%(asctime)s %(levelname)s %(name)s %(message)s'2142 },2143 },2144 'handlers': {2145 'file':{2146 # Значения ниже извлекаются из этого словаря и2147 # используются для создания обработчика, установки его уровня и2148 # его форматтера.2149 '()': owned_file_handler,2150 'level':'DEBUG',2151 'formatter': 'default',2152 # Значения ниже передаются вызываемому объекту-создателю обработчика2153 # в качестве именованных аргументов.2154 'owner': ['pulse', 'pulse'],2155 'filename': 'chowntest.log',2156 'mode': 'w',2157 'encoding': 'utf-8',2158 },2159 },2160 'root': {2161 'handlers': ['file'],2162 'level': 'DEBUG',2163 },2164}21652166logging.config.dictConfig(LOGGING)2167logger = logging.getLogger('mylogger')2168logger.debug('A debug message')2169```21702171Для запуска, вероятно, потребуется выполнить от имени `root`:21722173```console2174$ sudo python3.3 chowntest.py2175$ cat chowntest.log21762013-11-05 09:34:51,128 DEBUG mylogger A debug message2177$ ls -l chowntest.log2178-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log2179```21802181Обратите внимание, что в этом примере используется Python 3.3, потому что в нём появился [`shutil.chown()`](https://python-all.ru/3.11/library/shutil.html#shutil.chown). Этот подход должен работать с любой версией Python, поддерживающей [`dictConfig()`](https://python-all.ru/3.11/library/logging.config.html#logging.config.dictConfig) – а именно Python 2.7, 3.2 или новее. В версиях до 3.3 потребовалось бы реализовать фактическую смену владельца, например, с помощью [`os.chown()`](https://python-all.ru/3.11/library/os.html#os.chown).21822183На практике функция создания обработчика может находиться в служебном модуле где-нибудь в вашем проекте. Вместо строки в конфигурации:21842185```python2186'()': owned_file_handler,2187```21882189можно использовать, например:21902191```python2192'()': 'ext://project.util.owned_file_handler',2193```21942195где `project.util` можно заменить на фактическое имя пакета, в котором находится функция. В приведённом рабочем скрипте должно сработать использование `'ext://__main__.owned_file_handler'`. Здесь фактический вызываемый объект разрешается с помощью [`dictConfig()`](https://python-all.ru/3.11/library/logging.config.html#logging.config.dictConfig) из спецификации `ext://`.21962197Этот пример, надеюсь, также показывает, как можно реализовать другие типы изменений файлов – например, установку определённых битов разрешений POSIX – аналогичным образом, с помощью [`os.chmod()`](https://python-all.ru/3.11/library/os.html#os.chmod).21982199Разумеется, этот подход можно распространить и на другие типы обработчиков, помимо [`FileHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.FileHandler) – например, на один из вращающихся файловых обработчиков или на совершенно другой тип обработчика.22002201## Использование определённых стилей форматирования во всём приложении22022203В Python 3.2 у [`Formatter`](https://python-all.ru/3.11/library/logging.html#logging.Formatter) появился именованный параметр `style`, который, хотя по умолчанию для обратной совместимости он равен `%`, позволяет указать `{` или `$` для поддержки подходов к форматированию, поддерживаемых [`str.format()`](https://python-all.ru/3.11/library/stdtypes.html#str.format) и [`string.Template`](https://python-all.ru/3.11/library/string.html#string.Template). Обратите внимание, что это управляет форматированием сообщений журнала для окончательного вывода в журнал и совершенно не зависит от того, как конструируется отдельное сообщение журнала.22042205Вызовы логирования ([`debug()`](https://python-all.ru/3.11/library/logging.html#logging.Logger.debug), [`info()`](https://python-all.ru/3.11/library/logging.html#logging.Logger.info) и т.д.) принимают только позиционные параметры для самого сообщения журнала, а именованные параметры используются только для определения параметров обработки вызова (например, именованный параметр `exc_info` для указания, что нужно записывать информацию о трассировке, или именованный параметр `extra` для указания дополнительной контекстной информации, добавляемой в журнал). Таким образом, нельзя напрямую выполнять вызовы логирования с использованием синтаксиса [`str.format()`](https://python-all.ru/3.11/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.11/library/string.html#string.Template), потому что внутри пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Изменить это без нарушения обратной совместимости было бы невозможно, поскольку все существующие вызовы логирования в коде используют строки с %-форматированием.22062207Высказывались предложения связывать стили форматирования с конкретными регистраторами, но этот подход также сталкивается с проблемами обратной совместимости, поскольку любой существующий код может использовать данное имя регистратора и %-форматирование.22082209Чтобы логирование работало совместимо между любыми сторонними библиотеками и вашим кодом, решения о форматировании необходимо принимать на уровне отдельного вызова логирования. Это открывает несколько способов, которыми можно реализовать альтернативные стили форматирования.22102211### Использование фабрик LogRecord22122213В Python 3.2, вместе с упомянутыми выше изменениями [`Formatter`](https://python-all.ru/3.11/library/logging.html#logging.Formatter), пакет logging получил возможность позволять пользователям устанавливать свои собственные подклассы [`LogRecord`](https://python-all.ru/3.11/library/logging.html#logging.LogRecord) с помощью функции [`setLogRecordFactory()`](https://python-all.ru/3.11/library/logging.html#logging.setLogRecordFactory). Вы можете использовать это, чтобы установить свой собственный подкласс [`LogRecord`](https://python-all.ru/3.11/library/logging.html#logging.LogRecord), который делает правильные вещи, переопределяя метод [`getMessage()`](https://python-all.ru/3.11/library/logging.html#logging.LogRecord.getMessage). В реализации базового класса этого метода происходит форматирование `msg % args`, и именно здесь можно подставить альтернативное форматирование; однако следует быть осторожным, чтобы поддерживать все стили форматирования и разрешить %-форматирование по умолчанию для обеспечения совместимости с другим кодом. Также следует позаботиться о вызове `str(self.msg)`, как это делает базовая реализация.22142215Обратитесь к справочной документации по [`setLogRecordFactory()`](https://python-all.ru/3.11/library/logging.html#logging.setLogRecordFactory) и [`LogRecord`](https://python-all.ru/3.11/library/logging.html#logging.LogRecord) для получения дополнительной информации.22162217### Использование пользовательских объектов сообщений22182219Есть еще один, возможно, более простой способ использовать {}- и $-форматирование для построения отдельных сообщений лога. Вы, возможно, помните (из раздела [Использование произвольных объектов в качестве сообщений](https://python-all.ru/3.11/howto/logging.html#arbitrary-object-messages)), что при логировании можно использовать произвольный объект в качестве строки формата сообщения, и пакет logging вызовет [`str()`](https://python-all.ru/3.11/library/stdtypes.html#str) для этого объекта, чтобы получить фактическую строку формата. Рассмотрим следующие два класса:22202221```python2222class BraceMessage:2223 def __init__(self, fmt, /, *args, **kwargs):2224 self.fmt = fmt2225 self.args = args2226 self.kwargs = kwargs22272228 def __str__(self):2229 return self.fmt.format(*self.args, **self.kwargs)22302231class DollarMessage:2232 def __init__(self, fmt, /, **kwargs):2233 self.fmt = fmt2234 self.kwargs = kwargs22352236 def __str__(self):2237 from string import Template2238 return Template(self.fmt).substitute(**self.kwargs)2239```22402241Любой из них можно использовать вместо строки формата, чтобы разрешить {}- или $-форматирование для построения фактической части «message», которая появляется в форматированном выводе лога вместо «%(message)s», «{message}» или «$message». Если вам кажется неудобным использовать имена классов каждый раз при логировании, вы можете сделать это более приятным, используя псевдоним, такой как `M` или `_` для сообщения (или, возможно, `__`, если вы используете `_` для локализации).22422243Примеры этого подхода приведены ниже. Во-первых, форматирование с помощью [`str.format()`](https://python-all.ru/3.11/library/stdtypes.html#str.format):22442245```python2246>>> __ = BraceMessage2247>>> print(__('Message with {0} {1}', 2, 'placeholders'))2248Message with 2 placeholders2249>>> class Point: pass2250...2251>>> p = Point()2252>>> p.x = 0.52253>>> p.y = 0.52254>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))2255Message with coordinates: (0.50, 0.50)2256```22572258Во-вторых, форматирование с помощью [`string.Template`](https://python-all.ru/3.11/library/string.html#string.Template):22592260```python2261>>> __ = DollarMessage2262>>> print(__('Message with $num $what', num=2, what='placeholders'))2263Message with 2 placeholders2264>>>2265```22662267Стоит отметить, что при таком подходе вы не платите значительных потерь производительности: фактическое форматирование происходит не при вызове логирования, а когда (и если) сообщение лога действительно должно быть выведено в лог обработчиком. Так что единственная необычная вещь, которая может вас сбить с толку, это то, что круглые скобки ставятся вокруг строки формата и аргументов, а не только вокруг строки формата. Это потому, что нотация \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов `XXXMessage`, показанных выше.22682269## Настройка фильтров с помощью [`dictConfig()`](https://python-all.ru/3.11/library/logging.config.html#logging.config.dictConfig)22702271*Можно* настраивать фильтры с помощью [`dictConfig()`](https://python-all.ru/3.11/library/logging.config.html#logging.config.dictConfig), хотя с первого взгляда может быть неочевидно, как это сделать (поэтому и дан этот рецепт). Поскольку [`Filter`](https://python-all.ru/3.11/library/logging.html#logging.Filter) – единственный класс фильтра, включенный в стандартную библиотеку, и вряд ли он удовлетворит многие требования (он присутствует только как базовый класс), вам, как правило, потребуется определить свой собственный подкласс [`Filter`](https://python-all.ru/3.11/library/logging.html#logging.Filter) с переопределенным методом [`filter()`](https://python-all.ru/3.11/library/logging.html#logging.Filter.filter). Для этого укажите ключ `()` в словаре конфигурации для фильтра, указав вызываемый объект, который будет использоваться для создания фильтра (класс – наиболее очевидный вариант, но вы можете предоставить любой вызываемый объект, возвращающий экземпляр [`Filter`](https://python-all.ru/3.11/library/logging.html#logging.Filter)). Вот полный пример:22722273```python2274import logging2275import logging.config2276import sys22772278class MyFilter(logging.Filter):2279 def __init__(self, param=None):2280 self.param = param22812282 def filter(self, record):2283 if self.param is None:2284 allow = True2285 else:2286 allow = self.param not in record.msg2287 if allow:2288 record.msg = 'changed: ' + record.msg2289 return allow22902291LOGGING = {2292 'version': 1,2293 'filters': {2294 'myfilter': {2295 '()': MyFilter,2296 'param': 'noshow',2297 }2298 },2299 'handlers': {2300 'console': {2301 'class': 'logging.StreamHandler',2302 'filters': ['myfilter']2303 }2304 },2305 'root': {2306 'level': 'DEBUG',2307 'handlers': ['console']2308 },2309}23102311if __name__ == '__main__':2312 logging.config.dictConfig(LOGGING)2313 logging.debug('hello')2314 logging.debug('hello - noshow')2315```23162317Этот пример показывает, как можно передавать конфигурационные данные вызываемому объекту, который создает экземпляр, в виде именованных параметров. При запуске приведенный выше скрипт выведет:23182319```text2320changed: hello2321```23222323что показывает, что фильтр работает в соответствии с настройками.23242325Несколько дополнительных моментов, на которые стоит обратить внимание:23262327- Если вы не можете сослаться на вызываемый объект напрямую в конфигурации (например, если он находится в другом модуле, и вы не можете импортировать его напрямую в том месте, где находится словарь конфигурации), вы можете использовать форму `ext://...`, как описано в разделе [Доступ к внешним объектам](https://python-all.ru/3.11/library/logging.config.html#logging-config-dict-externalobj). Например, в приведенном выше примере можно было использовать текст `'ext://__main__.MyFilter'` вместо `MyFilter`.2328- Помимо фильтров, этот метод также можно использовать для настройки пользовательских обработчиков и форматтеров. Смотрите раздел [Пользовательские объекты](https://python-all.ru/3.11/library/logging.config.html#logging-config-dict-userdef) для получения дополнительной информации о том, как logging поддерживает использование пользовательских объектов в своей конфигурации, а также см. другой рецепт из этой книги рецептов [Настройка обработчиков с помощью dictConfig()](https://python-all.ru/3.11/howto/logging-cookbook.html#custom-handlers) выше.23292330## Настраиваемое форматирование исключений23312332Могут возникнуть ситуации, когда вы захотите настроить форматирование исключений – для примера, предположим, вы хотите ровно одну строку на каждое событие лога, даже если присутствует информация об исключении. Вы можете сделать это с помощью пользовательского класса форматтера, как показано в следующем примере:23332334```python2335import logging23362337class OneLineExceptionFormatter(logging.Formatter):2338 def formatException(self, exc_info):2339 """2340 Форматировать исключение так, чтобы оно выводилось одной строкой.2341 """2342 result = super().formatException(exc_info)2343 return repr(result) # или форматировать одной строкой по своему усмотрению23442345 def format(self, record):2346 s = super().format(record)2347 if record.exc_text:2348 s = s.replace('\n', '') + '|'2349 return s23502351def configure_logging():2352 fh = logging.FileHandler('output.txt', 'w')2353 f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',2354 '%d/%m/%Y %H:%M:%S')2355 fh.setFormatter(f)2356 root = logging.getLogger()2357 root.setLevel(logging.DEBUG)2358 root.addHandler(fh)23592360def main():2361 configure_logging()2362 logging.info('Sample message')2363 try:2364 x = 1 / 02365 except ZeroDivisionError as e:2366 logging.exception('ZeroDivisionError: %s', e)23672368if __name__ == '__main__':2369 main()2370```23712372При запуске это создает файл ровно с двумя строками:23732374```text237528/01/2015 07:21:23|INFO|Sample message|237628/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'|2377```23782379Хотя описанный выше подход упрощен, он показывает путь к тому, как можно форматировать информацию об исключениях по своему вкусу. Модуль [`traceback`](https://python-all.ru/3.11/library/traceback.html#module-traceback) может быть полезен для более специализированных нужд.23802381## Озвучивание сообщений лога23822383Могут быть ситуации, когда желательно выводить сообщения лога в звуковом, а не визуальном формате. Это легко сделать, если в вашей системе доступна функция преобразования текста в речь (TTS), даже если у нее нет привязки к Python. Большинство TTS-систем имеют программу командной строки, которую можно запустить, и ее можно вызвать из обработчика с помощью [`subprocess`](https://python-all.ru/3.11/library/subprocess.html#module-subprocess). Здесь предполагается, что программы командной строки TTS не будут ожидать взаимодействия с пользователем или занимать много времени для завершения, и что частота сообщений лога не будет настолько высокой, чтобы перегружать пользователя сообщениями, и что допустимо проговаривать сообщения по одному, а не одновременно. В приведенном ниже примере реализации ожидается, пока одно сообщение не будет произнесено, прежде чем обрабатывать следующее, и это может заставить другие обработчики ждать. Вот короткий пример, демонстрирующий подход, который предполагает, что доступен TTS-пакет `espeak`:23842385```python2386import logging2387import subprocess2388import sys23892390class TTSHandler(logging.Handler):2391 def emit(self, record):2392 msg = self.format(record)2393 # Говорить медленно женским английским голосом.2394 cmd = ['espeak', '-s150', '-ven+f3', msg]2395 p = subprocess.Popen(cmd, stdout=subprocess.PIPE,2396 stderr=subprocess.STDOUT)2397 # дождаться завершения программы2398 p.communicate()23992400def configure_logging():2401 h = TTSHandler()2402 root = logging.getLogger()2403 root.addHandler(h)2404 # стандартный форматтер просто возвращает сообщение2405 root.setLevel(logging.DEBUG)24062407def main():2408 logging.info('Hello')2409 logging.debug('Goodbye')24102411if __name__ == '__main__':2412 configure_logging()2413 sys.exit(main())2414```24152416При запуске этот скрипт должен сказать «Hello», а затем «Goodbye» женским голосом.24172418Описанный выше подход, конечно, можно адаптировать для других TTS-систем и даже для других систем, которые могут обрабатывать сообщения через внешние программы, запускаемые из командной строки.24192420## Буферизация сообщений лога и условный вывод24212422Могут возникнуть ситуации, когда вы хотите записывать сообщения во временную область и выводить их только при наступлении определенного условия. Например, вы можете начать запись отладочных событий в функции, и если функция завершится без ошибок, вы не захотите засорять лог собранной отладочной информацией, но если возникнет ошибка, вы захотите вывести всю отладочную информацию вместе с ошибкой.24232424Вот пример, показывающий, как это можно сделать с помощью декоратора для ваших функций, где вы хотите, чтобы логирование вело себя таким образом. Он использует [`logging.handlers.MemoryHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.MemoryHandler), который позволяет буферизовать зарегистрированные события до наступления некоторого условия, после чего буферизованные события `flushed` – передаются другому обработчику (обработчику `target`) для обработки. По умолчанию `MemoryHandler` сбрасывается, когда его буфер заполняется или встречается событие, уровень которого больше или равен указанному порогу. Вы можете использовать этот рецепт с более специализированным подклассом `MemoryHandler`, если хотите настроить поведение сброса.24252426Пример скрипта содержит простую функцию `foo`, которая просто перебирает все уровни логирования, записывая в `sys.stderr` информацию о том, какой уровень будет использоваться, а затем регистрирует сообщение на этом уровне. Вы можете передать параметр в `foo`, который, если равен true, будет регистрировать на уровнях ERROR и CRITICAL – в противном случае он регистрирует только на уровнях DEBUG, INFO и WARNING.24272428Скрипт просто настраивает декорирование `foo` декоратором, который будет выполнять необходимое условное логирование. Декоратор принимает регистратор в качестве параметра и подключает обработчик памяти на время вызова декорированной функции. Декоратор можно дополнительно параметризовать с помощью целевого обработчика, уровня, при котором должен происходить сброс, и емкости буфера (количество буферизируемых записей). По умолчанию они равны [`StreamHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.StreamHandler), который пишет в `sys.stderr`, `logging.ERROR` и `100` соответственно.24292430Вот скрипт:24312432```python2433import logging2434from logging.handlers import MemoryHandler2435import sys24362437logger = logging.getLogger(__name__)2438logger.addHandler(logging.NullHandler())24392440def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):2441 if target_handler is None:2442 target_handler = logging.StreamHandler()2443 if flush_level is None:2444 flush_level = logging.ERROR2445 if capacity is None:2446 capacity = 1002447 handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)24482449 def decorator(fn):2450 def wrapper(*args, **kwargs):2451 logger.addHandler(handler)2452 try:2453 return fn(*args, **kwargs)2454 except Exception:2455 logger.exception('call failed')2456 raise2457 finally:2458 super(MemoryHandler, handler).flush()2459 logger.removeHandler(handler)2460 return wrapper24612462 return decorator24632464def write_line(s):2465 sys.stderr.write('%s\n' % s)24662467def foo(fail=False):2468 write_line('about to log at DEBUG ...')2469 logger.debug('Actually logged at DEBUG')2470 write_line('about to log at INFO ...')2471 logger.info('Actually logged at INFO')2472 write_line('about to log at WARNING ...')2473 logger.warning('Actually logged at WARNING')2474 if fail:2475 write_line('about to log at ERROR ...')2476 logger.error('Actually logged at ERROR')2477 write_line('about to log at CRITICAL ...')2478 logger.critical('Actually logged at CRITICAL')2479 return fail24802481decorated_foo = log_if_errors(logger)(foo)24822483if __name__ == '__main__':2484 logger.setLevel(logging.DEBUG)2485 write_line('Calling undecorated foo with False')2486 assert not foo(False)2487 write_line('Calling undecorated foo with True')2488 assert foo(True)2489 write_line('Calling decorated foo with False')2490 assert not decorated_foo(False)2491 write_line('Calling decorated foo with True')2492 assert decorated_foo(True)2493```24942495При запуске этого скрипта отобразится следующий вывод:24962497```text2498Calling undecorated foo with False2499about to log at DEBUG ...2500about to log at INFO ...2501about to log at WARNING ...2502Calling undecorated foo with True2503about to log at DEBUG ...2504about to log at INFO ...2505about to log at WARNING ...2506about to log at ERROR ...2507about to log at CRITICAL ...2508Calling decorated foo with False2509about to log at DEBUG ...2510about to log at INFO ...2511about to log at WARNING ...2512Calling decorated foo with True2513about to log at DEBUG ...2514about to log at INFO ...2515about to log at WARNING ...2516about to log at ERROR ...2517Actually logged at DEBUG2518Actually logged at INFO2519Actually logged at WARNING2520Actually logged at ERROR2521about to log at CRITICAL ...2522Actually logged at CRITICAL2523```25242525Как видно, фактический вывод журнала происходит только при регистрации события, уровень которого ERROR или выше, но в этом случае также регистрируются все предыдущие события с более низкими уровнями.25262527Конечно, можно использовать обычные средства декорирования:25282529```python2530@log_if_errors(logger)2531def foo(fail=False):2532 ...2533```25342535## Отправка сообщений журнала по электронной почте с буферизацией25362537Чтобы проиллюстрировать, как можно отправлять сообщения журнала по электронной почте, так чтобы заданное количество сообщений отправлялось за одно письмо, можно создать подкласс [`BufferingHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.BufferingHandler). В приведённом ниже примере, который можно адаптировать под свои нужды, предоставляется простая тестовая обвязка, позволяющая запустить скрипт с аргументами командной строки, указывающими, что обычно необходимо для отправки через SMTP. (Запустите загруженный скрипт с аргументом `-h`, чтобы увидеть обязательные и необязательные аргументы.)25382539```python2540import logging2541import logging.handlers2542import smtplib25432544class BufferingSMTPHandler(logging.handlers.BufferingHandler):2545 def __init__(self, mailhost, port, username, password, fromaddr, toaddrs,2546 subject, capacity):2547 logging.handlers.BufferingHandler.__init__(self, capacity)2548 self.mailhost = mailhost2549 self.mailport = port2550 self.username = username2551 self.password = password2552 self.fromaddr = fromaddr2553 if isinstance(toaddrs, str):2554 toaddrs = [toaddrs]2555 self.toaddrs = toaddrs2556 self.subject = subject2557 self.setFormatter(logging.Formatter("%(asctime)s %(levelname)-5s %(message)s"))25582559 def flush(self):2560 if len(self.buffer) > 0:2561 try:2562 smtp = smtplib.SMTP(self.mailhost, self.mailport)2563 smtp.starttls()2564 smtp.login(self.username, self.password)2565 msg = "From: %s\r\nTo: %s\r\nSubject: %s\r\n\r\n" % (self.fromaddr, ','.join(self.toaddrs), self.subject)2566 for record in self.buffer:2567 s = self.format(record)2568 msg = msg + s + "\r\n"2569 smtp.sendmail(self.fromaddr, self.toaddrs, msg)2570 smtp.quit()2571 except Exception:2572 if logging.raiseExceptions:2573 raise2574 self.buffer = []25752576if __name__ == '__main__':2577 import argparse25782579 ap = argparse.ArgumentParser()2580 aa = ap.add_argument2581 aa('host', metavar='HOST', help='SMTP server')2582 aa('--port', '-p', type=int, default=587, help='SMTP port')2583 aa('user', metavar='USER', help='SMTP username')2584 aa('password', metavar='PASSWORD', help='SMTP password')2585 aa('to', metavar='TO', help='Addressee for emails')2586 aa('sender', metavar='SENDER', help='Sender email address')2587 aa('--subject', '-s',2588 default='Test Logging email from Python logging module (buffering)',2589 help='Subject of email')2590 options = ap.parse_args()2591 logger = logging.getLogger()2592 logger.setLevel(logging.DEBUG)2593 h = BufferingSMTPHandler(options.host, options.port, options.user,2594 options.password, options.sender,2595 options.to, options.subject, 10)2596 logger.addHandler(h)2597 for i in range(102):2598 logger.info("Info index = %d", i)2599 h.flush()2600 h.close()2601```26022603Если запустить этот скрипт и SMTP-сервер настроен правильно, то будет отправлено одиннадцать писем указанному адресату. Первые десять писем будут содержать по десять сообщений журнала, а одиннадцатое – два сообщения. В сумме получается 102 сообщения, как указано в скрипте.26042605## Форматирование времени с использованием UTC (GMT) через конфигурацию26062607Иногда требуется форматировать время в UTC, что можно сделать с помощью класса `UTCFormatter`, показанного ниже:26082609```python2610import logging2611import time26122613class UTCFormatter(logging.Formatter):2614 converter = time.gmtime2615```26162617и затем можно использовать `UTCFormatter` в своём коде вместо [`Formatter`](https://python-all.ru/3.11/library/logging.html#logging.Formatter). Если требуется сделать это через конфигурацию, можно воспользоваться API [`dictConfig()`](https://python-all.ru/3.11/library/logging.config.html#logging.config.dictConfig), как показано в следующем полном примере:26182619```python2620import logging2621import logging.config2622import time26232624class UTCFormatter(logging.Formatter):2625 converter = time.gmtime26262627LOGGING = {2628 'version': 1,2629 'disable_existing_loggers': False,2630 'formatters': {2631 'utc': {2632 '()': UTCFormatter,2633 'format': '%(asctime)s %(message)s',2634 },2635 'local': {2636 'format': '%(asctime)s %(message)s',2637 }2638 },2639 'handlers': {2640 'console1': {2641 'class': 'logging.StreamHandler',2642 'formatter': 'utc',2643 },2644 'console2': {2645 'class': 'logging.StreamHandler',2646 'formatter': 'local',2647 },2648 },2649 'root': {2650 'handlers': ['console1', 'console2'],2651 }2652}26532654if __name__ == '__main__':2655 logging.config.dictConfig(LOGGING)2656 logging.warning('The local time is %s', time.asctime())2657```26582659При запуске этого скрипта он должен вывести примерно следующее:26602661```text26622015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 201526632015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 20152664```26652666показывая, как время форматируется как в местном времени, так и в UTC, по одному для каждого обработчика.26672668## Использование контекстного менеджера для выборочного журналирования26692670Бывают ситуации, когда полезно временно изменить конфигурацию журналирования, а затем вернуть её обратно после выполнения каких-то действий. Для этого контекстный менеджер – самый очевидный способ сохранить и восстановить контекст журналирования. Вот простой пример такого контекстного менеджера, который позволяет по желанию изменить уровень журналирования и добавить обработчик журнала исключительно в области действия контекстного менеджера:26712672```python2673import logging2674import sys26752676class LoggingContext:2677 def __init__(self, logger, level=None, handler=None, close=True):2678 self.logger = logger2679 self.level = level2680 self.handler = handler2681 self.close = close26822683 def __enter__(self):2684 if self.level is not None:2685 self.old_level = self.logger.level2686 self.logger.setLevel(self.level)2687 if self.handler:2688 self.logger.addHandler(self.handler)26892690 def __exit__(self, et, ev, tb):2691 if self.level is not None:2692 self.logger.setLevel(self.old_level)2693 if self.handler:2694 self.logger.removeHandler(self.handler)2695 if self.handler and self.close:2696 self.handler.close()2697 # неявный возврат None => не подавлять исключения2698```26992700Если указать значение уровня, уровень регистратора устанавливается на это значение в области действия блока with, охватываемого контекстным менеджером. Если указать обработчик, он добавляется к регистратору при входе в блок и удаляется при выходе из блока. Также можно попросить менеджер закрыть обработчик при выходе из блока – это можно сделать, если обработчик больше не нужен.27012702Чтобы проиллюстрировать, как это работает, можно добавить следующий блок кода к предыдущему:27032704```python2705if __name__ == '__main__':2706 logger = logging.getLogger('foo')2707 logger.addHandler(logging.StreamHandler())2708 logger.setLevel(logging.INFO)2709 logger.info('1. This should appear just once on stderr.')2710 logger.debug('2. This should not appear.')2711 with LoggingContext(logger, level=logging.DEBUG):2712 logger.debug('3. This should appear once on stderr.')2713 logger.debug('4. This should not appear.')2714 h = logging.StreamHandler(sys.stdout)2715 with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):2716 logger.debug('5. This should appear twice - once on stderr and once on stdout.')2717 logger.info('6. This should appear just once on stderr.')2718 logger.debug('7. This should not appear.')2719```27202721Изначально устанавливаем уровень регистратора равным `INFO`, поэтому сообщение №1 отображается, а сообщение №2 – нет. Затем временно меняем уровень на `DEBUG` в следующем блоке `with`, и сообщение №3 отображается. После выхода из блока уровень регистратора восстанавливается до `INFO`, поэтому сообщение №4 не отображается. В следующем блоке `with` снова устанавливаем уровень `DEBUG`, но также добавляем обработчик, записывающий в `sys.stdout`. Таким образом, сообщение №5 отображается дважды на консоли (один раз через `stderr` и один раз через `stdout`). После завершения оператора `with` состояние возвращается к исходному, поэтому сообщение №6 отображается (как сообщение №1), а сообщение №7 – нет (как сообщение №2).27222723Если запустить полученный скрипт, результат будет следующим:27242725```console2726$ python logctx.py27271. This should appear just once on stderr.27283. This should appear once on stderr.27295. This should appear twice - once on stderr and once on stdout.27305. This should appear twice - once on stderr and once on stdout.27316. This should appear just once on stderr.2732```27332734Если запустить его снова, но перенаправить `stderr` в `/dev/null`, мы увидим следующее, что является единственным сообщением, записанным в `stdout`:27352736```console2737$ python logctx.py 2>/dev/null27385. This should appear twice - once on stderr and once on stdout.2739```27402741Ещё раз, но перенаправляя `stdout` в `/dev/null`, получаем:27422743```console2744$ python logctx.py >/dev/null27451. This should appear just once on stderr.27463. This should appear once on stderr.27475. This should appear twice - once on stderr and once on stdout.27486. This should appear just once on stderr.2749```27502751В этом случае сообщение №5, выведенное в `stdout`, не отображается, как и ожидалось.27522753Разумеется, описанный подход можно обобщить, например, для временного подключения фильтров журналирования. Обратите внимание, что приведённый выше код работает как в Python 2, так и в Python 3.27542755## Шаблон для запуска CLI-приложения27562757Вот пример, показывающий, как можно:27582759- Использовать уровень журналирования на основе аргументов командной строки2760- Перенаправлять вызовы к нескольким подкомандам в отдельных файлах, все с журналированием на одном уровне согласованным образом2761- Использовать простую минимальную конфигурацию27622763Предположим, у нас есть приложение командной строки, которое останавливает, запускает или перезапускает некоторые службы. Для иллюстрации это может быть организовано в виде файла `app.py`, который является главным скриптом приложения, с отдельными командами, реализованными в `start.py`, `stop.py` и `restart.py`. Предположим также, что мы хотим управлять степенью подробности вывода приложения через аргумент командной строки с значением по умолчанию `logging.INFO`. Вот один из способов, как мог бы быть написан `app.py`:27642765```python2766import argparse2767import importlib2768import logging2769import os2770import sys27712772def main(args=None):2773 scriptname = os.path.basename(__file__)2774 parser = argparse.ArgumentParser(scriptname)2775 levels = ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')2776 parser.add_argument('--log-level', default='INFO', choices=levels)2777 subparsers = parser.add_subparsers(dest='command',2778 help='Available commands:')2779 start_cmd = subparsers.add_parser('start', help='Start a service')2780 start_cmd.add_argument('name', metavar='NAME',2781 help='Name of service to start')2782 stop_cmd = subparsers.add_parser('stop',2783 help='Stop one or more services')2784 stop_cmd.add_argument('names', metavar='NAME', nargs='+',2785 help='Name of service to stop')2786 restart_cmd = subparsers.add_parser('restart',2787 help='Restart one or more services')2788 restart_cmd.add_argument('names', metavar='NAME', nargs='+',2789 help='Name of service to restart')2790 options = parser.parse_args()2791 # весь код для отправки команд мог бы быть в этом файле. Для целей2792 # только в целях иллюстрации каждая команда реализована в отдельном модуле.2793 try:2794 mod = importlib.import_module(options.command)2795 cmd = getattr(mod, 'command')2796 except (ImportError, AttributeError):2797 print('Unable to find the code for command \'%s\'' % options.command)2798 return 12799 # Здесь можно было бы сделать по-хитрому и загрузить конфигурацию из файла или словаря2800 logging.basicConfig(level=options.log_level,2801 format='%(levelname)s %(name)s %(message)s')2802 cmd(options)28032804if __name__ == '__main__':2805 sys.exit(main())2806```28072808А команды `start`, `stop` и `restart` могут быть реализованы в отдельных модулях, например, для запуска:28092810```python2811# start.py2812import logging28132814logger = logging.getLogger(__name__)28152816def command(options):2817 logger.debug('About to start %s', options.name)2818 # здесь происходит фактическая обработка команды...2819 logger.info('Started the \'%s\' service.', options.name)2820```28212822и аналогично для остановки:28232824```python2825# stop.py2826import logging28272828logger = logging.getLogger(__name__)28292830def command(options):2831 n = len(options.names)2832 if n == 1:2833 plural = ''2834 services = '\'%s\'' % options.names[0]2835 else:2836 plural = 's'2837 services = ', '.join('\'%s\'' % name for name in options.names)2838 i = services.rfind(', ')2839 services = services[:i] + ' and ' + services[i + 2:]2840 logger.debug('About to stop %s', services)2841 # здесь происходит фактическая обработка команды...2842 logger.info('Stopped the %s service%s.', services, plural)2843```28442845и аналогично для перезапуска:28462847```python2848# restart.py2849import logging28502851logger = logging.getLogger(__name__)28522853def command(options):2854 n = len(options.names)2855 if n == 1:2856 plural = ''2857 services = '\'%s\'' % options.names[0]2858 else:2859 plural = 's'2860 services = ', '.join('\'%s\'' % name for name in options.names)2861 i = services.rfind(', ')2862 services = services[:i] + ' and ' + services[i + 2:]2863 logger.debug('About to restart %s', services)2864 # здесь происходит фактическая обработка команды...2865 logger.info('Restarted the %s service%s.', services, plural)2866```28672868Если запустить это приложение с уровнем журналирования по умолчанию, мы получим примерно такой вывод:28692870```console2871$ python app.py start foo2872INFO start Started the 'foo' service.28732874$ python app.py stop foo bar2875INFO stop Stopped the 'foo' and 'bar' services.28762877$ python app.py restart foo bar baz2878INFO restart Restarted the 'foo', 'bar' and 'baz' services.2879```28802881Первое слово – уровень журналирования, а второе – имя модуля или пакета, в котором было зарегистрировано событие.28822883Если изменить уровень журналирования, можно изменить объём информации, отправляемой в журнал. Например, чтобы получить больше информации:28842885```console2886$ python app.py --log-level DEBUG start foo2887DEBUG start About to start foo2888INFO start Started the 'foo' service.28892890$ python app.py --log-level DEBUG stop foo bar2891DEBUG stop About to stop 'foo' and 'bar'2892INFO stop Stopped the 'foo' and 'bar' services.28932894$ python app.py --log-level DEBUG restart foo bar baz2895DEBUG restart About to restart 'foo', 'bar' and 'baz'2896INFO restart Restarted the 'foo', 'bar' and 'baz' services.2897```28982899А если нужно меньше:29002901```console2902$ python app.py --log-level WARNING start foo2903$ python app.py --log-level WARNING stop foo bar2904$ python app.py --log-level WARNING restart foo bar baz2905```29062907В этом случае команды ничего не выводят в консоль, поскольку ни одно сообщение уровня `WARNING` и выше ими не записывается.29082909## Графический интерфейс Qt для журналирования29102911Время от времени возникает вопрос о том, как организовать логирование в GUI-приложении. Фреймворк [Qt](https://python-all.ru/3.11/howto/logging-cookbook.html) – популярная кроссплатформенная UI-среда с привязками к Python через библиотеки [PySide2](https://python-all.ru/3.11/howto/logging-cookbook.html) или [PyQt5](https://python-all.ru/3.11/howto/logging-cookbook.html).29122913В следующем примере показано, как выполнять журналирование в графический интерфейс Qt. Он представляет простой класс `QtHandler`, который принимает вызываемый объект – слот главного потока, обновляющий GUI. Также создаётся рабочий поток, чтобы продемонстрировать возможность журналирования как из самого интерфейса (через кнопку для ручной записи), так и из фонового рабочего потока (который в данном случае просто выводит сообщения со случайными уровнями и случайными короткими задержками).29142915Рабочий поток реализован с помощью класса `QThread` из Qt, а не модуля [`threading`](https://python-all.ru/3.11/library/threading.html#module-threading), поскольку бывают ситуации, когда необходимо использовать `QThread`, который обеспечивает лучшую интеграцию с другими компонентами `Qt`.29162917Код должен работать с последними версиями `PySide6`, `PyQt6`, `PySide2` или `PyQt5`. Вы сможете адаптировать этот подход для более ранних версий Qt. Обратитесь к комментариям в примере кода за более подробной информацией.29182919```python2920import datetime2921import logging2922import random2923import sys2924import time29252926# Обработка небольших различий между разными пакетами Qt2927try:2928 from PySide6 import QtCore, QtGui, QtWidgets2929 Signal = QtCore.Signal2930 Slot = QtCore.Slot2931except ImportError:2932 try:2933 from PyQt6 import QtCore, QtGui, QtWidgets2934 Signal = QtCore.pyqtSignal2935 Slot = QtCore.pyqtSlot2936 except ImportError:2937 try:2938 from PySide2 import QtCore, QtGui, QtWidgets2939 Signal = QtCore.Signal2940 Slot = QtCore.Slot2941 except ImportError:2942 from PyQt5 import QtCore, QtGui, QtWidgets2943 Signal = QtCore.pyqtSignal2944 Slot = QtCore.pyqtSlot29452946logger = logging.getLogger(__name__)29472948#2949# Сигналы должны содержаться в QObject или подклассе, чтобы корректно2950# инициализироваться.2951#2952class Signaller(QtCore.QObject):2953 signal = Signal(str, logging.LogRecord)29542955#2956# Вывод в графический интерфейс Qt должен происходить только в главном потоке. Поэтому данный2957# обработчик спроектирован так, чтобы принимать функцию-слот, настроенную на выполнение в главном2958# потоке. В этом примере функция принимает строковый аргумент, который является2959# отформатированным сообщением лога, и запись лога, которая его породила. Отформатированная2960# строка – это просто удобство; можно отформатировать строку для вывода любым способом2961# в самой функции-слоте.2962#2963# Функцию-слот можно настроить на любые нужные обновления GUI. Обработчик2964# не знает и не заботится о конкретных элементах интерфейса.2965#2966class QtHandler(logging.Handler):2967 def __init__(self, slotfunc, *args, **kwargs):2968 super().__init__(*args, **kwargs)2969 self.signaller = Signaller()2970 self.signaller.signal.connect(slotfunc)29712972 def emit(self, record):2973 s = self.format(record)2974 self.signaller.signal.emit(s, record)29752976#2977# В этом примере используются QThreads, что означает, что потоки на уровне Python2978# называются как-то вроде "Dummy-1". Функция ниже получает имя Qt2979# текущего потока.2980#2981def ctname():2982 return QtCore.QThread.currentThread().objectName()29832984#2985# Используется для генерации случайных уровней для логирования.2986#2987LEVELS = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,2988 logging.CRITICAL)29892990#2991# Этот класс-воркер представляет работу, выполняемую в потоке, отдельном от2992# главного потока. Поток запускается на выполнение работы по нажатию кнопки,2993# которая соединяется со слотом в воркере.2994#2995# Поскольку значение threadName по умолчанию в LogRecord не очень полезно, мы добавляем2996# qThreadName, содержащий имя QThread, вычисленное выше, и передаём это2997# значение в словаре "extra", который используется для обновления LogRecord с помощью2998# имя QThread.2999#3000# Этот пример рабочего просто выводит сообщения последовательно, перемежая их случайными задержками порядка нескольких секунд.3001# Позволяет потоку выполняться до прерывания. Это обеспечивает достаточно чистую остановку потока.3002#3003class Worker(QtCore.QObject):3004 @Slot()3005 def start(self):3006 extra = {'qThreadName': ctname() }3007 logger.debug('Started work', extra=extra)3008 i = 13009 # Реализует простой пользовательский интерфейс для этого примера из кулинарной книги. Он содержит:3010 # * Окно текстового редактора только для чтения, которое содержит форматированные сообщения журнала3011 while not QtCore.QThread.currentThread().isInterruptionRequested():3012 delay = 0.5 + random.random() * 23013 time.sleep(delay)3014 try:3015 if random.random() < 0.1:3016 raise ValueError('Exception raised: %d' % i)3017 else:3018 level = random.choice(LEVELS)3019 logger.log(level, 'Message after delay of %3.1f: %d', delay, i, extra=extra)3020 except ValueError as e:3021 logger.exception('Failed: %s', e, extra=extra)3022 i += 130233024#3025# * Кнопка запуска работы и записи в журнал в отдельном потоке3026#3027# * Кнопка записи чего-либо из основного потока3028# * Кнопка очистки окна журнала3029# Устанавливает моноширинный шрифт, принятый по умолчанию на платформе3030# для Qt63031#3032class Window(QtWidgets.QWidget):30333034 COLORS = {3035 logging.DEBUG: 'black',3036 logging.INFO: 'blue',3037 logging.WARNING: 'orange',3038 logging.ERROR: 'red',3039 logging.CRITICAL: 'purple',3040 }30413042 def __init__(self, app):3043 super().__init__()3044 self.app = app3045 self.textedit = te = QtWidgets.QPlainTextEdit(self)3046 # Устанавливает моноширинный шрифт по умолчанию для платформы3047 f = QtGui.QFont('nosuchfont')3048 if hasattr(f, 'Monospace'):3049 f.setStyleHint(f.Monospace)3050 else:3051 f.setStyleHint(f.StyleHint.Monospace) # для Qt63052 te.setFont(f)3053 te.setReadOnly(True)3054 PB = QtWidgets.QPushButton3055 self.work_button = PB('Start background work', self)3056 self.log_button = PB('Log a message at a random level', self)3057 self.clear_button = PB('Clear log window', self)3058 self.handler = h = QtHandler(self.update_status)3059 # Размещает все виджеты3060 fs = '%(asctime)s %(qThreadName)-12s %(levelname)-8s %(message)s'3061 formatter = logging.Formatter(fs)3062 h.setFormatter(formatter)3063 logger.addHandler(h)3064 # Подключает слоты и сигналы, не относящиеся к рабочему3065 app.aboutToQuit.connect(self.force_quit)30663067 # Запускает новый рабочий поток и подключает слоты для рабочего3068 layout = QtWidgets.QVBoxLayout(self)3069 layout.addWidget(te)3070 layout.addWidget(self.work_button)3071 layout.addWidget(self.log_button)3072 layout.addWidget(self.clear_button)3073 self.setFixedSize(900, 400)30743075 # После запуска кнопка должна быть отключена3076 self.log_button.clicked.connect(self.manual_update)3077 self.clear_button.clicked.connect(self.clear_display)30783079 # Запустить новый рабочий поток и подключить слоты для рабочего3080 self.start_thread()3081 self.work_button.clicked.connect(self.worker.start)3082 # Это запустит цикл событий в рабочем потоке3083 self.work_button.clicked.connect(lambda : self.work_button.setEnabled(False))30843085 def start_thread(self):3086 self.worker = Worker()3087 self.worker_thread = QtCore.QThread()3088 self.worker.setObjectName('Worker')3089 self.worker_thread.setObjectName('WorkerThread') # Просто скажите рабочему остановиться, затем скажите ему выйти и дождитесь этого3090 self.worker.moveToThread(self.worker_thread)3091 # Для использования при закрытии окна3092 self.worker_thread.start()30933094 def kill_thread(self):3095 # Функции ниже обновляют интерфейс и выполняются в основном потоке, поскольку слоты настроены именно там3096 # Эта функция использует переданное форматированное сообщение, но также использует информацию из записи, чтобы отформатировать сообщение подходящим цветом в соответствии с его серьёзностью (уровнем).3097 self.worker_thread.requestInterruption()3098 if self.worker_thread.isRunning():3099 self.worker_thread.quit()3100 self.worker_thread.wait()3101 else:3102 print('worker has already exited.')31033104 def force_quit(self):3105 # Для использования при закрытии окна3106 if self.worker_thread.isRunning():3107 self.kill_thread()31083109 # Функции ниже обновляют пользовательский интерфейс и выполняются в главном потоке, потому что3110 # здесь настраиваются слоты31113112 @Slot(str, logging.LogRecord)3113 def update_status(self, status, record):3114 color = self.COLORS.get(record.levelno, 'black')3115 s = '<pre><font color="%s">%s</font></pre>' % (color, status)3116 self.textedit.appendHtml(s)31173118 @Slot()3119 def manual_update(self):3120 # Эта функция использует переданное форматированное сообщение, а также использует3121 # информацию из записи для форматирования сообщения в подходящий3122 # цвет в соответствии с его серьёзностью (уровнем).3123 level = random.choice(LEVELS)3124 extra = {'qThreadName': ctname() }3125 logger.log(level, 'Manually logged!', extra=extra)31263127 @Slot()3128 def clear_display(self):3129 self.textedit.clear()31303131def main():3132 QtCore.QThread.currentThread().setObjectName('MainThread')3133 logging.getLogger().setLevel(logging.DEBUG)3134 app = QtWidgets.QApplication(sys.argv)3135 example = Window(app)3136 example.show()3137 if hasattr(app, 'exec'):3138 rc = app.exec()3139 else:3140 rc = app.exec_()3141 sys.exit(rc)31423143if __name__=='__main__':3144 main()3145```31463147## Журналирование в syslog с поддержкой RFC 542431483149Хотя [**RFC 5424**](https://python-all.ru/3.11/howto/logging-cookbook.html) датируется 2009 годом, большинство syslog-серверов по умолчанию настроены на использование более старого [**RFC 3164**](https://python-all.ru/3.11/howto/logging-cookbook.html), который берёт начало в 2001 году. Когда `logging` был добавлен в Python в 2003 году, он поддерживал более ранний (и единственный существовавший на тот момент) протокол. С момента выхода RFC 5424, поскольку он не получил широкого распространения в syslog-серверах, функциональность [`SysLogHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.handlers.SysLogHandler) не обновлялась.31503151RFC 5424 содержит полезные возможности, такие как поддержка структурированных данных. Если необходимо вести журналирование на syslog-сервер с поддержкой этого протокола, это можно сделать с помощью подкласса обработчика, который выглядит примерно так:31523153```python3154import datetime3155import logging.handlers3156import re3157import socket3158import time31593160class SysLogHandler5424(logging.handlers.SysLogHandler):31613162 tz_offset = re.compile(r'([+-]\d{2})(\d{2})$')3163 escaped = re.compile(r'([\]"\\])')31643165 def __init__(self, *args, **kwargs):3166 self.msgid = kwargs.pop('msgid', None)3167 self.appname = kwargs.pop('appname', None)3168 super().__init__(*args, **kwargs)31693170 def format(self, record):3171 version = 13172 asctime = datetime.datetime.fromtimestamp(record.created).isoformat()3173 m = self.tz_offset.match(time.strftime('%z'))3174 has_offset = False3175 if m and time.timezone:3176 hrs, mins = m.groups()3177 if int(hrs) or int(mins):3178 has_offset = True3179 if not has_offset:3180 asctime += 'Z'3181 else:3182 asctime += f'{hrs}:{mins}'3183 try:3184 hostname = socket.gethostname()3185 except Exception:3186 hostname = '-'3187 appname = self.appname or '-'3188 procid = record.process3189 msgid = '-'3190 msg = super().format(record)3191 sdata = '-'3192 if hasattr(record, 'structured_data'):3193 sd = record.structured_data3194 # Это должен быть словарь, где ключи – SD-ID, а значение –3195 # словарь, отображающий PARAM-NAME на PARAM-VALUE (обратитесь к RFC, чтобы узнать, что эти3196 # означают)3197 # Здесь нет проверки ошибок – это только для иллюстрации, и вы3198 # можете адаптировать этот код для использования в производственных средах3199 parts = []32003201 def replacer(m):3202 g = m.groups()3203 return '\\' + g[0]32043205 for sdid, dv in sd.items():3206 part = f'[{sdid}'3207 for k, v in dv.items():3208 s = str(v)3209 s = self.escaped.sub(replacer, s)3210 part += f' {k}="{s}"'3211 part += ']'3212 parts.append(part)3213 sdata = ''.join(parts)3214 return f'{version} {asctime} {hostname} {appname} {procid} {msgid} {sdata} {msg}'3215```32163217Чтобы полностью разобраться в приведённом коде, потребуется знакомство с RFC 5424. Возможно, ваши потребности будут несколько иными (например, в способе передачи структурированных данных в журнал). Тем не менее, приведённый код можно адаптировать под конкретные нужды. С таким обработчиком структурированные данные передаются, например, так:32183219```python3220sd = {3221 'foo@12345': {'bar': 'baz', 'baz': 'bozz', 'fizz': r'buzz'},3222 'foo@54321': {'rab': 'baz', 'zab': 'bozz', 'zzif': r'buzz'}3223}3224extra = {'structured_data': sd}3225i = 13226logger.debug('Message %d', i, extra=extra)3227```32283229## Как использовать объект Logger как выходной поток32303231Иногда возникает необходимость взаимодействовать со сторонним API, который ожидает объект, подобный файлу, для записи, но при этом нужно перенаправить вывод API в журнал. Это можно сделать с помощью класса, который оборачивает объект Logger, предоставляя файлоподобный интерфейс. Вот короткий скрипт, иллюстрирующий такой класс:32323233```python3234import logging32353236class LoggerWriter:3237 def __init__(self, logger, level):3238 self.logger = logger3239 self.level = level32403241 def write(self, message):3242 if message != '\n': # избегайте печати пустых строк, если хотите3243 self.logger.log(self.level, message)32443245 def flush(self):3246 # на самом деле ничего не делает, но может ожидаться от файлоподобного3247 # объекта – так что опционально в зависимости от вашей ситуации3248 pass32493250 def close(self):3251 # на самом деле ничего не делает, но может ожидаться от файлоподобного3252 # объекта – так что опционально в зависимости от вашей ситуации. Возможно, вы захотите3253 # установить флаг, чтобы последующие вызовы write вызывали исключение3254 pass32553256def main():3257 logging.basicConfig(level=logging.DEBUG)3258 logger = logging.getLogger('demo')3259 info_fp = LoggerWriter(logger, logging.INFO)3260 debug_fp = LoggerWriter(logger, logging.DEBUG)3261 print('An INFO message', file=info_fp)3262 print('A DEBUG message', file=debug_fp)32633264if __name__ == "__main__":3265 main()3266```32673268При запуске этот скрипт выводит32693270```text3271INFO:demo:An INFO message3272DEBUG:demo:A DEBUG message3273```32743275Можно также использовать `LoggerWriter` для перенаправления `sys.stdout` и `sys.stderr`, сделав примерно так:32763277```python3278import sys32793280sys.stdout = LoggerWriter(logger, logging.INFO)3281sys.stderr = LoggerWriter(logger, logging.WARNING)3282```32833284Это следует делать *после* настройки журналирования под свои нужды. В приведённом выше примере вызов [`basicConfig()`](https://python-all.ru/3.11/library/logging.html#logging.basicConfig) делает это (используя значение `sys.stderr` *до* того, как оно будет перезаписано экземпляром `LoggerWriter`). В результате получится примерно такой вывод:32853286```pycon3287>>> print('Foo')3288INFO:demo:Foo3289>>> print('Bar', file=sys.stderr)3290WARNING:demo:Bar3291>>>3292```32933294Разумеется, приведённые выше примеры показывают вывод в формате, используемом [`basicConfig()`](https://python-all.ru/3.11/library/logging.html#logging.basicConfig), но при настройке журналирования можно использовать другой форматтер.32953296Обратите внимание, что при такой схеме вы в значительной степени зависите от буферизации и порядка вызовов write, которые перехватываете. Например, при определении `LoggerWriter` выше, если есть такой фрагмент кода:32973298```python3299sys.stderr = LoggerWriter(logger, logging.WARNING)33001 / 03301```33023303то запуск скрипта даёт33043305```text3306WARNING:demo:Traceback (most recent call last):33073308WARNING:demo: File "/home/runner/cookbook-loggerwriter/test.py", line 53, in <module>33093310WARNING:demo:3311WARNING:demo:main()3312WARNING:demo: File "/home/runner/cookbook-loggerwriter/test.py", line 49, in main33133314WARNING:demo:3315WARNING:demo:1 / 03316WARNING:demo:ZeroDivisionError3317WARNING:demo::3318WARNING:demo:division by zero3319```33203321Как видно, такой вывод неидеален. Это происходит потому, что базовый код, который пишет в `sys.stderr`, выполняет несколько записей, каждая из которых приводит к отдельной строке лога (например, последние три строки выше). Чтобы обойти эту проблему, нужно буферизовать данные и выводить строки лога только при появлении символов новой строки. Давайте используем немного улучшенную реализацию `LoggerWriter`:33223323```python3324class BufferingLoggerWriter(LoggerWriter):3325 def __init__(self, logger, level):3326 super().__init__(logger, level)3327 self.buffer = ''33283329 def write(self, message):3330 if '\n' not in message:3331 self.buffer += message3332 else:3333 parts = message.split('\n')3334 if self.buffer:3335 s = self.buffer + parts.pop(0)3336 self.logger.log(self.level, s)3337 self.buffer = parts.pop()3338 for part in parts:3339 self.logger.log(self.level, part)3340```33413342Этот код просто буферизует данные до появления символа новой строки, после чего записывает полные строки. С таким подходом вывод становится лучше:33433344```text3345WARNING:demo:Traceback (most recent call last):3346WARNING:demo: File "/home/runner/cookbook-loggerwriter/main.py", line 55, in <module>3347WARNING:demo: main()3348WARNING:demo: File "/home/runner/cookbook-loggerwriter/main.py", line 52, in main3349WARNING:demo: 1/03350WARNING:demo:ZeroDivisionError: division by zero3351```33523353## Шаблоны, которых следует избегать33543355Хотя в предыдущих разделах были описаны способы решения задач, с которыми вы можете столкнуться, стоит упомянуть некоторые шаблоны использования, которые *бесполезны* и в большинстве случаев их следует избегать. Следующие разделы приведены в произвольном порядке.33563357### Многократное открытие одного и того же файла журнала33583359В Windows обычно не получится открыть один и тот же файл несколько раз, так как это приведёт к ошибке «файл используется другим процессом». Однако на платформах POSIX никаких ошибок при многократном открытии одного файла не возникнет. Это может произойти случайно, например:33603361- Добавление файлового обработчика более одного раза со ссылкой на один и тот же файл (например, из-за ошибки копирования/вставки/забыли изменить).3362- Открытие двух файлов, которые выглядят разными (у них разные имена), но на самом деле являются одним и тем же файлом, так как один – символическая ссылка на другой.3363- Порождение процесса (форк), после которого и родительский, и дочерний процесс имеют ссылку на один и тот же файл. Это может происходить, например, при использовании модуля [`multiprocessing`](https://python-all.ru/3.11/library/multiprocessing.html#module-multiprocessing).33643365Многократное открытие файла может *выглядеть* работающим большую часть времени, но на практике может привести к ряду проблем:33663367- Вывод логирования может искажаться, поскольку несколько потоков или процессов пытаются писать в один и тот же файл. Хотя логирование защищает от одновременного использования одного и того же экземпляра обработчика несколькими потоками, такой защиты нет, если одновременную запись пытаются выполнить два разных потока, использующие два разных экземпляра обработчика, которые указывают на один и тот же файл.3368- Попытка удалить файл (например, во время ротации) молча завершается неудачей, потому что есть другая ссылка на него. Это может привести к путанице и потере времени на отладку – записи журнала оказываются в неожиданных местах или полностью теряются. Или файл, который должен был быть перемещён, остаётся на месте и неожиданно растёт в размерах, несмотря на то что ротация по размеру якобы настроена.33693370Используйте методы, описанные в [Логирование в один файл из нескольких процессов](https://python-all.ru/3.11/howto/logging-cookbook.html#multiple-processes), чтобы обойти такие проблемы.33713372### Использование логгеров в качестве атрибутов класса или передача их в качестве параметров33733374Хотя могут быть необычные случаи, когда это необходимо, в целом в этом нет смысла, потому что логгеры – синглтоны. Код всегда может получить доступ к нужному экземпляру логгера по имени с помощью `logging.getLogger(name)`, поэтому передавать экземпляры повсюду и хранить их в качестве атрибутов экземпляра бессмысленно. Обратите внимание, что в других языках, таких как Java и C#, логгеры часто являются статическими атрибутами класса. Однако этот шаблон не имеет смысла в Python, где модуль (а не класс) является единицей декомпозиции программного обеспечения.33753376### Добавление обработчиков, отличных от [`NullHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.NullHandler), к логгеру в библиотеке33773378Настройка логирования путём добавления обработчиков, форматировщиков и фильтров – это ответственность разработчика приложения, а не разработчика библиотеки. Если вы поддерживаете библиотеку, убедитесь, что не добавляете обработчики ни к одному из своих логгеров, кроме экземпляра [`NullHandler`](https://python-all.ru/3.11/library/logging.handlers.html#logging.NullHandler).33793380### Создание большого количества логгеров33813382Логгеры – это синглтоны, которые никогда не освобождаются во время выполнения скрипта, поэтому создание большого количества логгеров приведёт к расходу памяти, которую затем нельзя освободить. Вместо того чтобы создавать логгер для каждого обрабатываемого файла или сетевого соединения, используйте [существующие механизмы](https://python-all.ru/3.11/howto/logging-cookbook.html#context-info) для передачи контекстной информации в ваши журналы и ограничьте создаваемые логгеры теми, которые описывают области вашего приложения (обычно модули, но иногда и с чуть большей детализацией).33833384## Другие ресурсы33853386> **См. также**3387>3388> **Модуль [`logging`](https://python-all.ru/3.11/library/logging.html#module-logging)**3389>3390> Справочник API для модуля logging.3391>3392> **Модуль [`logging.config`](https://python-all.ru/3.11/library/logging.config.html#module-logging.config)**3393>3394> API конфигурации для модуля logging.3395>3396> **Модуль [`logging.handlers`](https://python-all.ru/3.11/library/logging.handlers.html#module-logging.handlers)**3397>3398> Полезные обработчики, входящие в состав модуля logging.3399>3400> [Базовое руководство](https://python-all.ru/3.11/howto/logging.html#logging-basic-tutorial)3401>3402> [Продвинутое руководство](https://python-all.ru/3.11/howto/logging.html#logging-advanced-tutorial)3403