logging-cookbook.md
1> **Источник:** https://python-all.ru/3.15/howto/logging-cookbook.html2>3> «Документация Python на русском» – неофициальный перевод официальной документации Python: версии от 2.6 до 3.16, полнотекстовый поиск, английский оригинал рядом с переводом. Эта Markdown-версия страницы предназначена для работы с LLM: вставьте её в ChatGPT, Claude или Cursor.45---67# Сборник рецептов по логированию89На этой странице собрано несколько рецептов по логированию, которые оказались полезными. Ссылки на учебные и справочные материалы см. в разделе [Другие ресурсы](https://python-all.ru/3.15/howto/logging-cookbook.html#cookbook-ref-links).1011## Использование логирования в нескольких модулях1213Многократные вызовы `logging.getLogger('someLogger')` возвращают ссылку на один и тот же объект логгера. Это верно не только в пределах одного модуля, но и для разных модулей, если они выполняются в одном процессе интерпретатора Python. Кроме того, код приложения может определить и настроить родительский логгер в одном модуле, а затем создать (но не настраивать) дочерний логгер в другом модуле – все вызовы логгера у дочернего будут передаваться родительскому. Вот главный модуль:1415```python16import logging17import auxiliary_module1819# создать логгер с именем 'spam_application'20logger = logging.getLogger('spam_application')21logger.setLevel(logging.DEBUG)22# создать файловый обработчик, записывающий даже отладочные сообщения23fh = logging.FileHandler('spam.log')24fh.setLevel(logging.DEBUG)25# создать консольный обработчик с более высоким уровнем логирования26ch = logging.StreamHandler()27ch.setLevel(logging.ERROR)28# создать форматтер и добавить его к обработчикам29formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')30fh.setFormatter(formatter)31ch.setFormatter(formatter)32# добавить обработчики к логгеру33logger.addHandler(fh)34logger.addHandler(ch)3536logger.info('creating an instance of auxiliary_module.Auxiliary')37a = auxiliary_module.Auxiliary()38logger.info('created an instance of auxiliary_module.Auxiliary')39logger.info('calling auxiliary_module.Auxiliary.do_something')40a.do_something()41logger.info('finished auxiliary_module.Auxiliary.do_something')42logger.info('calling auxiliary_module.some_function()')43auxiliary_module.some_function()44logger.info('done with auxiliary_module.some_function()')45```4647А вот вспомогательный модуль:4849```python50import logging5152# создать логгер53module_logger = logging.getLogger('spam_application.auxiliary')5455class Auxiliary:56 def __init__(self):57 self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')58 self.logger.info('creating an instance of Auxiliary')5960 def do_something(self):61 self.logger.info('doing something')62 a = 1 + 163 self.logger.info('done doing something')6465def some_function():66 module_logger.info('received a call to "some_function"')67```6869Вывод выглядит так:7071```text722005-03-23 23:47:11,663 - spam_application - INFO -73 creating an instance of auxiliary_module.Auxiliary742005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -75 creating an instance of Auxiliary762005-03-23 23:47:11,665 - spam_application - INFO -77 created an instance of auxiliary_module.Auxiliary782005-03-23 23:47:11,668 - spam_application - INFO -79 calling auxiliary_module.Auxiliary.do_something802005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -81 doing something822005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -83 done doing something842005-03-23 23:47:11,670 - spam_application - INFO -85 finished auxiliary_module.Auxiliary.do_something862005-03-23 23:47:11,671 - spam_application - INFO -87 calling auxiliary_module.some_function()882005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -89 received a call to 'some_function'902005-03-23 23:47:11,673 - spam_application - INFO -91 done with auxiliary_module.some_function()92```9394## Журналирование из нескольких потоков9596Журналирование из нескольких потоков не требует особых усилий. В следующем примере показано журналирование из главного (начального) потока и ещё одного потока:9798```python99import logging100import threading101import time102103def worker(arg):104 while not arg['stop']:105 logging.debug('Hi from myfunc')106 time.sleep(0.5)107108def main():109 logging.basicConfig(level=logging.DEBUG, format='%(relativeCreated)6d %(threadName)s %(message)s')110 info = {'stop': False}111 thread = threading.Thread(target=worker, args=(info,))112 thread.start()113 while True:114 try:115 logging.debug('Hello from main')116 time.sleep(0.75)117 except KeyboardInterrupt:118 info['stop'] = True119 break120 thread.join()121122if __name__ == '__main__':123 main()124```125126При запуске скрипт должен вывести что-то вроде следующего:127128```text129 0 Thread-1 Hi from myfunc130 3 MainThread Hello from main131 505 Thread-1 Hi from myfunc132 755 MainThread Hello from main1331007 Thread-1 Hi from myfunc1341507 MainThread Hello from main1351508 Thread-1 Hi from myfunc1362010 Thread-1 Hi from myfunc1372258 MainThread Hello from main1382512 Thread-1 Hi from myfunc1393009 MainThread Hello from main1403013 Thread-1 Hi from myfunc1413515 Thread-1 Hi from myfunc1423761 MainThread Hello from main1434017 Thread-1 Hi from myfunc1444513 MainThread Hello from main1454518 Thread-1 Hi from myfunc146```147148Как и следовало ожидать, вывод журнала перемежается. Разумеется, такой подход работает и для большего количества потоков, чем показано здесь.149150## Несколько обработчиков и форматировщиков151152Логгеры – это обычные объекты Python. У метода [`addHandler()`](https://python-all.ru/3.15/library/logging.html#logging.Logger.addHandler) нет минимального или максимального ограничения на количество добавляемых обработчиков. Иногда приложению полезно записывать все сообщения всех уровней в текстовый файл и одновременно выводить ошибки и сообщения выше в консоль. Чтобы это настроить, достаточно сконфигурировать нужные обработчики. Вызовы журналирования в коде приложения останутся без изменений. Вот небольшая модификация предыдущего простого примера конфигурации на основе модуля:153154```python155import logging156157logger = logging.getLogger('simple_example')158logger.setLevel(logging.DEBUG)159# создать файловый обработчик, записывающий даже отладочные сообщения160fh = logging.FileHandler('spam.log')161fh.setLevel(logging.DEBUG)162# создать консольный обработчик с более высоким уровнем логирования163ch = logging.StreamHandler()164ch.setLevel(logging.ERROR)165# создать форматтер и добавить его к обработчикам166formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')167ch.setFormatter(formatter)168fh.setFormatter(formatter)169# добавить обработчики в логгер170logger.addHandler(ch)171logger.addHandler(fh)172173# код 'приложения'174logger.debug('debug message')175logger.info('info message')176logger.warning('warn message')177logger.error('error message')178logger.critical('critical message')179```180181Обратите внимание, что «прикладной» код не заботится о нескольких обработчиках. Единственное, что изменилось – добавление и настройка нового обработчика с именем *fh*.182183Возможность создавать новые обработчики с фильтрами более высокого или низкого уровня очень полезна при написании и тестировании приложения. Вместо множества операторов `print` для отладки используйте `logger.debug`: в отличие от операторов print, которые позже придётся удалять или закомментировать, вызовы logger.debug могут оставаться в исходном коде и оставаться неактивными, пока они снова не понадобятся. В тот момент единственное, что нужно изменить – уровень журналирования логгера и/или обработчика на DEBUG.184185## Журналирование в несколько мест назначения186187Допустим, вы хотите вести журнал в консоль и файл с разными форматами сообщений и в разных ситуациях. Предположим, вы хотите записывать сообщения уровня DEBUG и выше в файл, а сообщения уровня INFO и выше – в консоль. Также предположим, что файл должен содержать временные метки, а консольные сообщения – нет. Вот как это можно сделать:188189```python190import logging191192# настроить логирование в файл – подробнее см. предыдущий раздел193logging.basicConfig(level=logging.DEBUG,194 format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',195 datefmt='%m-%d %H:%M',196 filename='/tmp/myapp.log',197 filemode='w')198# Определяет обработчик, который записывает сообщения уровня INFO и выше в sys.stderr.199console = logging.StreamHandler()200console.setLevel(logging.INFO)201# Задает формат, упрощенный для вывода в консоль.202formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')203# Указывает обработчику использовать этот формат.204console.setFormatter(formatter)205# Добавляет обработчик в корневой логгер.206logging.getLogger().addHandler(console)207208# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...209logging.info('Jackdaws love my big sphinx of quartz.')210211# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:212# приложение:213214logger1 = logging.getLogger('myapp.area1')215logger2 = logging.getLogger('myapp.area2')216217logger1.debug('Quick zephyrs blow, vexing daft Jim.')218logger1.info('How quickly daft jumping zebras vex.')219logger2.warning('Jail zesty vixen who grabbed pay from quack.')220logger2.error('The five boxing wizards jump quickly.')221```222223При запуске на консоли вы увидите224225```text226root : INFO Jackdaws love my big sphinx of quartz.227myapp.area1 : INFO How quickly daft jumping zebras vex.228myapp.area2 : WARNING Jail zesty vixen who grabbed pay from quack.229myapp.area2 : ERROR The five boxing wizards jump quickly.230```231232а в файле увидите примерно такое233234```text23510-22 22:19 root INFO Jackdaws love my big sphinx of quartz.23610-22 22:19 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim.23710-22 22:19 myapp.area1 INFO How quickly daft jumping zebras vex.23810-22 22:19 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack.23910-22 22:19 myapp.area2 ERROR The five boxing wizards jump quickly.240```241242Как видите, сообщение DEBUG отображается только в файле. Остальные сообщения отправляются в оба места назначения.243244В этом примере используются консольный и файловый обработчики, но вы можете использовать любое количество и любое сочетание обработчиков по своему выбору.245246Обратите внимание, что указанное выше имя файла журнала `/tmp/myapp.log` подразумевает использование стандартного расположения временных файлов в системах POSIX. В Windows может потребоваться выбрать другое имя каталога для журнала – просто убедитесь, что каталог существует и у вас есть права на создание и обновление файлов в нём.247248## Пользовательская обработка уровней249250Иногда может потребоваться немного отойти от стандартной обработки уровней в обработчиках, когда все уровни выше порога обрабатываются одним обработчиком. Для этого нужно использовать фильтры. Рассмотрим сценарий, в котором требуется организовать работу следующим образом:251252- Отправлять сообщения уровня `INFO` и `WARNING` в `sys.stdout`253- Отправлять сообщения уровня `ERROR` и выше в `sys.stderr`254- Отправлять сообщения уровня `DEBUG` и выше в файл `app.log`255256Предположим, вы настраиваете журналирование с помощью следующего JSON:257258```json259{260 "version": 1,261 "disable_existing_loggers": false,262 "formatters": {263 "simple": {264 "format": "%(levelname)-8s - %(message)s"265 }266 },267 "handlers": {268 "stdout": {269 "class": "logging.StreamHandler",270 "level": "INFO",271 "formatter": "simple",272 "stream": "ext://sys.stdout"273 },274 "stderr": {275 "class": "logging.StreamHandler",276 "level": "ERROR",277 "formatter": "simple",278 "stream": "ext://sys.stderr"279 },280 "file": {281 "class": "logging.FileHandler",282 "formatter": "simple",283 "filename": "app.log",284 "mode": "w"285 }286 },287 "root": {288 "level": "DEBUG",289 "handlers": [290 "stderr",291 "stdout",292 "file"293 ]294 }295}296```297298Эта конфигурация делает *почти* то, что нам нужно, за исключением того, что `sys.stdout` будет показывать сообщения уровня `ERROR`, и будут отслеживаться только события этого уровня и выше, а также сообщения `INFO` и `WARNING`. Чтобы этого избежать, можно настроить фильтр, исключающий эти сообщения, и добавить его к соответствующему обработчику. Это настраивается добавлением раздела `filters` параллельно `formatters` и `handlers`:299300```json301{302 "filters": {303 "warnings_and_below": {304 "()" : "__main__.filter_maker",305 "level": "WARNING"306 }307 }308}309```310311и изменив раздел обработчика `stdout`, чтобы добавить его:312313```json314{315 "stdout": {316 "class": "logging.StreamHandler",317 "level": "INFO",318 "formatter": "simple",319 "stream": "ext://sys.stdout",320 "filters": ["warnings_and_below"]321 }322}323```324325Фильтр – это просто функция, поэтому можно определить `filter_maker` (фабричную функцию) следующим образом:326327```python328def filter_maker(level):329 level = getattr(logging, level)330331 def filter(record):332 return record.levelno <= level333334 return filter335```336337Это преобразует переданный строковый аргумент в числовой уровень и возвращает функцию, которая возвращает `True` только в том случае, если уровень переданной записи меньше или равен указанному уровню. Обратите внимание, что в этом примере я определил `filter_maker` в тестовом скрипте `main.py`, который запускаю из командной строки, поэтому его модуль будет `__main__` – отсюда `__main__.filter_maker` в конфигурации фильтра. Вам нужно будет изменить это, если вы определите его в другом модуле.338339После добавления фильтра можно запустить `main.py`, полная версия которого:340341```python342import json343import logging344import logging.config345346CONFIG = '''347{348 "version": 1,349 "disable_existing_loggers": false,350 "formatters": {351 "simple": {352 "format": "%(levelname)-8s - %(message)s"353 }354 },355 "filters": {356 "warnings_and_below": {357 "()" : "__main__.filter_maker",358 "level": "WARNING"359 }360 },361 "handlers": {362 "stdout": {363 "class": "logging.StreamHandler",364 "level": "INFO",365 "formatter": "simple",366 "stream": "ext://sys.stdout",367 "filters": ["warnings_and_below"]368 },369 "stderr": {370 "class": "logging.StreamHandler",371 "level": "ERROR",372 "formatter": "simple",373 "stream": "ext://sys.stderr"374 },375 "file": {376 "class": "logging.FileHandler",377 "formatter": "simple",378 "filename": "app.log",379 "mode": "w"380 }381 },382 "root": {383 "level": "DEBUG",384 "handlers": [385 "stderr",386 "stdout",387 "file"388 ]389 }390}391'''392393def filter_maker(level):394 level = getattr(logging, level)395396 def filter(record):397 return record.levelno <= level398399 return filter400401logging.config.dictConfig(json.loads(CONFIG))402logging.debug('A DEBUG message')403logging.info('An INFO message')404logging.warning('A WARNING message')405logging.error('An ERROR message')406logging.critical('A CRITICAL message')407```408409И после запуска вот так:410411```shell412python main.py 2>stderr.log >stdout.log413```414415Мы видим, что результаты соответствуют ожиданиям:416417```shell418$ more *.log419::::::::::::::420app.log421::::::::::::::422DEBUG - A DEBUG message423INFO - An INFO message424WARNING - A WARNING message425ERROR - An ERROR message426CRITICAL - A CRITICAL message427::::::::::::::428stderr.log429::::::::::::::430ERROR - An ERROR message431CRITICAL - A CRITICAL message432::::::::::::::433stdout.log434::::::::::::::435INFO - An INFO message436WARNING - A WARNING message437```438439## Пример сервера конфигурации440441Вот пример модуля, использующего сервер конфигурации журналирования:442443```python444import logging445import logging.config446import time447import os448449# Прочитать начальный конфигурационный файл.450logging.config.fileConfig('logging.conf')451452# Создать и запустить слушатель на порту 9999.453t = logging.config.listen(9999)454t.start()455456logger = logging.getLogger('simpleExample')457458try:459 # Прокрутить вызовы логирования, чтобы увидеть разницу.460 # Создавать новые конфигурации до нажатия Ctrl+C.461 while True:462 logger.debug('debug message')463 logger.info('info message')464 logger.warning('warn message')465 logger.error('error message')466 logger.critical('critical message')467 time.sleep(5)468except KeyboardInterrupt:469 # очистка470 logging.config.stopListening()471 t.join()472```473474А вот скрипт, который принимает имя файла и отправляет этот файл на сервер, предварив его двоично-закодированной длиной, в качестве новой конфигурации журналирования:475476```python477#!/usr/bin/env python478import socket, sys, struct479480with open(sys.argv[1], 'rb') as f:481 data_to_send = f.read()482483HOST = 'localhost'484PORT = 9999485s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)486print('connecting...')487s.connect((HOST, PORT))488print('sending config...')489s.send(struct.pack('>L', len(data_to_send)))490s.send(data_to_send)491s.close()492print('complete')493```494495## Работа с блокирующими обработчиками496497Иногда нужно, чтобы ваши обработчики логирования выполняли свою работу без блокировки потока, из которого ведётся логирование. Это часто встречается в веб-приложениях, хотя, конечно, бывает и в других сценариях.498499Типичный виновник медленной работы – [`SMTPHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.SMTPHandler): отправка электронной почты может занимать много времени по ряду причин, не зависящих от разработчика (например, из-за плохой работы почтовой или сетевой инфраструктуры). Но почти любой сетевой обработчик может блокировать: даже операция [`SocketHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.SocketHandler) может выполнять DNS-запрос «под капотом», который оказывается слишком медленным (и этот запрос может быть глубоко в коде библиотеки сокетов, ниже уровня Python и вне вашего контроля).500501Одно из решений – использовать двухчастный подход. На первом этапе к логгерам, к которым обращаются из критичных по производительности потоков, следует подключать только [`QueueHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.QueueHandler). Они просто пишут в свою очередь, которую можно настроить на достаточно большую ёмкость или инициализировать без верхнего ограничения размера. Запись в очередь обычно выполняется быстро, хотя в коде желательно перехватывать исключение [`queue.Full`](https://python-all.ru/3.15/library/queue.html#queue.Full) на всякий случай. Если вы – разработчик библиотеки, в коде которой есть критичные по производительности потоки, обязательно задокументируйте это (вместе с рекомендацией подключать к вашим логгерам только `QueueHandlers`) для пользы других разработчиков, которые будут использовать ваш код.502503Вторая часть решения – [`QueueListener`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.QueueListener), который был разработан как аналог [`QueueHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.QueueHandler). `QueueListener` устроен очень просто: ему передаётся очередь и несколько обработчиков, и он запускает внутренний поток, который слушает свою очередь на предмет LogRecords, отправленных из `QueueHandlers` (или любого другого источника `LogRecords`). `LogRecords` извлекаются из очереди и передаются обработчикам для обработки.504505Преимущество отдельного класса [`QueueListener`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.QueueListener) в том, что один его экземпляр может обслуживать несколько `QueueHandlers`. Это более экономит ресурсы, чем, скажем, многопоточные версии существующих классов обработчиков, которые расходовали бы по одному потоку на обработчик без особой пользы.506507Ниже приведён пример использования этих двух классов (импорты опущены):508509```python510que = queue.Queue(-1) # Без ограничения размера.511queue_handler = QueueHandler(que)512handler = logging.StreamHandler()513listener = QueueListener(que, handler)514root = logging.getLogger()515root.addHandler(queue_handler)516formatter = logging.Formatter('%(threadName)s: %(message)s')517handler.setFormatter(formatter)518listener.start()519# Вывод лога будет отображать поток, создавший событие (главный поток), а не внутренний поток,520# отслеживающий внутреннюю очередь.521# Именно это и должно происходить.522# то, что должно произойти.523root.warning('Look out!')524listener.stop()525```526527который при запуске выведет:528529```text530MainThread: Look out!531```532533> **Примечание**534>535> Хотя предыдущее обсуждение не касалось напрямую асинхронного кода, а скорее медленных обработчиков логирования, следует отметить, что при логировании из асинхронного кода сетевые и даже файловые обработчики могут приводить к проблемам (блокировать цикл событий), поскольку часть логирования выполняется внутри [`asyncio`](https://python-all.ru/3.15/library/asyncio.html#module-asyncio). Поэтому, если в приложении используется асинхронный код, лучше всего применять описанный выше подход к логированию, чтобы любой блокирующий код выполнялся только в `QueueListener` потоке.536537Изменено в версии 3.5: До Python 3.5 [`QueueListener`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.QueueListener) всегда передавал каждое полученное из очереди сообщение каждому обработчику, с которыми был инициализирован. (Это объяснялось тем, что предполагалось, что фильтрация по уровню полностью выполняется на стороне наполнения очереди.) Начиная с версии 3.5 это поведение можно изменить, передав именованный аргумент `respect_handler_level=True` конструктору слушателя. Когда это сделано, слушатель сравнивает уровень каждого сообщения с уровнем обработчика и передаёт сообщение обработчику, только если это уместно.538539Изменено в версии 3.14: [`QueueListener`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.QueueListener) можно запускать (и останавливать) через оператор [`with`](https://python-all.ru/3.15/reference/compound_stmts.html#with). Например:540541```python542with QueueListener(que, handler) as listener:543 # Слушатель очереди автоматически запускается при входе в блок 'with'.544 # когда входим в блок 'with'.545 pass546# Слушатель очереди автоматически останавливается при выходе из блока 'with'.547# когда выходим из блока 'with'.548```549550## Отправка и получение событий логирования по сети551552Допустим, вы хотите отправлять события логирования по сети и обрабатывать их на принимающей стороне. Простой способ – подключить экземпляр [`SocketHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.SocketHandler) к корневому логгеру на отправляющей стороне:553554```python555import logging, logging.handlers556557rootLogger = logging.getLogger()558rootLogger.setLevel(logging.DEBUG)559socketHandler = logging.handlers.SocketHandler('localhost',560 logging.handlers.DEFAULT_TCP_LOGGING_PORT)561# Не нужно использовать форматтер, так как сокет-обработчик отправляет событие в виде неформатированного пикла.562# неформатированный pickle563rootLogger.addHandler(socketHandler)564565# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...566logging.info('Jackdaws love my big sphinx of quartz.')567568# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:569# приложение:570571logger1 = logging.getLogger('myapp.area1')572logger2 = logging.getLogger('myapp.area2')573574logger1.debug('Quick zephyrs blow, vexing daft Jim.')575logger1.info('How quickly daft jumping zebras vex.')576logger2.warning('Jail zesty vixen who grabbed pay from quack.')577logger2.error('The five boxing wizards jump quickly.')578```579580На принимающей стороне можно настроить приёмник с помощью модуля [`socketserver`](https://python-all.ru/3.15/library/socketserver.html#module-socketserver). Вот простой работающий пример:581582```python583import pickle584import logging585import logging.handlers586import socketserver587import struct588589class LogRecordStreamHandler(socketserver.StreamRequestHandler):590 """Обработчик для потокового запроса логирования.591592 Это по сути записывает запись, используя ту политику логирования, которая настроена локально.593 настроено локально.594 """595596 def handle(self):597 """598 Обрабатывает несколько запросов – каждый ожидается в формате: 4-байтовая длина, затем запись журнала в формате пикл.599 Записывает запись в соответствии с политикой, настроенной локально.600 согласно локально настроенной политике.601 """602 while True:603 chunk = self.connection.recv(4)604 if len(chunk) < 4:605 break606 slen = struct.unpack('>L', chunk)[0]607 chunk = self.connection.recv(slen)608 while len(chunk) < slen:609 chunk = chunk + self.connection.recv(slen - len(chunk))610 obj = self.unPickle(chunk)611 record = logging.makeLogRecord(obj)612 self.handleLogRecord(record)613614 def unPickle(self, data):615 return pickle.loads(data)616617 def handleLogRecord(self, record):618 # Если указано имя, используется именованный логгер, а не тот, что619 # подразумевается записью.620 if self.server.logname is not None:621 name = self.server.logname622 else:623 name = record.name624 logger = logging.getLogger(name)625 # Примечание: КАЖДАЯ запись попадает в журнал. Это связано с тем, что Logger.handle626 # обычно вызывается ПОСЛЕ фильтрации на уровне регистратора. Если требуется627 # выполнять фильтрацию, делайте это на стороне клиента, чтобы не тратить628 # циклы процессора и сетевую пропускную способность!629 logger.handle(record)630631class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):632 """633 Простой приёмник журнала на основе TCP-сокетов, подходящий для тестирования.634 """635636 allow_reuse_address = True637638 def __init__(self, host='localhost',639 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,640 handler=LogRecordStreamHandler):641 socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)642 self.abort = 0643 self.timeout = 1644 self.logname = None645646 def serve_until_stopped(self):647 import select648 abort = 0649 while not abort:650 rd, wr, ex = select.select([self.socket.fileno()],651 [], [],652 self.timeout)653 if rd:654 self.handle_request()655 abort = self.abort656657def main():658 logging.basicConfig(659 format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')660 tcpserver = LogRecordSocketReceiver()661 print('About to start TCP server...')662 tcpserver.serve_until_stopped()663664if __name__ == '__main__':665 main()666```667668Сначала запустите сервер, затем клиент. На стороне клиента в консоль ничего не выводится; на стороне сервера вы должны увидеть что-то вроде:669670```text671About to start TCP server...672 59 root INFO Jackdaws love my big sphinx of quartz.673 59 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim.674 69 myapp.area1 INFO How quickly daft jumping zebras vex.675 69 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack.676 69 myapp.area2 ERROR The five boxing wizards jump quickly.677```678679Обратите внимание, что в некоторых сценариях существуют проблемы безопасности с pickle. Если они вас затрагивают, вы можете использовать альтернативную схему сериализации, переопределив метод [`makePickle()`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.SocketHandler.makePickle) и реализовав свою альтернативу там, а также адаптировав вышеприведённый скрипт для использования вашей альтернативной сериализации.680681### Запуск сокетного слушателя логирования в продакшене682683Для запуска слушателя логирования в продакшене может потребоваться инструмент управления процессами, такой как [Supervisor](https://python-all.ru/3.15/howto/logging-cookbook.html). [Вот Gist](https://python-all.ru/3.15/howto/logging-cookbook.html), который содержит минимальные файлы для запуска описанной выше функциональности с помощью Supervisor. Он состоит из следующих файлов:684685| Файл | Назначение |686| --- | --- |687| `prepare.sh` | Bash-скрипт для подготовки окружения к тестированию |688| `supervisor.conf` | Файл конфигурации Supervisor с записями для слушателя и многопроцессного веб-приложения |689| `ensure_app.sh` | Bash-скрипт для обеспечения работы Supervisor с указанной конфигурацией |690| `log_listener.py` | Программа сокетного слушателя, которая получает события логирования и записывает их в файл |691| `main.py` | Простое веб-приложение, которое выполняет логирование через сокет, подключённый к слушателю |692| `webapp.json` | JSON-файл конфигурации для веб-приложения |693| `client.py` | Python-скрипт для тестирования веб-приложения |694695Веб-приложение использует [Gunicorn](https://python-all.ru/3.15/howto/logging-cookbook.html) – популярный сервер веб-приложений, который запускает несколько рабочих процессов для обработки запросов. Данный пример показывает, как рабочие процессы могут писать в один и тот же файл журнала, не мешая друг другу – все они проходят через сокетный слушатель.696697Чтобы протестировать эти файлы, выполните следующие действия в среде POSIX:6986991. Скачайте [Gist](https://python-all.ru/3.15/howto/logging-cookbook.html) в виде ZIP-архива, используя кнопку Download ZIP.7002. Распакуйте указанные файлы из архива во временный каталог.7013. Во временном каталоге выполните `bash prepare.sh` для подготовки. При этом будут созданы подкаталог `run` для файлов, связанных с Supervisor, и журналов, а также подкаталог `venv` для виртуального окружения, в которое будут установлены `bottle`, `gunicorn` и `supervisor`.7024. Запустите `bash ensure_app.sh`, чтобы убедиться, что Supervisor работает с указанной выше конфигурацией.7035. Запустите `venv/bin/python client.py` для проверки веб-приложения, что приведёт к записи данных в журнал.7046. Проверьте файлы журнала в подкаталоге `run`. Вы должны увидеть самые свежие строки журнала в файлах, соответствующих шаблону `app.log*`. Они не будут в каком-либо определённом порядке, так как были обработаны параллельно разными рабочими процессами недетерминированным образом.7057. Вы можете остановить слушатель и веб-приложение, выполнив `venv/bin/supervisorctl -c supervisor.conf shutdown`.706707Возможно, потребуется подправить файлы конфигурации в маловероятном случае, если настроенные порты конфликтуют с чем-либо ещё в вашей тестовой среде.708709В конфигурации по умолчанию используется TCP-сокет на порту 9020. Вы можете использовать сокет Unix Domain вместо TCP-сокета, выполнив следующее:7107111. В `listener.json` добавьте ключ `socket` с путём к доменному сокету, который вы хотите использовать. Если этот ключ присутствует, слушатель прослушивает соответствующий доменный сокет, а не TCP-сокет (ключ `port` игнорируется).7122. В `webapp.json` измените словарь конфигурации обработчика сокетов так, чтобы значением `host` был путь к доменному сокету, а значение `port` установите в `null`.713714## Добавление контекстной информации в вывод журнала715716Иногда требуется, чтобы вывод журнала содержал контекстную информацию в дополнение к параметрам, переданным в вызове логирования. Например, в сетевом приложении может быть желательно записывать в журнал информацию, специфичную для клиента (например, имя пользователя удалённого клиента или IP-адрес). Хотя для этого можно использовать параметр *extra*, не всегда удобно передавать информацию таким образом. Может возникнуть соблазн создавать экземпляры [`Logger`](https://python-all.ru/3.15/library/logging.html#logging.Logger) для каждого соединения, но это плохая идея, поскольку такие экземпляры не собираются сборщиком мусора. Хотя на практике это не проблема, когда количество экземпляров `Logger` зависит от уровня детализации, используемого при логировании приложения, управление ими может стать сложным, если количество экземпляров `Logger` станет фактически неограниченным.717718### Использование LoggerAdapter для добавления контекстной информации719720Простой способ передавать контекстную информацию для вывода вместе с информацией о событиях логирования – использовать класс [`LoggerAdapter`](https://python-all.ru/3.15/library/logging.html#logging.LoggerAdapter). Этот класс спроектирован так, чтобы выглядеть как [`Logger`](https://python-all.ru/3.15/library/logging.html#logging.Logger), что позволяет вызывать [`debug()`](https://python-all.ru/3.15/library/logging.html#logging.debug), [`info()`](https://python-all.ru/3.15/library/logging.html#logging.info), [`warning()`](https://python-all.ru/3.15/library/logging.html#logging.warning), [`error()`](https://python-all.ru/3.15/library/logging.html#logging.error), [`exception()`](https://python-all.ru/3.15/library/logging.html#logging.exception), [`critical()`](https://python-all.ru/3.15/library/logging.html#logging.critical) и [`log()`](https://python-all.ru/3.15/library/logging.html#logging.log). Эти методы имеют те же сигнатуры, что и их аналоги в `Logger`, поэтому экземпляры обоих типов можно использовать взаимозаменяемо.721722При создании экземпляра [`LoggerAdapter`](https://python-all.ru/3.15/library/logging.html#logging.LoggerAdapter) вы передаёте ему экземпляр [`Logger`](https://python-all.ru/3.15/library/logging.html#logging.Logger) и объект, подобный словарю, содержащий вашу контекстную информацию. Когда вы вызываете один из методов логирования на экземпляре `LoggerAdapter`, он делегирует вызов базовому экземпляру `Logger`, переданному в конструктор, и организует передачу контекстной информации в этом делегированном вызове. Вот фрагмент кода `LoggerAdapter`:723724```python725def debug(self, msg, /, *args, **kwargs):726 """727 Передаёт вызов отладки нижележащему регистратору после добавления728 контекстной информации из данного экземпляра адаптера.729 """730 msg, kwargs = self.process(msg, kwargs)731 self.logger.debug(msg, *args, **kwargs)732```733734Метод [`process()`](https://python-all.ru/3.15/library/logging.html#logging.LoggerAdapter.process) класса [`LoggerAdapter`](https://python-all.ru/3.15/library/logging.html#logging.LoggerAdapter) – это то место, где контекстная информация добавляется в вывод журнала. Ему передаются сообщение и именованные аргументы вызова логирования, а он возвращает (потенциально) изменённые версии для использования в вызове базового регистратора. В реализации по умолчанию этот метод оставляет сообщение без изменений, но вставляет ключ 'extra' в именованные аргументы, значением которого является объект, подобный словарю, переданный конструктору. Конечно, если вы передали именованный аргумент 'extra' в вызове адаптера, он будет молча перезаписан.735736Преимущество использования 'extra' в том, что значения из объекта, подобного словарю, сливаются в \_\_dict\_\_ экземпляра [`LogRecord`](https://python-all.ru/3.15/library/logging.html#logging.LogRecord), что позволяет использовать настроенные строки с экземплярами [`Formatter`](https://python-all.ru/3.15/library/logging.html#logging.Formatter), которые знают о ключах этого объекта. Если вам нужен другой метод, например, добавить контекстную информацию в начало или конец строки сообщения, достаточно создать подкласс [`LoggerAdapter`](https://python-all.ru/3.15/library/logging.html#logging.LoggerAdapter) и переопределить [`process()`](https://python-all.ru/3.15/library/logging.html#logging.LoggerAdapter.process) для нужного поведения. Вот простой пример:737738```python739class CustomAdapter(logging.LoggerAdapter):740 """741 Данный пример адаптера ожидает, что переданный объект, подобный словарю, содержит742 ключ 'connid', значение которого в квадратных скобках добавляется к началу сообщения журнала.743 """744 def process(self, msg, kwargs):745 return '[%s] %s' % (self.extra['connid'], msg), kwargs746```747748который можно использовать так:749750```python751logger = logging.getLogger(__name__)752adapter = CustomAdapter(logger, {'connid': some_conn_id})753```754755Тогда все события, регистрируемые через адаптер, будут содержать значение `some_conn_id`, добавленное в начало сообщений журнала.756757#### Использование объектов, отличных от словарей, для передачи контекстной информации758759Необязательно передавать в [`LoggerAdapter`](https://python-all.ru/3.15/library/logging.html#logging.LoggerAdapter) именно словарь – можно передать экземпляр класса, реализующего `__getitem__` и `__iter__`, чтобы он выглядел как словарь для системы логирования. Это полезно, если нужно генерировать значения динамически (тогда как значения в словаре были бы постоянными).760761### Использование фильтров для добавления контекстной информации762763Вы также можете добавлять контекстную информацию в вывод журнала с помощью определённого пользователем [`Filter`](https://python-all.ru/3.15/library/logging.html#logging.Filter). Экземплярам `Filter` разрешено изменять `LogRecords`, переданный им, включая добавление дополнительных атрибутов, которые затем можно выводить с помощью подходящей форматной строки или, если необходимо, пользовательского [`Formatter`](https://python-all.ru/3.15/library/logging.html#logging.Formatter).764765Например, в веб-приложении обрабатываемый запрос (или, по крайней мере, его интересные части) можно сохранить в потоковой локальной переменной ([`threading.local`](https://python-all.ru/3.15/library/threading.html#threading.local)), а затем из `Filter` получить к ней доступ, чтобы добавить, скажем, информацию из запроса – например, удалённый IP-адрес и имя пользователя – в `LogRecord`, используя имена атрибутов 'ip' и 'user', как в примере с `LoggerAdapter` выше. В этом случае можно использовать ту же форматную строку для получения вывода, аналогичного показанному выше. Вот пример скрипта:766767```python768import logging769from random import choice770771class ContextFilter(logging.Filter):772 """773 Это фильтр, который внедряет контекстную информацию в журнал.774775 Вместо использования реальной контекстной информации в данном примере используются случайные776 данные.777 """778779 USERS = ['jim', 'fred', 'sheila']780 IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']781782 def filter(self, record):783784 record.ip = choice(ContextFilter.IPS)785 record.user = choice(ContextFilter.USERS)786 return True787788if __name__ == '__main__':789 levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)790 logging.basicConfig(level=logging.DEBUG,791 format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')792 a1 = logging.getLogger('a.b.c')793 a2 = logging.getLogger('d.e.f')794795 f = ContextFilter()796 a1.addFilter(f)797 a2.addFilter(f)798 a1.debug('A debug message')799 a1.info('An info message with %s', 'some parameters')800 for x in range(10):801 lvl = choice(levels)802 lvlname = logging.getLevelName(lvl)803 a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')804```805806который при запуске выдаёт примерно следующее:807808```text8092010-09-06 22:38:15,292 a.b.c DEBUG IP: 123.231.231.123 User: fred A debug message8102010-09-06 22:38:15,300 a.b.c INFO IP: 192.168.0.1 User: sheila An info message with some parameters8112010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters8122010-09-06 22:38:15,300 d.e.f ERROR IP: 127.0.0.1 User: jim A message at ERROR level with 2 parameters8132010-09-06 22:38:15,300 d.e.f DEBUG IP: 127.0.0.1 User: sheila A message at DEBUG level with 2 parameters8142010-09-06 22:38:15,300 d.e.f ERROR IP: 123.231.231.123 User: fred A message at ERROR level with 2 parameters8152010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1 User: jim A message at CRITICAL level with 2 parameters8162010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters8172010-09-06 22:38:15,300 d.e.f DEBUG IP: 192.168.0.1 User: jim A message at DEBUG level with 2 parameters8182010-09-06 22:38:15,301 d.e.f ERROR IP: 127.0.0.1 User: sheila A message at ERROR level with 2 parameters8192010-09-06 22:38:15,301 d.e.f DEBUG IP: 123.231.231.123 User: fred A message at DEBUG level with 2 parameters8202010-09-06 22:38:15,301 d.e.f INFO IP: 123.231.231.123 User: fred A message at INFO level with 2 parameters821```822823## Использование `contextvars`824825Начиная с Python 3.7, модуль [`contextvars`](https://python-all.ru/3.15/library/contextvars.html#module-contextvars) предоставляет контекстно-локальное хранилище, которое работает как для [`threading`](https://python-all.ru/3.15/library/threading.html#module-threading), так и для [`asyncio`](https://python-all.ru/3.15/library/asyncio.html#module-asyncio) обработки. Этот тип хранилища может быть в целом предпочтительнее потоковых локальных переменных. Следующий пример показывает, как в многопоточной среде журналы могут наполняться контекстной информацией, например, атрибутами запросов, обрабатываемых веб-приложениями.826827Для иллюстрации предположим, что у вас есть разные веб-приложения, каждое независимо от других, но запущенные в одном процессе Python и использующие общую для них библиотеку. Как каждое из этих приложений может иметь собственный журнал, где все сообщения логирования из библиотеки (и другого кода обработки запросов) направляются в соответствующий файл журнала приложения, а также включают в журнал дополнительную контекстную информацию, такую как IP-адрес клиента, метод HTTP-запроса и имя пользователя?828829Предположим, что библиотеку можно смоделировать следующим кодом:830831```python832# webapplib.py833import logging834import time835836logger = logging.getLogger(__name__)837838def useful():839 # Просто представительное событие, зарегистрированное из библиотеки840 logger.debug('Hello from webapplib!')841 # Просто приостановить выполнение на некоторое время, чтобы дать возможность другим потокам поработать842 time.sleep(0.01)843```844845Мы можем смоделировать несколько веб-приложений с помощью двух простых классов, `Request` и `WebApp`. Они имитируют работу реальных многопоточных веб-приложений – каждый запрос обрабатывается отдельным потоком:846847```python848# main.py849import argparse850from contextvars import ContextVar851import logging852import os853from random import choice854import threading855import webapplib856857logger = logging.getLogger(__name__)858root = logging.getLogger()859root.setLevel(logging.DEBUG)860861class Request:862 """863 Простой фиктивный класс запроса, который просто хранит фиктивные метод HTTP-запроса,864 IP-адрес клиента и имя пользователя клиента865 """866 def __init__(self, method, ip, user):867 self.method = method868 self.ip = ip869 self.user = user870871# Фиктивный набор запросов, который будет использоваться в симуляции – мы будем просто выбирать872# из этого списка случайным образом. Обратите внимание, что все GET-запросы приходят с адресов 192.168.2.XXX873# адресов, тогда как POST-запросы – с адресов 192.16.3.XXX. В примере запросов представлены три пользователя874# представлены в примере запросов.875876REQUESTS = [877 Request('GET', '192.168.2.20', 'jim'),878 Request('POST', '192.168.3.20', 'fred'),879 Request('GET', '192.168.2.21', 'sheila'),880 Request('POST', '192.168.3.21', 'jim'),881 Request('GET', '192.168.2.22', 'fred'),882 Request('POST', '192.168.3.22', 'sheila'),883]884885# Обратите внимание, что строка форматирования содержит ссылки на контекстную информацию запроса886# такую как HTTP-метод, IP-адрес клиента и имя пользователя887888formatter = logging.Formatter('%(threadName)-11s %(appName)s %(name)-9s %(user)-6s %(ip)s %(method)-4s %(message)s')889890# Создаём контекстные переменные. Они будут заполнены в начале обработки запроса891# и использоваться в журналировании, которое выполняется в ходе этой обработки892893ctx_request = ContextVar('request')894ctx_appname = ContextVar('appname')895896class InjectingFilter(logging.Filter):897 """898 Фильтр, который внедряет в журналы контекстно-зависимую информацию и гарантирует,899 что в его журнал включается только информация для конкретного веб-приложения900 """901 def __init__(self, app):902 self.app = app903904 def filter(self, record):905 request = ctx_request.get()906 record.method = request.method907 record.ip = request.ip908 record.user = request.user909 record.appName = appName = ctx_appname.get()910 return appName == self.app.name911912class WebApp:913 """914 Фиктивный класс веб-приложения, который имеет собственный обработчик и фильтр для915 журнала, специфичного для веб-приложения.916 """917 def __init__(self, name):918 self.name = name919 handler = logging.FileHandler(name + '.log', 'w')920 f = InjectingFilter(self)921 handler.setFormatter(formatter)922 handler.addFilter(f)923 root.addHandler(handler)924 self.num_requests = 0925926 def process_request(self, request):927 """928 Это фиктивный метод обработки запроса. Он вызывается для929 отдельный поток для каждого запроса. Сохраняем информацию контекста в930 контекстные переменные перед тем, как делать что-либо ещё.931 """932 ctx_request.set(request)933 ctx_appname.set(self.name)934 self.num_requests += 1935 logger.debug('Request processing started')936 webapplib.useful()937 logger.debug('Request processing finished')938939def main():940 fn = os.path.splitext(os.path.basename(__file__))[0]941 adhf = argparse.ArgumentDefaultsHelpFormatter942 ap = argparse.ArgumentParser(formatter_class=adhf, prog=fn,943 description='Simulate a couple of web '944 'applications handling some '945 'requests, showing how request '946 'context can be used to '947 'populate logs')948 aa = ap.add_argument949 aa('--count', '-c', type=int, default=100, help='How many requests to simulate')950 options = ap.parse_args()951952 # Создаём фиктивные веб-приложения и помещаем их в список, из которого будем выбирать953 # случайным образом.954 app1 = WebApp('app1')955 app2 = WebApp('app2')956 apps = [app1, app2]957 threads = []958 # Добавляем общий обработчик, который будет перехватывать все события.959 handler = logging.FileHandler('app.log', 'w')960 handler.setFormatter(formatter)961 root.addHandler(handler)962963 # Генерируем вызовы для обработки запросов.964 for i in range(options.count):965 try:966 # Выбираем случайное приложение и запрос для него.967 app = choice(apps)968 request = choice(REQUESTS)969 # Обрабатываем запрос в его собственном потоке.970 t = threading.Thread(target=app.process_request, args=(request,))971 threads.append(t)972 t.start()973 except KeyboardInterrupt:974 break975976 # Ждём завершения потоков.977 for t in threads:978 t.join()979980 for app in apps:981 print('%s processed %s requests' % (app.name, app.num_requests))982983if __name__ == '__main__':984 main()985```986987Если запустить приведённый выше код, вы обнаружите, что примерно половина запросов попадает в `app1.log`, а остальные – в `app2.log`, и все запросы регистрируются в `app.log`. Каждый журнал, специфичный для веб-приложения, будет содержать только записи для этого приложения, а информация о запросе будет отображаться в журнале согласованно (т.е. информация каждого фиктивного запроса всегда будет появляться вместе в одной строке журнала). Это иллюстрируется следующим выводом оболочки:988989```shell990~/logging-contextual-webapp$ python main.py991app1 processed 51 requests992app2 processed 49 requests993~/logging-contextual-webapp$ wc -l *.log994 153 app1.log995 147 app2.log996 300 app.log997 600 total998~/logging-contextual-webapp$ head -3 app1.log999Thread-3 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1000Thread-3 (process_request) app1 webapplib jim 192.168.3.21 POST Hello from webapplib!1001Thread-5 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1002~/logging-contextual-webapp$ head -3 app2.log1003Thread-1 (process_request) app2 __main__ sheila 192.168.2.21 GET Request processing started1004Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET Hello from webapplib!1005Thread-2 (process_request) app2 __main__ jim 192.168.2.20 GET Request processing started1006~/logging-contextual-webapp$ head app.log1007Thread-1 (process_request) app2 __main__ sheila 192.168.2.21 GET Request processing started1008Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET Hello from webapplib!1009Thread-2 (process_request) app2 __main__ jim 192.168.2.20 GET Request processing started1010Thread-3 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1011Thread-2 (process_request) app2 webapplib jim 192.168.2.20 GET Hello from webapplib!1012Thread-3 (process_request) app1 webapplib jim 192.168.3.21 POST Hello from webapplib!1013Thread-4 (process_request) app2 __main__ fred 192.168.2.22 GET Request processing started1014Thread-5 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1015Thread-4 (process_request) app2 webapplib fred 192.168.2.22 GET Hello from webapplib!1016Thread-6 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started1017~/logging-contextual-webapp$ grep app1 app1.log | wc -l10181531019~/logging-contextual-webapp$ grep app2 app2.log | wc -l10201471021~/logging-contextual-webapp$ grep app1 app.log | wc -l10221531023~/logging-contextual-webapp$ grep app2 app.log | wc -l10241471025```10261027## Добавление контекстной информации в обработчиках10281029Каждый [`Handler`](https://python-all.ru/3.15/library/logging.html#logging.Handler) имеет собственную цепочку фильтров. Если нужно добавить контекстную информацию в [`LogRecord`](https://python-all.ru/3.15/library/logging.html#logging.LogRecord) без её утечки в другие обработчики, можно использовать фильтр, возвращающий новый `LogRecord` вместо изменения исходного на месте, как показано в следующем скрипте:10301031```python1032import copy1033import logging10341035def filter(record: logging.LogRecord):1036 record = copy.copy(record)1037 record.user = 'jim'1038 return record10391040if __name__ == '__main__':1041 logger = logging.getLogger()1042 logger.setLevel(logging.INFO)1043 handler = logging.StreamHandler()1044 formatter = logging.Formatter('%(message)s from %(user)-8s')1045 handler.setFormatter(formatter)1046 handler.addFilter(filter)1047 logger.addHandler(handler)10481049 logger.info('A log message')1050```10511052## Ведение журнала в один файл из нескольких процессов10531054Хотя модуль logging является потокобезопасным и запись в один файл из нескольких потоков в одном процессе *поддерживается*, запись в один файл из *нескольких процессов* *не* поддерживается, поскольку в Python нет стандартного способа сериализовать доступ к одному файлу из нескольких процессов. Если нужно вести журнал в один файл из нескольких процессов, один из способов – сделать так, чтобы все процессы записывали данные в [`SocketHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.SocketHandler), а отдельный процесс реализовывал сокет-сервер, который читает из сокета и записывает в файл. (Если хотите, можно выделить один поток в одном из существующих процессов для выполнения этой функции.) [В этом разделе](https://python-all.ru/3.15/howto/logging-cookbook.html#network-logging) подробно описывается данный подход и приводится рабочий приёмник сокета, который можно использовать как отправную точку для адаптации в своих приложениях.10551056Вы также можете написать собственный обработчик, который использует класс [`Lock`](https://python-all.ru/3.15/library/multiprocessing.html#multiprocessing.Lock) из модуля [`multiprocessing`](https://python-all.ru/3.15/library/multiprocessing.html#module-multiprocessing) для сериализации доступа к файлу из ваших процессов. Стандартные библиотечные [`FileHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.FileHandler) и их подклассы не используют `multiprocessing`.10571058В качестве альтернативы можно использовать `Queue` и [`QueueHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.QueueHandler) для отправки всех событий журналирования одному из процессов в вашем многопроцессном приложении. В следующем примере сценария показано, как это сделать; в примере отдельный процесс-слушатель ожидает события, отправленные другими процессами, и регистрирует их в соответствии со своей собственной конфигурацией журналирования. Хотя пример демонстрирует лишь один из способов (например, вместо отдельного процесса-слушателя можно использовать поток-слушатель – реализация будет аналогичной), он позволяет задать полностью разные конфигурации журналирования для слушателя и остальных процессов в вашем приложении и может быть использован как основа для кода, отвечающего вашим конкретным требованиям:10591060```python1061# Вам понадобятся эти импорты в вашем коде.1062import logging1063import logging.handlers1064import multiprocessing10651066# Следующие две строки импорта только для этой демонстрации.1067from random import choice, random1068import time10691070#1071# Поскольку нужно задать настройки логирования для слушателя и рабочих процессов, функции1072# слушателя и рабочего процесса принимают параметр configurer – вызываемый объект для1073# настройки логирования этого процесса. Эти функции также получают очередь, которую1074# используют для взаимодействия.1075#1076# На практике слушателя можно настроить как угодно, но заметьте: в этом простом1077# примере слушатель не применяет логику уровней или фильтров к полученным записям.1078# На практике эту логику, вероятно, стоит вынести в рабочие процессы, чтобы не1079# пересылать между процессами события, которые всё равно будут отфильтрованы.1080#1081# Размер файлов при ротации намеренно сделан небольшим, чтобы результат был хорошо виден.1082def listener_configurer():1083 root = logging.getLogger()1084 h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)1085 f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')1086 h.setFormatter(f)1087 root.addHandler(h)10881089# Это главный цикл процесса-слушателя: ждём события логирования1090# (LogRecords) в очереди и обрабатываем их; завершаем работу, когда получаем None вместо1091# LogRecord.1092def listener_process(queue, configurer):1093 configurer()1094 while True:1095 try:1096 record = queue.get()1097 if record is None: # Отправляем это как сигнал завершения, чтобы слушатель остановился.1098 break1099 logger = logging.getLogger(record.name)1100 logger.handle(record) # Никакой логики уровней и фильтров – просто делаем дело!1101 except Exception:1102 import sys, traceback1103 print('Whoops! Problem:', file=sys.stderr)1104 traceback.print_exc(file=sys.stderr)11051106# Массивы для случайного выбора в этой демонстрации.11071108LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,1109 logging.ERROR, logging.CRITICAL]11101111LOGGERS = ['a.b.c', 'd.e.f']11121113MESSAGES = [1114 'Random message #1',1115 'Random message #2',1116 'Random message #3',1117]11181119# Настройка рабочего процесса выполняется в начале его работы.1120# Обратите внимание: в Windows нельзя полагаться на семантику fork, поэтому каждый процесс1121# будет выполнять код настройки логирования при запуске.1122def worker_configurer(queue):1123 h = logging.handlers.QueueHandler(queue) # Нужен только один обработчик.1124 root = logging.getLogger()1125 root.addHandler(h)1126 # Отправляем все сообщения для демонстрации; никакой другой логики уровней или фильтров.1127 root.setLevel(logging.DEBUG)11281129# Это главный цикл рабочего процесса, который просто логирует десять событий с1130# случайные задержки перед завершением.1131# Сообщения print нужны лишь для того, чтобы было видно, что программа работает.1132def worker_process(queue, configurer):1133 configurer(queue)1134 name = multiprocessing.current_process().name1135 print('Worker started: %s' % name)1136 for i in range(10):1137 time.sleep(random())1138 logger = logging.getLogger(choice(LOGGERS))1139 level = choice(LEVELS)1140 message = choice(MESSAGES)1141 logger.log(level, message)1142 print('Worker finished: %s' % name)11431144# Здесь организуется демонстрация. Создать очередь, создать и запустить1145# слушатель, создать десять рабочих процессов и запустить их, дождаться их завершения,1146# затем отправить None в очередь, чтобы сообщить слушателю о завершении.1147def main():1148 queue = multiprocessing.Queue(-1)1149 listener = multiprocessing.Process(target=listener_process,1150 args=(queue, listener_configurer))1151 listener.start()1152 workers = []1153 for i in range(10):1154 worker = multiprocessing.Process(target=worker_process,1155 args=(queue, worker_configurer))1156 workers.append(worker)1157 worker.start()1158 for w in workers:1159 w.join()1160 queue.put_nowait(None)1161 listener.join()11621163if __name__ == '__main__':1164 main()1165```11661167Вариант приведённого выше сценария оставляет ведение журнала в главном процессе, в отдельном потоке:11681169```python1170import logging1171import logging.config1172import logging.handlers1173from multiprocessing import Process, Queue1174import random1175import threading1176import time11771178def logger_thread(q):1179 while True:1180 record = q.get()1181 if record is None:1182 break1183 logger = logging.getLogger(record.name)1184 logger.handle(record)11851186def worker_process(q):1187 qh = logging.handlers.QueueHandler(q)1188 root = logging.getLogger()1189 root.setLevel(logging.DEBUG)1190 root.addHandler(qh)1191 levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1192 logging.CRITICAL]1193 loggers = ['foo', 'foo.bar', 'foo.bar.baz',1194 'spam', 'spam.ham', 'spam.ham.eggs']1195 for i in range(100):1196 lvl = random.choice(levels)1197 logger = logging.getLogger(random.choice(loggers))1198 logger.log(lvl, 'Message no. %d', i)11991200if __name__ == '__main__':1201 q = Queue()1202 d = {1203 'version': 1,1204 'formatters': {1205 'detailed': {1206 'class': 'logging.Formatter',1207 'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1208 }1209 },1210 'handlers': {1211 'console': {1212 'class': 'logging.StreamHandler',1213 'level': 'INFO',1214 },1215 'file': {1216 'class': 'logging.FileHandler',1217 'filename': 'mplog.log',1218 'mode': 'w',1219 'formatter': 'detailed',1220 },1221 'foofile': {1222 'class': 'logging.FileHandler',1223 'filename': 'mplog-foo.log',1224 'mode': 'w',1225 'formatter': 'detailed',1226 },1227 'errors': {1228 'class': 'logging.FileHandler',1229 'filename': 'mplog-errors.log',1230 'mode': 'w',1231 'level': 'ERROR',1232 'formatter': 'detailed',1233 },1234 },1235 'loggers': {1236 'foo': {1237 'handlers': ['foofile']1238 }1239 },1240 'root': {1241 'level': 'DEBUG',1242 'handlers': ['console', 'file', 'errors']1243 },1244 }1245 workers = []1246 for i in range(5):1247 wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))1248 workers.append(wp)1249 wp.start()1250 logging.config.dictConfig(d)1251 lp = threading.Thread(target=logger_thread, args=(q,))1252 lp.start()1253 # На этом этапе главный процесс может заняться своей полезной работой1254 # Когда он с этим закончит, он может дождаться завершения рабочих процессов...1255 for wp in workers:1256 wp.join()1257 # А теперь указать потоку журналирования завершиться1258 q.put(None)1259 lp.join()1260```12611262Этот вариант показывает, как можно, например, применить конфигурацию для определённых регистраторов – например, регистратор `foo` имеет специальный обработчик, который сохраняет все события подсистемы `foo` в файл `mplog-foo.log`. Это будет использовано механизмом журналирования в главном процессе (даже если события журналирования генерируются в рабочих процессах) для направления сообщений к соответствующим местам назначения.12631264### Использование concurrent.futures.ProcessPoolExecutor12651266Если вы хотите использовать [`concurrent.futures.ProcessPoolExecutor`](https://python-all.ru/3.15/library/concurrent.futures.html#concurrent.futures.ProcessPoolExecutor) для запуска рабочих процессов, необходимо создать очередь немного иначе. Вместо12671268```python1269queue = multiprocessing.Queue(-1)1270```12711272следует использовать12731274```python1275queue = multiprocessing.Manager().Queue(-1) # также работает с примерами выше1276```12771278и затем можно заменить создание рабочего процесса с этого:12791280```python1281workers = []1282for i in range(10):1283 worker = multiprocessing.Process(target=worker_process,1284 args=(queue, worker_configurer))1285 workers.append(worker)1286 worker.start()1287for w in workers:1288 w.join()1289```12901291на это (не забудьте сначала импортировать [`concurrent.futures`](https://python-all.ru/3.15/library/concurrent.futures.html#module-concurrent.futures)):12921293```python1294with concurrent.futures.ProcessPoolExecutor(max_workers=10) as executor:1295 for i in range(10):1296 executor.submit(worker_process, queue, worker_configurer)1297```12981299### Развёртывание веб-приложений с помощью Gunicorn и uWSGI13001301При развёртывании веб-приложений с помощью [Gunicorn](https://python-all.ru/3.15/howto/logging-cookbook.html) или [uWSGI](https://python-all.ru/3.15/howto/logging-cookbook.html) (или аналогичных инструментов) создаётся несколько рабочих процессов для обработки запросов клиентов. В таких средах следует избегать создания обработчиков, основанных на файлах, непосредственно в веб-приложении. Вместо этого используйте [`SocketHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.SocketHandler) для ведения журнала из веб-приложения в слушатель в отдельном процессе. Это можно настроить с помощью инструмента управления процессами, такого как Supervisor – подробнее см. [Запуск слушателя сокета журналирования в рабочей среде](https://python-all.ru/3.15/howto/logging-cookbook.html#running-a-logging-socket-listener-in-production).13021303## Использование ротации файлов13041305Иногда требуется позволить файлу журнала расти до определённого размера, затем открыть новый файл и вести запись в него. Может потребоваться сохранять определённое количество таких файлов, и когда будет создано заданное число файлов, выполнять ротацию, чтобы и количество, и размер файлов оставались в заданных границах. Для такого сценария использования пакет logging предоставляет [`RotatingFileHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.RotatingFileHandler):13061307```python1308import glob1309import logging1310import logging.handlers13111312LOG_FILENAME = 'logging_rotatingfile_example.out'13131314# Настроить конкретный регистратор с нужным уровнем вывода1315my_logger = logging.getLogger('MyLogger')1316my_logger.setLevel(logging.DEBUG)13171318# Добавить обработчик сообщений журнала в регистратор1319handler = logging.handlers.RotatingFileHandler(1320 LOG_FILENAME, maxBytes=20, backupCount=5)13211322my_logger.addHandler(handler)13231324# Записать несколько сообщений1325for i in range(20):1326 my_logger.debug('i = %d' % i)13271328# Посмотреть, какие файлы созданы1329logfiles = glob.glob('%s*' % LOG_FILENAME)13301331for filename in logfiles:1332 print(filename)1333```13341335В результате должно получиться 6 отдельных файлов, каждый из которых содержит часть истории журнала приложения:13361337```text1338logging_rotatingfile_example.out1339logging_rotatingfile_example.out.11340logging_rotatingfile_example.out.21341logging_rotatingfile_example.out.31342logging_rotatingfile_example.out.41343logging_rotatingfile_example.out.51344```13451346Самый свежий файл всегда называется `logging_rotatingfile_example.out`, и каждый раз при достижении ограничения по размеру он переименовывается с суффиксом `.1`. Каждый из существующих резервных файлов переименовывается с увеличением суффикса (`.1` становится `.2` и т.д.), а файл `.6` удаляется.13471348Разумеется, в этом примере размер файла журнала установлен слишком маленьким для наглядности. В реальности нужно установить *maxBytes* в подходящее значение.13491350## Использование альтернативных стилей форматирования13511352Когда журналирование было добавлено в стандартную библиотеку Python, единственным способом форматирования сообщений с переменным содержимым было использование %-форматирования. С тех пор в Python появились два новых подхода к форматированию: [`string.Template`](https://python-all.ru/3.15/library/string.html#string.Template) (добавлен в Python 2.4) и [`str.format()`](https://python-all.ru/3.15/library/stdtypes.html#str.format) (добавлен в Python 2.6).13531354Начиная с версии 3.2, модуль logging предоставляет улучшенную поддержку этих двух дополнительных стилей форматирования. Класс [`Formatter`](https://python-all.ru/3.15/library/logging.html#logging.Formatter) был расширен: добавлен дополнительный необязательный именованный параметр `style`. По умолчанию он равен `'%'`, но возможны также значения `'{'` и `'$'`, соответствующие двум другим стилям форматирования. Обратная совместимость сохраняется по умолчанию (как и следовало ожидать), но при явном указании параметра style появляется возможность задавать строки формата, работающие с [`str.format()`](https://python-all.ru/3.15/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.15/library/string.html#string.Template). Вот пример сеанса работы в консоли, демонстрирующий возможности:13551356```pycon1357>>> import logging1358>>> root = logging.getLogger()1359>>> root.setLevel(logging.DEBUG)1360>>> handler = logging.StreamHandler()1361>>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}',1362... style='{')1363>>> handler.setFormatter(bf)1364>>> root.addHandler(handler)1365>>> logger = logging.getLogger('foo.bar')1366>>> logger.debug('This is a DEBUG message')13672010-10-28 15:11:55,341 foo.bar DEBUG This is a DEBUG message1368>>> logger.critical('This is a CRITICAL message')13692010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message1370>>> df = logging.Formatter('$asctime $name ${levelname} $message',1371... style='$')1372>>> handler.setFormatter(df)1373>>> logger.debug('This is a DEBUG message')13742010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message1375>>> logger.critical('This is a CRITICAL message')13762010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message1377>>>1378```13791380Обратите внимание: форматирование сообщений журнала для конечного вывода в файлы совершенно не зависит от того, как конструируется отдельное сообщение. Оно по-прежнему может использовать %-форматирование, как показано ниже:13811382```python1383>>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')13842010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message1385>>>1386```13871388Вызовы функций журналирования (`logger.debug()`, `logger.info()` и т.д.) принимают только позиционные параметры для самого сообщения журнала; именованные параметры используются только для определения параметров обработки вызова (например, именованный параметр `exc_info` указывает, что нужно записать информацию о трассировке стека, или именованный параметр `extra` – добавить дополнительный контекст в журнал). Поэтому невозможно напрямую использовать синтаксис [`str.format()`](https://python-all.ru/3.15/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.15/library/string.html#string.Template) при вызовах, поскольку внутри пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Изменить это без нарушения обратной совместимости нельзя, так как все существующие вызовы logging в существующем коде используют %-формат строк.13891390Однако существует способ использовать {}- и $-форматирование для построения отдельных сообщений журнала. Напомним, что в качестве строки формата сообщения можно использовать произвольный объект, и пакет logging вызовет у этого объекта `str()` для получения фактической строки формата. Рассмотрим следующие два класса:13911392```python1393class BraceMessage:1394 def __init__(self, fmt, /, *args, **kwargs):1395 self.fmt = fmt1396 self.args = args1397 self.kwargs = kwargs13981399 def __str__(self):1400 return self.fmt.format(*self.args, **self.kwargs)14011402class DollarMessage:1403 def __init__(self, fmt, /, **kwargs):1404 self.fmt = fmt1405 self.kwargs = kwargs14061407 def __str__(self):1408 from string import Template1409 return Template(self.fmt).substitute(**self.kwargs)1410```14111412Любой из этих классов можно использовать вместо строки формата, чтобы разрешить применение {}- или $-форматирования для построения фактической части «message», которая появляется в отформатированном выводе журнала вместо «%(message)s», «{message}» или «$message». Это немного громоздко – использовать имена классов каждый раз при журналировании, но вполне приемлемо, если применить псевдоним, например \_\_ (двойное подчеркивание – не путать с \_, одинарным подчеркиванием, используемым как синоним/псевдоним для [`gettext.gettext()`](https://python-all.ru/3.15/library/gettext.html#gettext.gettext) или его аналогов).14131414Вышеуказанные классы не входят в состав Python, но их легко скопировать и вставить в свой код. Их можно использовать следующим образом (предполагая, что они объявлены в модуле с именем `wherever`):14151416```pycon1417>>> from wherever import BraceMessage as __1418>>> print(__('Message with {0} {name}', 2, name='placeholders'))1419Message with 2 placeholders1420>>> class Point: pass1421...1422>>> p = Point()1423>>> p.x = 0.51424>>> p.y = 0.51425>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})',1426... point=p))1427Message with coordinates: (0.50, 0.50)1428>>> from wherever import DollarMessage as __1429>>> print(__('Message with $num $what', num=2, what='placeholders'))1430Message with 2 placeholders1431>>>1432```14331434Хотя в приведённых выше примерах используется `print()` для демонстрации работы форматирования, в реальности для ведения журнала с помощью этого подхода следует использовать `logger.debug()` или аналогичную функцию.14351436Стоит отметить, что этот подход не приводит к существенному снижению производительности: собственно форматирование происходит не в момент вызова журналирования, а когда (и если) сообщение действительно должно быть выведено в журнал обработчиком. Так что единственная необычная деталь, которая может вызвать затруднение, – это то, что круглые скобки охватывают строку формата вместе с аргументами, а не только строку формата. Это объясняется тем, что запись \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов `XXXMessage`.14371438Если хотите, можно использовать [`LoggerAdapter`](https://python-all.ru/3.15/library/logging.html#logging.LoggerAdapter) для достижения аналогичного эффекта, как в следующем примере:14391440```python1441import logging14421443class Message:1444 def __init__(self, fmt, args):1445 self.fmt = fmt1446 self.args = args14471448 def __str__(self):1449 return self.fmt.format(*self.args)14501451class StyleAdapter(logging.LoggerAdapter):1452 def log(self, level, msg, /, *args, stacklevel=1, **kwargs):1453 if self.isEnabledFor(level):1454 msg, kwargs = self.process(msg, kwargs)1455 self.logger.log(level, Message(msg, args), **kwargs,1456 stacklevel=stacklevel+1)14571458logger = StyleAdapter(logging.getLogger(__name__))14591460def main():1461 logger.debug('Hello, {}', 'world!')14621463if __name__ == '__main__':1464 logging.basicConfig(level=logging.DEBUG)1465 main()1466```14671468Приведённый выше сценарий должен записать в журнал сообщение `Hello, world!` при запуске с Python 3.8 или новее.14691470## Настройка `LogRecord`14711472Каждое событие журналирования представлено экземпляром [`LogRecord`](https://python-all.ru/3.15/library/logging.html#logging.LogRecord). Когда событие регистрируется и не отфильтровывается по уровню регистратора, создаётся `LogRecord`, заполняется информацией о событии и затем передаётся обработчикам для этого регистратора (и его предков, вплоть до регистратора, в котором дальнейшее распространение по иерархии отключено). До Python 3.2 было только два места, где выполнялось это создание:14731474- [`Logger.makeRecord()`](https://python-all.ru/3.15/library/logging.html#logging.Logger.makeRecord), который вызывается в обычном процессе регистрации события. Он напрямую вызывал [`LogRecord`](https://python-all.ru/3.15/library/logging.html#logging.LogRecord) для создания экземпляра.1475- [`makeLogRecord()`](https://python-all.ru/3.15/library/logging.html#logging.makeLogRecord), которая вызывается со словарем, содержащим атрибуты для добавления в LogRecord. Обычно она вызывается, когда подходящий словарь был получен по сети (например, в виде pickle через [`SocketHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.SocketHandler) или в формате JSON через [`HTTPHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.HTTPHandler)).14761477Обычно это означало, что если требуется выполнить какие-либо специальные действия с [`LogRecord`](https://python-all.ru/3.15/library/logging.html#logging.LogRecord), приходилось делать одно из следующего.14781479- Создать собственный подкласс [`Logger`](https://python-all.ru/3.15/library/logging.html#logging.Logger), который переопределяет [`Logger.makeRecord()`](https://python-all.ru/3.15/library/logging.html#logging.Logger.makeRecord), и установить его с помощью [`setLoggerClass()`](https://python-all.ru/3.15/library/logging.html#logging.setLoggerClass) до того, как будут созданы какие-либо логгеры, которые вас интересуют.1480- Добавить [`Filter`](https://python-all.ru/3.15/library/logging.html#logging.Filter) к логгеру или обработчику, который выполняет необходимые специальные манипуляции при вызове его метода [`filter()`](https://python-all.ru/3.15/library/logging.html#logging.Filter.filter).14811482Первый подход был бы несколько громоздким в сценарии, где (скажем) несколько разных библиотек хотели бы делать разные вещи. Каждая попыталась бы установить свой собственный подкласс [`Logger`](https://python-all.ru/3.15/library/logging.html#logging.Logger), и та, которая сделала это последней, победила бы.14831484Второй подход достаточно хорошо работает во многих случаях, но не позволяет, например, использовать специализированный подкласс [`LogRecord`](https://python-all.ru/3.15/library/logging.html#logging.LogRecord). Разработчики библиотек могут установить подходящий фильтр на своих логгерах, но им приходилось бы помнить об этом каждый раз, когда они добавляют новый логгер (что они делают, просто добавляя новые пакеты или модули и выполняя14851486```python1487logger = logging.getLogger(__name__)1488```14891490на уровне модуля). Вероятно, это одна из тех вещей, о которых нужно помнить. Разработчики также могли бы добавить фильтр к [`NullHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.NullHandler), прикрепленному к их корневому логгеру, но он не будет вызываться, если разработчик приложения прикрепит обработчик к логгеру библиотеки нижнего уровня – так что вывод от этого обработчика не будет отражать намерений разработчика библиотеки.14911492В Python 3.2 и новее создание [`LogRecord`](https://python-all.ru/3.15/library/logging.html#logging.LogRecord) осуществляется через фабрику, которую можно указать. Фабрика – это просто вызываемый объект, который можно установить с помощью [`setLogRecordFactory()`](https://python-all.ru/3.15/library/logging.html#logging.setLogRecordFactory) и запросить с помощью [`getLogRecordFactory()`](https://python-all.ru/3.15/library/logging.html#logging.getLogRecordFactory). Фабрика вызывается с той же сигнатурой, что и конструктор `LogRecord`, поскольку [`LogRecord`](https://python-all.ru/3.15/library/logging.html#logging.LogRecord) является значением по умолчанию для фабрики.14931494Этот подход позволяет пользовательской фабрике контролировать все аспекты создания LogRecord. Например, можно вернуть подкласс или просто добавить несколько дополнительных атрибутов к записи после ее создания, используя шаблон, подобный следующему:14951496```python1497old_factory = logging.getLogRecordFactory()14981499def record_factory(*args, **kwargs):1500 record = old_factory(*args, **kwargs)1501 record.custom_attribute = 0xdecafbad1502 return record15031504logging.setLogRecordFactory(record_factory)1505```15061507Этот шаблон позволяет разным библиотекам объединять фабрики в цепочку, и пока они не перезаписывают атрибуты друг друга или случайно не перезаписывают стандартные атрибуты, никаких сюрпризов быть не должно. Однако следует иметь в виду, что каждое звено цепочки добавляет накладные расходы во время выполнения ко всем операциям логирования, и эту технику следует использовать только тогда, когда использование [`Filter`](https://python-all.ru/3.15/library/logging.html#logging.Filter) не дает желаемого результата.15081509## Создание подклассов QueueHandler и QueueListener – пример с ZeroMQ15101511### Подкласс `QueueHandler`15121513Можно использовать подкласс [`QueueHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.QueueHandler) для отправки сообщений в очереди других типов, например, в сокет ZeroMQ «publish». В приведенном ниже примере сокет создается отдельно и передается обработчику (в качестве его «очереди»):15141515```python1516import zmq # с использованием pyzmq, привязки Python к ZeroMQ1517import json # для переносимой сериализации записей15181519ctx = zmq.Context()1520sock = zmq.Socket(ctx, zmq.PUB) # или zmq.PUSH, или другое подходящее значение1521sock.bind('tcp://*:5556') # или где угодно15221523class ZeroMQSocketHandler(QueueHandler):1524 def enqueue(self, record):1525 self.queue.send_json(record.__dict__)15261527handler = ZeroMQSocketHandler(sock)1528```15291530Конечно, есть и другие способы организации этого, например, передача данных, необходимых обработчику для создания сокета:15311532```python1533class ZeroMQSocketHandler(QueueHandler):1534 def __init__(self, uri, socktype=zmq.PUB, ctx=None):1535 self.ctx = ctx or zmq.Context()1536 socket = zmq.Socket(self.ctx, socktype)1537 socket.bind(uri)1538 super().__init__(socket)15391540 def enqueue(self, record):1541 self.queue.send_json(record.__dict__)15421543 def close(self):1544 self.queue.close()1545```15461547### Подкласс `QueueListener`15481549Можно также создать подкласс [`QueueListener`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.QueueListener) для получения сообщений из очередей других типов, например, из сокета ZeroMQ «subscribe». Вот пример:15501551```python1552class ZeroMQSocketListener(QueueListener):1553 def __init__(self, uri, /, *handlers, **kwargs):1554 self.ctx = kwargs.get('ctx') or zmq.Context()1555 socket = zmq.Socket(self.ctx, zmq.SUB)1556 socket.setsockopt_string(zmq.SUBSCRIBE, '') # подписаться на всё1557 socket.connect(uri)1558 super().__init__(socket, *handlers, **kwargs)15591560 def dequeue(self):1561 msg = self.queue.recv_json()1562 return logging.makeLogRecord(msg)1563```15641565## Создание подклассов QueueHandler и QueueListener – пример с `pynng`15661567Подобно предыдущему разделу, можно реализовать прослушиватель и обработчик с помощью [pynng](https://python-all.ru/3.15/howto/logging-cookbook.html), который является привязкой Python к [NNG](https://python-all.ru/3.15/howto/logging-cookbook.html), позиционируемой как духовный преемник ZeroMQ. Следующие фрагменты кода иллюстрируют это – их можно протестировать в среде, где установлен `pynng`. Для разнообразия сначала приводим прослушиватель.15681569### Подкласс `QueueListener`15701571```python1572# listener.py1573import json1574import logging1575import logging.handlers15761577import pynng15781579DEFAULT_ADDR = "tcp://localhost:13232"15801581interrupted = False15821583class NNGSocketListener(logging.handlers.QueueListener):15841585 def __init__(self, uri, /, *handlers, **kwargs):1586 # Установить тайм-аут для возможности прерывания и открыть1587 # сокет подписчика1588 socket = pynng.Sub0(listen=uri, recv_timeout=500)1589 # Подписка b'' соответствует всем темам1590 topics = kwargs.pop('topics', None) or b''1591 socket.subscribe(topics)1592 # Используем сокет как очередь1593 super().__init__(socket, *handlers, **kwargs)15941595 def dequeue(self, block):1596 data = None1597 # Продолжать цикл, пока не прерван и не получены данные через1598 # сокет1599 while not interrupted:1600 try:1601 data = self.queue.recv(block=block)1602 break1603 except pynng.Timeout:1604 pass1605 except pynng.Closed: # иногда происходит при нажатии Ctrl-C1606 break1607 if data is None:1608 return None1609 # Получить событие журнала, отправленное издателем1610 event = json.loads(data.decode('utf-8'))1611 return logging.makeLogRecord(event)16121613 def enqueue_sentinel(self):1614 # Не используется в этой реализации, так как сокет на самом деле не является1615 # очередь1616 pass16171618logging.getLogger('pynng').propagate = False1619listener = NNGSocketListener(DEFAULT_ADDR, logging.StreamHandler(), topics=b'')1620listener.start()1621print('Press Ctrl-C to stop.')1622try:1623 while True:1624 pass1625except KeyboardInterrupt:1626 interrupted = True1627finally:1628 listener.stop()1629```16301631### Подкласс `QueueHandler`16321633```python1634# sender.py1635import json1636import logging1637import logging.handlers1638import time1639import random16401641import pynng16421643DEFAULT_ADDR = "tcp://localhost:13232"16441645class NNGSocketHandler(logging.handlers.QueueHandler):16461647 def __init__(self, uri):1648 socket = pynng.Pub0(dial=uri, send_timeout=500)1649 super().__init__(socket)16501651 def enqueue(self, record):1652 # Отправить запись в виде JSON с кодировкой UTF-81653 d = dict(record.__dict__)1654 data = json.dumps(d)1655 self.queue.send(data.encode('utf-8'))16561657 def close(self):1658 self.queue.close()16591660logging.getLogger('pynng').propagate = False1661handler = NNGSocketHandler(DEFAULT_ADDR)1662# Убедиться, что идентификатор процесса присутствует в выводе1663logging.basicConfig(level=logging.DEBUG,1664 handlers=[logging.StreamHandler(), handler],1665 format='%(levelname)-8s %(name)10s %(process)6s %(message)s')1666levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1667 logging.CRITICAL)1668logger_names = ('myapp', 'myapp.lib1', 'myapp.lib2')1669msgno = 11670while True:1671 # Просто случайным образом выбирать несколько регистраторов и уровней и вести запись1672 level = random.choice(levels)1673 logger = logging.getLogger(random.choice(logger_names))1674 logger.log(level, 'Message no. %5d' % msgno)1675 msgno += 11676 delay = random.random() * 2 + 0.51677 time.sleep(delay)1678```16791680Можно выполнить два указанных выше фрагмента в отдельных командных оболочках. Если запустить прослушиватель в одной оболочке, а отправителя – в двух отдельных оболочках, должно получиться что-то вроде следующего. В первой оболочке отправителя:16811682```console1683$ python sender.py1684DEBUG myapp 613 Message no. 11685WARNING myapp.lib2 613 Message no. 21686CRITICAL myapp.lib2 613 Message no. 31687WARNING myapp.lib2 613 Message no. 41688CRITICAL myapp.lib1 613 Message no. 51689DEBUG myapp 613 Message no. 61690CRITICAL myapp.lib1 613 Message no. 71691INFO myapp.lib1 613 Message no. 81692(and so on)1693```16941695Во второй оболочке отправителя:16961697```console1698$ python sender.py1699INFO myapp.lib2 657 Message no. 11700CRITICAL myapp.lib2 657 Message no. 21701CRITICAL myapp 657 Message no. 31702CRITICAL myapp.lib1 657 Message no. 41703INFO myapp.lib1 657 Message no. 51704WARNING myapp.lib2 657 Message no. 61705CRITICAL myapp 657 Message no. 71706DEBUG myapp.lib1 657 Message no. 81707(and so on)1708```17091710В оболочке прослушивателя:17111712```console1713$ python listener.py1714Press Ctrl-C to stop.1715DEBUG myapp 613 Message no. 11716WARNING myapp.lib2 613 Message no. 21717INFO myapp.lib2 657 Message no. 11718CRITICAL myapp.lib2 613 Message no. 31719CRITICAL myapp.lib2 657 Message no. 21720CRITICAL myapp 657 Message no. 31721WARNING myapp.lib2 613 Message no. 41722CRITICAL myapp.lib1 613 Message no. 51723CRITICAL myapp.lib1 657 Message no. 41724INFO myapp.lib1 657 Message no. 51725DEBUG myapp 613 Message no. 61726WARNING myapp.lib2 657 Message no. 61727CRITICAL myapp 657 Message no. 71728CRITICAL myapp.lib1 613 Message no. 71729INFO myapp.lib1 613 Message no. 81730DEBUG myapp.lib1 657 Message no. 81731(and so on)1732```17331734Как видно, записи журнала от двух процессов-отправителей перемежаются в выводе прослушивателя.17351736## Пример конфигурации на основе словаря17371738Ниже приведен пример словаря конфигурации логирования – он взят из [документации проекта Django](https://python-all.ru/3.15/howto/logging-cookbook.html). Этот словарь передается в [`dictConfig()`](https://python-all.ru/3.15/library/logging.config.html#logging.config.dictConfig) для применения конфигурации:17391740```python1741LOGGING = {1742 'version': 1,1743 'disable_existing_loggers': False,1744 'formatters': {1745 'verbose': {1746 'format': '{levelname} {asctime} {module} {process:d} {thread:d} {message}',1747 'style': '{',1748 },1749 'simple': {1750 'format': '{levelname} {message}',1751 'style': '{',1752 },1753 },1754 'filters': {1755 'special': {1756 '()': 'project.logging.SpecialFilter',1757 'foo': 'bar',1758 },1759 },1760 'handlers': {1761 'console': {1762 'level': 'INFO',1763 'class': 'logging.StreamHandler',1764 'formatter': 'simple',1765 },1766 'mail_admins': {1767 'level': 'ERROR',1768 'class': 'django.utils.log.AdminEmailHandler',1769 'filters': ['special']1770 }1771 },1772 'loggers': {1773 'django': {1774 'handlers': ['console'],1775 'propagate': True,1776 },1777 'django.request': {1778 'handlers': ['mail_admins'],1779 'level': 'ERROR',1780 'propagate': False,1781 },1782 'myproject.custom': {1783 'handlers': ['console', 'mail_admins'],1784 'level': 'INFO',1785 'filters': ['special']1786 }1787 }1788}1789```17901791Для получения дополнительной информации об этой конфигурации можно обратиться к [соответствующему разделу](https://python-all.ru/3.15/howto/logging-cookbook.html) документации Django.17921793## Использование ротатора и средства именования для настройки обработки ротации журналов17941795Пример того, как можно определить именователя и ротатора, приведен в следующем исполняемом скрипте, который показывает сжатие gzip файла журнала:17961797```python1798import gzip1799import logging1800import logging.handlers1801import os1802import shutil18031804def namer(name):1805 return name + ".gz"18061807def rotator(source, dest):1808 with open(source, 'rb') as f_in:1809 with gzip.open(dest, 'wb') as f_out:1810 shutil.copyfileobj(f_in, f_out)1811 os.remove(source)18121813rh = logging.handlers.RotatingFileHandler('rotated.log', maxBytes=128, backupCount=5)1814rh.rotator = rotator1815rh.namer = namer18161817root = logging.getLogger()1818root.setLevel(logging.INFO)1819root.addHandler(rh)1820f = logging.Formatter('%(asctime)s %(message)s')1821rh.setFormatter(f)1822for i in range(1000):1823 root.info(f'Message no. {i + 1}')1824```18251826После запуска будут созданы шесть новых файлов, пять из которых сжаты:18271828```console1829$ ls rotated.log*1830rotated.log rotated.log.2.gz rotated.log.4.gz1831rotated.log.1.gz rotated.log.3.gz rotated.log.5.gz1832$ zcat rotated.log.1.gz18332023-01-20 02:28:17,767 Message no. 99618342023-01-20 02:28:17,767 Message no. 99718352023-01-20 02:28:17,767 Message no. 9981836```18371838## Более сложный пример с многопроцессностью18391840Следующий рабочий пример показывает, как можно использовать логирование с многопроцессностью с помощью файлов конфигурации. Конфигурации довольно просты, но служат иллюстрацией того, как можно реализовать более сложные в реальном сценарии многопроцессной обработки.18411842В примере главный процесс порождает процесс-слушатель и несколько рабочих процессов. Каждый из главного процесса, слушателя и рабочих имеет три отдельные конфигурации (все рабочие используют одну и ту же конфигурацию). Видно ведение журнала в главном процессе, как рабочие пишут в QueueHandler, а слушатель реализует QueueListener и более сложную конфигурацию ведения журнала, и организует отправку событий, полученных через очередь, обработчикам, указанным в конфигурации. Обратите внимание, что эти конфигурации чисто иллюстративные, но этот пример можно адаптировать под свой сценарий.18431844Вот скрипт – строки документации и комментарии, надеюсь, поясняют, как он работает:18451846```python1847import logging1848import logging.config1849import logging.handlers1850from multiprocessing import Process, Queue, Event, current_process1851import os1852import random1853import time18541855class MyHandler:1856 """1857 Простой обработчик для событий логирования. Он выполняется в процессе-слушателе и1858 распределяет события по логгерам на основе имени в полученной записи,1859 которые затем передаются системой логирования обработчикам,1860 настроенным для этих логгеров.1861 """18621863 def handle(self, record):1864 if record.name == "root":1865 logger = logging.getLogger()1866 else:1867 logger = logging.getLogger(record.name)18681869 if logger.isEnabledFor(record.levelno):1870 # Имя процесса преобразуется только для того, чтобы показать, что это слушатель1871 # выполняет логирование в файлы и консоль.1872 record.processName = '%s (for %s)' % (current_process().name, record.processName)1873 logger.handle(record)18741875def listener_process(q, stop_event, config):1876 """1877 Это можно было бы сделать в главном процессе, но сделано в отдельном1878 процессе для наглядности.18791880 Это инициализирует логирование согласно указанной конфигурации1881 запускает слушатель и ожидает сигнала от главного процесса о завершении1882 через событие. Затем слушатель останавливается, и процесс завершается.1883 """1884 logging.config.dictConfig(config)1885 listener = logging.handlers.QueueListener(q, MyHandler())1886 listener.start()1887 if os.name == 'posix':1888 # В POSIX логгер setup уже был настроен в1889 # родительском процессе, но должен был быть отключён после вызова1890 # dictConfig.1891 # В Windows, поскольку fork не используется, логгер setup не будет1892 # существовать в дочернем процессе, поэтому он будет создан, и сообщение1893 # появится – отсюда и конструкция "if posix".1894 logger = logging.getLogger('setup')1895 logger.critical('Should not appear, because of disabled logger ...')1896 stop_event.wait()1897 listener.stop()18981899def worker_process(config):1900 """1901 Некоторое количество таких процессов порождается для иллюстрации. На1902 практике это могла бы быть разнородная группа процессов, а не1903 идентичные друг другу.19041905 Это инициализирует логирование согласно указанной конфигурации1906 и записывает сотню сообщений со случайными уровнями в случайно выбранные1907 логгеры.19081909 Добавлена небольшая задержка, чтобы дать другим процессам шанс выполниться. Это1910 не является строго необходимым, но позволяет немного перемешать вывод от разных1911 процессов больше, чем если бы её не было.1912 """1913 logging.config.dictConfig(config)1914 levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1915 logging.CRITICAL]1916 loggers = ['foo', 'foo.bar', 'foo.bar.baz',1917 'spam', 'spam.ham', 'spam.ham.eggs']1918 if os.name == 'posix':1919 # В POSIX логгер setup уже был настроен в1920 # родительском процессе, но должен был быть отключён после вызова1921 # dictConfig.1922 # В Windows, поскольку fork не используется, логгер setup не будет1923 # существовать в дочернем процессе, поэтому он будет создан, и сообщение1924 # появится – отсюда и конструкция "if posix".1925 logger = logging.getLogger('setup')1926 logger.critical('Should not appear, because of disabled logger ...')1927 for i in range(100):1928 lvl = random.choice(levels)1929 logger = logging.getLogger(random.choice(loggers))1930 logger.log(lvl, 'Message no. %d', i)1931 time.sleep(0.01)19321933def main():1934 q = Queue()1935 # Главный процесс получает простую конфигурацию, которая выводит информацию в консоль.1936 config_initial = {1937 'version': 1,1938 'handlers': {1939 'console': {1940 'class': 'logging.StreamHandler',1941 'level': 'INFO'1942 }1943 },1944 'root': {1945 'handlers': ['console'],1946 'level': 'DEBUG'1947 }1948 }1949 # Конфигурация рабочего процесса представляет собой QueueHandler, прикреплённый к1950 # корневому логгеру, что позволяет отправлять все сообщения в очередь.1951 # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1952 # родительском процессе. Это необходимо в POSIX, потому что логгер будет1953 # присутствовать в дочернем процессе после вызова fork().1954 config_worker = {1955 'version': 1,1956 'disable_existing_loggers': True,1957 'handlers': {1958 'queue': {1959 'class': 'logging.handlers.QueueHandler',1960 'queue': q1961 }1962 },1963 'root': {1964 'handlers': ['queue'],1965 'level': 'DEBUG'1966 }1967 }1968 # Конфигурация процесса-слушателя показывает, что вся гибкость1969 # конфигурации логирования доступна для отправки событий обработчикам так, как1970 # требуется.1971 # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1972 # родительском процессе. Это необходимо в POSIX, потому что логгер будет1973 # присутствовать в дочернем процессе после вызова fork().1974 config_listener = {1975 'version': 1,1976 'disable_existing_loggers': True,1977 'formatters': {1978 'detailed': {1979 'class': 'logging.Formatter',1980 'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1981 },1982 'simple': {1983 'class': 'logging.Formatter',1984 'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1985 }1986 },1987 'handlers': {1988 'console': {1989 'class': 'logging.StreamHandler',1990 'formatter': 'simple',1991 'level': 'INFO'1992 },1993 'file': {1994 'class': 'logging.FileHandler',1995 'filename': 'mplog.log',1996 'mode': 'w',1997 'formatter': 'detailed'1998 },1999 'foofile': {2000 'class': 'logging.FileHandler',2001 'filename': 'mplog-foo.log',2002 'mode': 'w',2003 'formatter': 'detailed'2004 },2005 'errors': {2006 'class': 'logging.FileHandler',2007 'filename': 'mplog-errors.log',2008 'mode': 'w',2009 'formatter': 'detailed',2010 'level': 'ERROR'2011 }2012 },2013 'loggers': {2014 'foo': {2015 'handlers': ['foofile']2016 }2017 },2018 'root': {2019 'handlers': ['console', 'file', 'errors'],2020 'level': 'DEBUG'2021 }2022 }2023 # Записываем несколько начальных событий, просто чтобы показать, что логирование в родительском процессе работает2024 # нормально.2025 logging.config.dictConfig(config_initial)2026 logger = logging.getLogger('setup')2027 logger.info('About to create workers ...')2028 workers = []2029 for i in range(5):2030 wp = Process(target=worker_process, name='worker %d' % (i + 1),2031 args=(config_worker,))2032 workers.append(wp)2033 wp.start()2034 logger.info('Started worker: %s', wp.name)2035 logger.info('About to create listener ...')2036 stop_event = Event()2037 lp = Process(target=listener_process, name='listener',2038 args=(q, stop_event, config_listener))2039 lp.start()2040 logger.info('Started listener')2041 # Теперь ожидаем завершения работы рабочих процессов.2042 for wp in workers:2043 wp.join()2044 # Все рабочие процессы завершены, теперь можно остановить прослушивание.2045 # Логирование в родительском процессе всё ещё работает нормально.2046 logger.info('Telling listener to stop ...')2047 stop_event.set()2048 lp.join()2049 logger.info('All done.')20502051if __name__ == '__main__':2052 main()2053```20542055## Вставка BOM в сообщения, отправляемые в SysLogHandler20562057[**RFC 5424**](https://python-all.ru/3.15/howto/logging-cookbook.html) требует, чтобы сообщение Unicode отправлялось демону syslog в виде набора байтов, имеющего следующую структуру: необязательный чисто ASCII-компонент, за которым следует метка порядка байтов UTF-8 (BOM), а затем Unicode, закодированный в UTF-8. (См. [**соответствующий раздел спецификации**](https://python-all.ru/3.15/howto/logging-cookbook.html).)20582059В Python 3.1 в [`SysLogHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.SysLogHandler) был добавлен код для вставки BOM в сообщение, но, к сожалению, он был реализован некорректно: BOM появлялся в начале сообщения и, следовательно, не допускал наличия чисто ASCII-компонента перед ним.20602061Поскольку такое поведение ошибочно, некорректный код вставки BOM удаляется из Python 3.2.4 и более поздних версий. Однако он не заменяется, и если требуется создавать сообщения, соответствующие [**RFC 5424**](https://python-all.ru/3.15/howto/logging-cookbook.html), которые включают BOM, необязательную чисто ASCII-последовательность перед ним и произвольный Unicode после него, закодированный в UTF-8, то необходимо сделать следующее:206220631. Необходимо присоединить экземпляр [`Formatter`](https://python-all.ru/3.15/library/logging.html#logging.Formatter) к экземпляру [`SysLogHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.SysLogHandler), указав строку формата, например:20642065 ```python2066 'ASCII section\ufeffUnicode section'2067 ```20682069 Кодовая точка Unicode U+FEFF при кодировании в UTF-8 будет представлена как метка порядка байтов UTF-8 – строка байтов `b'\xef\xbb\xbf'`.20702. ASCII-часть следует заменить на любые подходящие заполнители, но необходимо следить, чтобы данные, которые появляются там после подстановки, всегда были в ASCII (таким образом, они останутся без изменений после кодирования UTF-8).20713. Unicode-часть следует заменить на любые заполнители; если данные после подстановки содержат символы за пределами диапазона ASCII, это нормально – они будут закодированы в UTF-8.20722073Отформатированное сообщение *будет* закодировано в UTF-8 с помощью `SysLogHandler`. Если следовать приведённым выше правилам, можно создавать сообщения, соответствующие [**RFC 5424**](https://python-all.ru/3.15/howto/logging-cookbook.html). Если этого не делать, модуль logging может не жаловаться, но сообщения не будут соответствовать RFC 5424, и демон syslog может выражать недовольство.20742075## Реализация структурированного ведения журнала20762077Хотя большинство сообщений журнала предназначены для чтения человеком и поэтому не предназначены для машинного разбора, могут возникнуть ситуации, когда требуется выводить сообщения в структурированном формате, *который* может быть разобран программой (без необходимости в сложных регулярных выражениях). Это легко достигается с помощью пакета logging. Существует несколько способов, но ниже приведён простой подход, использующий JSON для сериализации события в машиночитаемом виде.20782079```python2080import json2081import logging20822083class StructuredMessage:2084 def __init__(self, message, /, **kwargs):2085 self.message = message2086 self.kwargs = kwargs20872088 def __str__(self):2089 return '%s >>> %s' % (self.message, json.dumps(self.kwargs))20902091_ = StructuredMessage # необязательно, для улучшения читаемости20922093logging.basicConfig(level=logging.INFO, format='%(message)s')2094logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))2095```20962097Если запустить приведённый выше скрипт, он выведет:20982099```text2100message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}2101```21022103Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.21042105Если требуется более специализированная обработка, можно использовать пользовательский кодировщик JSON, как в следующем полном примере:21062107```python2108import json2109import logging21102111class Encoder(json.JSONEncoder):2112 def default(self, o):2113 if isinstance(o, set):2114 return tuple(o)2115 elif isinstance(o, str):2116 return o.encode('unicode_escape').decode('ascii')2117 return super().default(o)21182119class StructuredMessage:2120 def __init__(self, message, /, **kwargs):2121 self.message = message2122 self.kwargs = kwargs21232124 def __str__(self):2125 s = Encoder().encode(self.kwargs)2126 return '%s >>> %s' % (self.message, s)21272128_ = StructuredMessage # необязательно, для улучшения читаемости21292130def main():2131 logging.basicConfig(level=logging.INFO, format='%(message)s')2132 logging.info(_('message 1', set_value={1, 2, 3}, snowman='\u2603'))21332134if __name__ == '__main__':2135 main()2136```21372138При запуске приведённого выше скрипта он выведет:21392140```text2141message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}2142```21432144Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.21452146## Настройка обработчиков с помощью [`dictConfig()`](https://python-all.ru/3.15/library/logging.config.html#logging.config.dictConfig)21472148Иногда требуется настроить обработчики логирования особым образом, и при использовании [`dictConfig()`](https://python-all.ru/3.15/library/logging.config.html#logging.config.dictConfig) это можно сделать без создания подклассов. Например, может потребоваться установить владельца файла журнала. В POSIX это легко сделать с помощью [`shutil.chown()`](https://python-all.ru/3.15/library/shutil.html#shutil.chown), но файловые обработчики в стандартной библиотеке не предоставляют встроенной поддержки. Можно настроить создание обработчика с помощью обычной функции, такой как:21492150```python2151def owned_file_handler(filename, mode='a', encoding=None, owner=None):2152 if owner:2153 if not os.path.exists(filename):2154 open(filename, 'a').close()2155 shutil.chown(filename, *owner)2156 return logging.FileHandler(filename, mode, encoding)2157```21582159Затем в конфигурации логирования, передаваемой в [`dictConfig()`](https://python-all.ru/3.15/library/logging.config.html#logging.config.dictConfig), можно указать, что обработчик должен быть создан вызовом этой функции:21602161```python2162LOGGING = {2163 'version': 1,2164 'disable_existing_loggers': False,2165 'formatters': {2166 'default': {2167 'format': '%(asctime)s %(levelname)s %(name)s %(message)s'2168 },2169 },2170 'handlers': {2171 'file':{2172 # Значения ниже извлекаются из этого словаря и2173 # используются для создания обработчика, установки его уровня и2174 # его форматтера.2175 '()': owned_file_handler,2176 'level':'DEBUG',2177 'formatter': 'default',2178 # Значения ниже передаются вызываемому объекту-создателю обработчика2179 # в качестве именованных аргументов.2180 'owner': ['pulse', 'pulse'],2181 'filename': 'chowntest.log',2182 'mode': 'w',2183 'encoding': 'utf-8',2184 },2185 },2186 'root': {2187 'handlers': ['file'],2188 'level': 'DEBUG',2189 },2190}2191```21922193В этом примере для иллюстрации права владения устанавливаются с использованием пользователя и группы `pulse`. Собирая всё вместе в рабочий скрипт, `chowntest.py`:21942195```python2196import logging, logging.config, os, shutil21972198def owned_file_handler(filename, mode='a', encoding=None, owner=None):2199 if owner:2200 if not os.path.exists(filename):2201 open(filename, 'a').close()2202 shutil.chown(filename, *owner)2203 return logging.FileHandler(filename, mode, encoding)22042205LOGGING = {2206 'version': 1,2207 'disable_existing_loggers': False,2208 'formatters': {2209 'default': {2210 'format': '%(asctime)s %(levelname)s %(name)s %(message)s'2211 },2212 },2213 'handlers': {2214 'file':{2215 # Значения ниже извлекаются из этого словаря и2216 # используются для создания обработчика, установки его уровня и2217 # его форматтера.2218 '()': owned_file_handler,2219 'level':'DEBUG',2220 'formatter': 'default',2221 # Значения ниже передаются вызываемому объекту-создателю обработчика2222 # в качестве именованных аргументов.2223 'owner': ['pulse', 'pulse'],2224 'filename': 'chowntest.log',2225 'mode': 'w',2226 'encoding': 'utf-8',2227 },2228 },2229 'root': {2230 'handlers': ['file'],2231 'level': 'DEBUG',2232 },2233}22342235logging.config.dictConfig(LOGGING)2236logger = logging.getLogger('mylogger')2237logger.debug('A debug message')2238```22392240Для запуска, вероятно, потребуется выполнить от имени `root`:22412242```console2243$ sudo python3.3 chowntest.py2244$ cat chowntest.log22452013-11-05 09:34:51,128 DEBUG mylogger A debug message2246$ ls -l chowntest.log2247-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log2248```22492250Обратите внимание, что в этом примере используется Python 3.3, потому что в нём появился [`shutil.chown()`](https://python-all.ru/3.15/library/shutil.html#shutil.chown). Этот подход должен работать с любой версией Python, поддерживающей [`dictConfig()`](https://python-all.ru/3.15/library/logging.config.html#logging.config.dictConfig) – а именно Python 2.7, 3.2 или новее. В версиях до 3.3 потребовалось бы реализовать фактическую смену владельца, например, с помощью [`os.chown()`](https://python-all.ru/3.15/library/os.html#os.chown).22512252На практике функция создания обработчика может находиться в служебном модуле где-нибудь в вашем проекте. Вместо строки в конфигурации:22532254```python2255'()': owned_file_handler,2256```22572258можно использовать, например:22592260```python2261'()': 'ext://project.util.owned_file_handler',2262```22632264где `project.util` можно заменить на фактическое имя пакета, в котором находится функция. В приведённом рабочем скрипте должно сработать использование `'ext://__main__.owned_file_handler'`. Здесь фактический вызываемый объект разрешается с помощью [`dictConfig()`](https://python-all.ru/3.15/library/logging.config.html#logging.config.dictConfig) из спецификации `ext://`.22652266Этот пример, надеюсь, также показывает, как можно реализовать другие типы изменений файлов – например, установку определённых битов разрешений POSIX – аналогичным образом, с помощью [`os.chmod()`](https://python-all.ru/3.15/library/os.html#os.chmod).22672268Разумеется, этот подход можно распространить и на другие типы обработчиков, помимо [`FileHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.FileHandler) – например, на один из вращающихся файловых обработчиков или на совершенно другой тип обработчика.22692270## Использование определённых стилей форматирования во всём приложении22712272В Python 3.2 у [`Formatter`](https://python-all.ru/3.15/library/logging.html#logging.Formatter) появился именованный параметр `style`, который, хотя по умолчанию для обратной совместимости он равен `%`, позволяет указать `{` или `$` для поддержки подходов к форматированию, поддерживаемых [`str.format()`](https://python-all.ru/3.15/library/stdtypes.html#str.format) и [`string.Template`](https://python-all.ru/3.15/library/string.html#string.Template). Обратите внимание, что это управляет форматированием сообщений журнала для окончательного вывода в журнал и совершенно не зависит от того, как конструируется отдельное сообщение журнала.22732274Вызовы логирования ([`debug()`](https://python-all.ru/3.15/library/logging.html#logging.Logger.debug), [`info()`](https://python-all.ru/3.15/library/logging.html#logging.Logger.info) и т.д.) принимают только позиционные параметры для самого сообщения журнала, а именованные параметры используются только для определения параметров обработки вызова (например, именованный параметр `exc_info` для указания, что нужно записывать информацию о трассировке, или именованный параметр `extra` для указания дополнительной контекстной информации, добавляемой в журнал). Таким образом, нельзя напрямую выполнять вызовы логирования с использованием синтаксиса [`str.format()`](https://python-all.ru/3.15/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.15/library/string.html#string.Template), потому что внутри пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Изменить это без нарушения обратной совместимости было бы невозможно, поскольку все существующие вызовы логирования в коде используют строки с %-форматированием.22752276Высказывались предложения связывать стили форматирования с конкретными регистраторами, но этот подход также сталкивается с проблемами обратной совместимости, поскольку любой существующий код может использовать данное имя регистратора и %-форматирование.22772278Чтобы логирование работало совместимо между любыми сторонними библиотеками и вашим кодом, решения о форматировании необходимо принимать на уровне отдельного вызова логирования. Это открывает несколько способов, которыми можно реализовать альтернативные стили форматирования.22792280### Использование фабрик LogRecord22812282В Python 3.2, вместе с упомянутыми выше изменениями [`Formatter`](https://python-all.ru/3.15/library/logging.html#logging.Formatter), пакет logging получил возможность позволять пользователям устанавливать свои собственные подклассы [`LogRecord`](https://python-all.ru/3.15/library/logging.html#logging.LogRecord) с помощью функции [`setLogRecordFactory()`](https://python-all.ru/3.15/library/logging.html#logging.setLogRecordFactory). Вы можете использовать это, чтобы установить свой собственный подкласс `LogRecord`, который делает правильные вещи, переопределяя метод [`getMessage()`](https://python-all.ru/3.15/library/logging.html#logging.LogRecord.getMessage). В реализации базового класса этого метода происходит форматирование `msg % args`, и именно здесь можно подставить альтернативное форматирование; однако следует быть осторожным, чтобы поддерживать все стили форматирования и разрешить %-форматирование по умолчанию для обеспечения совместимости с другим кодом. Также следует позаботиться о вызове `str(self.msg)`, как это делает базовая реализация.22832284Обратитесь к справочной документации по [`setLogRecordFactory()`](https://python-all.ru/3.15/library/logging.html#logging.setLogRecordFactory) и [`LogRecord`](https://python-all.ru/3.15/library/logging.html#logging.LogRecord) для получения дополнительной информации.22852286### Использование пользовательских объектов сообщений22872288Есть еще один, возможно, более простой способ использовать {}- и $-форматирование для построения отдельных сообщений лога. Вы, возможно, помните (из раздела [Использование произвольных объектов в качестве сообщений](https://python-all.ru/3.15/howto/logging.html#arbitrary-object-messages)), что при логировании можно использовать произвольный объект в качестве строки формата сообщения, и пакет logging вызовет [`str()`](https://python-all.ru/3.15/library/stdtypes.html#str) для этого объекта, чтобы получить фактическую строку формата. Рассмотрим следующие два класса:22892290```python2291class BraceMessage:2292 def __init__(self, fmt, /, *args, **kwargs):2293 self.fmt = fmt2294 self.args = args2295 self.kwargs = kwargs22962297 def __str__(self):2298 return self.fmt.format(*self.args, **self.kwargs)22992300class DollarMessage:2301 def __init__(self, fmt, /, **kwargs):2302 self.fmt = fmt2303 self.kwargs = kwargs23042305 def __str__(self):2306 from string import Template2307 return Template(self.fmt).substitute(**self.kwargs)2308```23092310Любой из них можно использовать вместо строки формата, чтобы разрешить {}- или $-форматирование для построения фактической части «message», которая появляется в форматированном выводе лога вместо «%(message)s», «{message}» или «$message». Если вам кажется неудобным использовать имена классов каждый раз при логировании, вы можете сделать это более приятным, используя псевдоним, такой как `M` или `_` для сообщения (или, возможно, `__`, если вы используете `_` для локализации).23112312Примеры этого подхода приведены ниже. Во-первых, форматирование с помощью [`str.format()`](https://python-all.ru/3.15/library/stdtypes.html#str.format):23132314```python2315>>> __ = BraceMessage2316>>> print(__('Message with {0} {1}', 2, 'placeholders'))2317Message with 2 placeholders2318>>> class Point: pass2319...2320>>> p = Point()2321>>> p.x = 0.52322>>> p.y = 0.52323>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))2324Message with coordinates: (0.50, 0.50)2325```23262327Во-вторых, форматирование с помощью [`string.Template`](https://python-all.ru/3.15/library/string.html#string.Template):23282329```python2330>>> __ = DollarMessage2331>>> print(__('Message with $num $what', num=2, what='placeholders'))2332Message with 2 placeholders2333>>>2334```23352336Стоит отметить, что при таком подходе вы не платите значительных потерь производительности: фактическое форматирование происходит не при вызове логирования, а когда (и если) сообщение лога действительно должно быть выведено в лог обработчиком. Так что единственная необычная вещь, которая может вас сбить с толку, это то, что круглые скобки ставятся вокруг строки формата и аргументов, а не только вокруг строки формата. Это потому, что нотация \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов `XXXMessage`, показанных выше.23372338## Настройка фильтров с помощью [`dictConfig()`](https://python-all.ru/3.15/library/logging.config.html#logging.config.dictConfig)23392340*Можно* настраивать фильтры с помощью [`dictConfig()`](https://python-all.ru/3.15/library/logging.config.html#logging.config.dictConfig), хотя с первого взгляда может быть неочевидно, как это сделать (поэтому и дан этот рецепт). Поскольку [`Filter`](https://python-all.ru/3.15/library/logging.html#logging.Filter) – единственный класс фильтра, включенный в стандартную библиотеку, и вряд ли он удовлетворит многие требования (он присутствует только как базовый класс), вам, как правило, потребуется определить свой собственный подкласс `Filter` с переопределенным методом [`filter()`](https://python-all.ru/3.15/library/logging.html#logging.Filter.filter). Для этого укажите ключ `()` в словаре конфигурации для фильтра, указав вызываемый объект, который будет использоваться для создания фильтра (класс – наиболее очевидный вариант, но вы можете предоставить любой вызываемый объект, возвращающий экземпляр `Filter`). Вот полный пример:23412342```python2343import logging2344import logging.config2345import sys23462347class MyFilter(logging.Filter):2348 def __init__(self, param=None):2349 self.param = param23502351 def filter(self, record):2352 if self.param is None:2353 allow = True2354 else:2355 allow = self.param not in record.msg2356 if allow:2357 record.msg = 'changed: ' + record.msg2358 return allow23592360LOGGING = {2361 'version': 1,2362 'filters': {2363 'myfilter': {2364 '()': MyFilter,2365 'param': 'noshow',2366 }2367 },2368 'handlers': {2369 'console': {2370 'class': 'logging.StreamHandler',2371 'filters': ['myfilter']2372 }2373 },2374 'root': {2375 'level': 'DEBUG',2376 'handlers': ['console']2377 },2378}23792380if __name__ == '__main__':2381 logging.config.dictConfig(LOGGING)2382 logging.debug('hello')2383 logging.debug('hello - noshow')2384```23852386Этот пример показывает, как можно передавать конфигурационные данные вызываемому объекту, который создает экземпляр, в виде именованных параметров. При запуске приведенный выше скрипт выведет:23872388```text2389changed: hello2390```23912392что показывает, что фильтр работает в соответствии с настройками.23932394Несколько дополнительных моментов, на которые стоит обратить внимание:23952396- Если вы не можете сослаться на вызываемый объект напрямую в конфигурации (например, если он находится в другом модуле, и вы не можете импортировать его напрямую в том месте, где находится словарь конфигурации), вы можете использовать форму `ext://...`, как описано в разделе [Доступ к внешним объектам](https://python-all.ru/3.15/library/logging.config.html#logging-config-dict-externalobj). Например, в приведенном выше примере можно было использовать текст `'ext://__main__.MyFilter'` вместо `MyFilter`.2397- Помимо фильтров, этот метод также можно использовать для настройки пользовательских обработчиков и форматтеров. Смотрите раздел [Пользовательские объекты](https://python-all.ru/3.15/library/logging.config.html#logging-config-dict-userdef) для получения дополнительной информации о том, как logging поддерживает использование пользовательских объектов в своей конфигурации, а также см. другой рецепт из этой книги рецептов [Настройка обработчиков с помощью dictConfig()](https://python-all.ru/3.15/howto/logging-cookbook.html#custom-handlers) выше.23982399## Настраиваемое форматирование исключений24002401Могут возникнуть ситуации, когда вы захотите настроить форматирование исключений – для примера, предположим, вы хотите ровно одну строку на каждое событие лога, даже если присутствует информация об исключении. Вы можете сделать это с помощью пользовательского класса форматтера, как показано в следующем примере:24022403```python2404import logging24052406class OneLineExceptionFormatter(logging.Formatter):2407 def formatException(self, exc_info):2408 """2409 Форматировать исключение так, чтобы оно выводилось одной строкой.2410 """2411 result = super().formatException(exc_info)2412 return repr(result) # или форматировать одной строкой по своему усмотрению24132414 def format(self, record):2415 s = super().format(record)2416 if record.exc_text:2417 s = s.replace('\n', '') + '|'2418 return s24192420def configure_logging():2421 fh = logging.FileHandler('output.txt', 'w')2422 f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',2423 '%d/%m/%Y %H:%M:%S')2424 fh.setFormatter(f)2425 root = logging.getLogger()2426 root.setLevel(logging.DEBUG)2427 root.addHandler(fh)24282429def main():2430 configure_logging()2431 logging.info('Sample message')2432 try:2433 x = 1 / 02434 except ZeroDivisionError as e:2435 logging.exception('ZeroDivisionError: %s', e)24362437if __name__ == '__main__':2438 main()2439```24402441При запуске это создает файл ровно с двумя строками:24422443```text244428/01/2015 07:21:23|INFO|Sample message|244528/01/2015 07:21:23|ERROR|ZeroDivisionError: division by zero|'Traceback (most recent call last):\n File "logtest7.py", line 30, in main\n x = 1 / 0\nZeroDivisionError: division by zero'|2446```24472448Хотя описанный выше подход упрощен, он показывает путь к тому, как можно форматировать информацию об исключениях по своему вкусу. Модуль [`traceback`](https://python-all.ru/3.15/library/traceback.html#module-traceback) может быть полезен для более специализированных нужд.24492450## Озвучивание сообщений лога24512452Могут быть ситуации, когда желательно выводить сообщения лога в звуковом, а не визуальном формате. Это легко сделать, если в вашей системе доступна функция преобразования текста в речь (TTS), даже если у нее нет привязки к Python. Большинство TTS-систем имеют программу командной строки, которую можно запустить, и ее можно вызвать из обработчика с помощью [`subprocess`](https://python-all.ru/3.15/library/subprocess.html#module-subprocess). Здесь предполагается, что программы командной строки TTS не будут ожидать взаимодействия с пользователем или занимать много времени для завершения, и что частота сообщений лога не будет настолько высокой, чтобы перегружать пользователя сообщениями, и что допустимо проговаривать сообщения по одному, а не одновременно. В приведенном ниже примере реализации ожидается, пока одно сообщение не будет произнесено, прежде чем обрабатывать следующее, и это может заставить другие обработчики ждать. Вот короткий пример, демонстрирующий подход, который предполагает, что доступен TTS-пакет `espeak`:24532454```python2455import logging2456import subprocess2457import sys24582459class TTSHandler(logging.Handler):2460 def emit(self, record):2461 msg = self.format(record)2462 # Говорить медленно женским английским голосом.2463 cmd = ['espeak', '-s150', '-ven+f3', msg]2464 p = subprocess.Popen(cmd, stdout=subprocess.PIPE,2465 stderr=subprocess.STDOUT)2466 # дождаться завершения программы2467 p.communicate()24682469def configure_logging():2470 h = TTSHandler()2471 root = logging.getLogger()2472 root.addHandler(h)2473 # стандартный форматтер просто возвращает сообщение2474 root.setLevel(logging.DEBUG)24752476def main():2477 logging.info('Hello')2478 logging.debug('Goodbye')24792480if __name__ == '__main__':2481 configure_logging()2482 sys.exit(main())2483```24842485При запуске этот скрипт должен сказать «Hello», а затем «Goodbye» женским голосом.24862487Описанный выше подход, конечно, можно адаптировать для других TTS-систем и даже для других систем, которые могут обрабатывать сообщения через внешние программы, запускаемые из командной строки.24882489## Буферизация сообщений лога и условный вывод24902491Могут возникнуть ситуации, когда вы хотите записывать сообщения во временную область и выводить их только при наступлении определенного условия. Например, вы можете начать запись отладочных событий в функции, и если функция завершится без ошибок, вы не захотите засорять лог собранной отладочной информацией, но если возникнет ошибка, вы захотите вывести всю отладочную информацию вместе с ошибкой.24922493Вот пример, показывающий, как это можно сделать с помощью декоратора для ваших функций, где вы хотите, чтобы логирование вело себя таким образом. Он использует [`logging.handlers.MemoryHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.MemoryHandler), который позволяет буферизовать зарегистрированные события до наступления некоторого условия, после чего буферизованные события `flushed` – передаются другому обработчику (обработчику `target`) для обработки. По умолчанию `MemoryHandler` сбрасывается, когда его буфер заполняется или встречается событие, уровень которого больше или равен указанному порогу. Вы можете использовать этот рецепт с более специализированным подклассом `MemoryHandler`, если хотите настроить поведение сброса.24942495Пример скрипта содержит простую функцию `foo`, которая просто перебирает все уровни логирования, записывая в `sys.stderr` информацию о том, какой уровень будет использоваться, а затем регистрирует сообщение на этом уровне. Вы можете передать параметр в `foo`, который, если равен true, будет регистрировать на уровнях ERROR и CRITICAL – в противном случае он регистрирует только на уровнях DEBUG, INFO и WARNING.24962497Скрипт просто настраивает декорирование `foo` декоратором, который будет выполнять необходимое условное логирование. Декоратор принимает регистратор в качестве параметра и подключает обработчик памяти на время вызова декорированной функции. Декоратор можно дополнительно параметризовать с помощью целевого обработчика, уровня, при котором должен происходить сброс, и емкости буфера (количество буферизируемых записей). По умолчанию они равны [`StreamHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.StreamHandler), который пишет в `sys.stderr`, `logging.ERROR` и `100` соответственно.24982499Вот скрипт:25002501```python2502import logging2503from logging.handlers import MemoryHandler2504import sys25052506logger = logging.getLogger(__name__)2507logger.addHandler(logging.NullHandler())25082509def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):2510 if target_handler is None:2511 target_handler = logging.StreamHandler()2512 if flush_level is None:2513 flush_level = logging.ERROR2514 if capacity is None:2515 capacity = 1002516 handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)25172518 def decorator(fn):2519 def wrapper(*args, **kwargs):2520 logger.addHandler(handler)2521 try:2522 return fn(*args, **kwargs)2523 except Exception:2524 logger.exception('call failed')2525 raise2526 finally:2527 super(MemoryHandler, handler).flush()2528 logger.removeHandler(handler)2529 return wrapper25302531 return decorator25322533def write_line(s):2534 sys.stderr.write('%s\n' % s)25352536def foo(fail=False):2537 write_line('about to log at DEBUG ...')2538 logger.debug('Actually logged at DEBUG')2539 write_line('about to log at INFO ...')2540 logger.info('Actually logged at INFO')2541 write_line('about to log at WARNING ...')2542 logger.warning('Actually logged at WARNING')2543 if fail:2544 write_line('about to log at ERROR ...')2545 logger.error('Actually logged at ERROR')2546 write_line('about to log at CRITICAL ...')2547 logger.critical('Actually logged at CRITICAL')2548 return fail25492550decorated_foo = log_if_errors(logger)(foo)25512552if __name__ == '__main__':2553 logger.setLevel(logging.DEBUG)2554 write_line('Calling undecorated foo with False')2555 assert not foo(False)2556 write_line('Calling undecorated foo with True')2557 assert foo(True)2558 write_line('Calling decorated foo with False')2559 assert not decorated_foo(False)2560 write_line('Calling decorated foo with True')2561 assert decorated_foo(True)2562```25632564При запуске этого скрипта отобразится следующий вывод:25652566```text2567Calling undecorated foo with False2568about to log at DEBUG ...2569about to log at INFO ...2570about to log at WARNING ...2571Calling undecorated foo with True2572about to log at DEBUG ...2573about to log at INFO ...2574about to log at WARNING ...2575about to log at ERROR ...2576about to log at CRITICAL ...2577Calling decorated foo with False2578about to log at DEBUG ...2579about to log at INFO ...2580about to log at WARNING ...2581Calling decorated foo with True2582about to log at DEBUG ...2583about to log at INFO ...2584about to log at WARNING ...2585about to log at ERROR ...2586Actually logged at DEBUG2587Actually logged at INFO2588Actually logged at WARNING2589Actually logged at ERROR2590about to log at CRITICAL ...2591Actually logged at CRITICAL2592```25932594Как видно, фактический вывод журнала происходит только при регистрации события, уровень которого ERROR или выше, но в этом случае также регистрируются все предыдущие события с более низкими уровнями.25952596Конечно, можно использовать обычные средства декорирования:25972598```python2599@log_if_errors(logger)2600def foo(fail=False):2601 ...2602```26032604## Отправка сообщений журнала по электронной почте с буферизацией26052606Чтобы проиллюстрировать, как можно отправлять сообщения журнала по электронной почте, так чтобы заданное количество сообщений отправлялось за одно письмо, можно создать подкласс [`BufferingHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.BufferingHandler). В приведённом ниже примере, который можно адаптировать под свои нужды, предоставляется простая тестовая обвязка, позволяющая запустить скрипт с аргументами командной строки, указывающими, что обычно необходимо для отправки через SMTP. (Запустите загруженный скрипт с аргументом `-h`, чтобы увидеть обязательные и необязательные аргументы.)26072608```python2609import logging2610import logging.handlers2611import smtplib26122613class BufferingSMTPHandler(logging.handlers.BufferingHandler):2614 def __init__(self, mailhost, port, username, password, fromaddr, toaddrs,2615 subject, capacity):2616 logging.handlers.BufferingHandler.__init__(self, capacity)2617 self.mailhost = mailhost2618 self.mailport = port2619 self.username = username2620 self.password = password2621 self.fromaddr = fromaddr2622 if isinstance(toaddrs, str):2623 toaddrs = [toaddrs]2624 self.toaddrs = toaddrs2625 self.subject = subject2626 self.setFormatter(logging.Formatter("%(asctime)s %(levelname)-5s %(message)s"))26272628 def flush(self):2629 if len(self.buffer) > 0:2630 try:2631 smtp = smtplib.SMTP(self.mailhost, self.mailport)2632 smtp.starttls()2633 smtp.login(self.username, self.password)2634 msg = "From: %s\r\nTo: %s\r\nSubject: %s\r\n\r\n" % (self.fromaddr, ','.join(self.toaddrs), self.subject)2635 for record in self.buffer:2636 s = self.format(record)2637 msg = msg + s + "\r\n"2638 smtp.sendmail(self.fromaddr, self.toaddrs, msg)2639 smtp.quit()2640 except Exception:2641 if logging.raiseExceptions:2642 raise2643 self.buffer = []26442645if __name__ == '__main__':2646 import argparse26472648 ap = argparse.ArgumentParser()2649 aa = ap.add_argument2650 aa('host', metavar='HOST', help='SMTP server')2651 aa('--port', '-p', type=int, default=587, help='SMTP port')2652 aa('user', metavar='USER', help='SMTP username')2653 aa('password', metavar='PASSWORD', help='SMTP password')2654 aa('to', metavar='TO', help='Addressee for emails')2655 aa('sender', metavar='SENDER', help='Sender email address')2656 aa('--subject', '-s',2657 default='Test Logging email from Python logging module (buffering)',2658 help='Subject of email')2659 options = ap.parse_args()2660 logger = logging.getLogger()2661 logger.setLevel(logging.DEBUG)2662 h = BufferingSMTPHandler(options.host, options.port, options.user,2663 options.password, options.sender,2664 options.to, options.subject, 10)2665 logger.addHandler(h)2666 for i in range(102):2667 logger.info("Info index = %d", i)2668 h.flush()2669 h.close()2670```26712672Если запустить этот скрипт и SMTP-сервер настроен правильно, то будет отправлено одиннадцать писем указанному адресату. Первые десять писем будут содержать по десять сообщений журнала, а одиннадцатое – два сообщения. В сумме получается 102 сообщения, как указано в скрипте.26732674## Форматирование времени с использованием UTC (GMT) через конфигурацию26752676Иногда требуется форматировать время в UTC, что можно сделать с помощью класса `UTCFormatter`, показанного ниже:26772678```python2679import logging2680import time26812682class UTCFormatter(logging.Formatter):2683 converter = time.gmtime2684```26852686и затем можно использовать `UTCFormatter` в своём коде вместо [`Formatter`](https://python-all.ru/3.15/library/logging.html#logging.Formatter). Если требуется сделать это через конфигурацию, можно воспользоваться API [`dictConfig()`](https://python-all.ru/3.15/library/logging.config.html#logging.config.dictConfig), как показано в следующем полном примере:26872688```python2689import logging2690import logging.config2691import time26922693class UTCFormatter(logging.Formatter):2694 converter = time.gmtime26952696LOGGING = {2697 'version': 1,2698 'disable_existing_loggers': False,2699 'formatters': {2700 'utc': {2701 '()': UTCFormatter,2702 'format': '%(asctime)s %(message)s',2703 },2704 'local': {2705 'format': '%(asctime)s %(message)s',2706 }2707 },2708 'handlers': {2709 'console1': {2710 'class': 'logging.StreamHandler',2711 'formatter': 'utc',2712 },2713 'console2': {2714 'class': 'logging.StreamHandler',2715 'formatter': 'local',2716 },2717 },2718 'root': {2719 'handlers': ['console1', 'console2'],2720 }2721}27222723if __name__ == '__main__':2724 logging.config.dictConfig(LOGGING)2725 logging.warning('The local time is %s', time.asctime())2726```27272728При запуске этого скрипта он должен вывести примерно следующее:27292730```text27312015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 201527322015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 20152733```27342735показывая, как время форматируется как в местном времени, так и в UTC, по одному для каждого обработчика.27362737## Использование контекстного менеджера для выборочного журналирования27382739Бывают ситуации, когда полезно временно изменить конфигурацию журналирования, а затем вернуть её обратно после выполнения каких-то действий. Для этого контекстный менеджер – самый очевидный способ сохранить и восстановить контекст журналирования. Вот простой пример такого контекстного менеджера, который позволяет по желанию изменить уровень журналирования и добавить обработчик журнала исключительно в области действия контекстного менеджера:27402741```python2742import logging2743import sys27442745class LoggingContext:2746 def __init__(self, logger, level=None, handler=None, close=True):2747 self.logger = logger2748 self.level = level2749 self.handler = handler2750 self.close = close27512752 def __enter__(self):2753 if self.level is not None:2754 self.old_level = self.logger.level2755 self.logger.setLevel(self.level)2756 if self.handler:2757 self.logger.addHandler(self.handler)27582759 def __exit__(self, et, ev, tb):2760 if self.level is not None:2761 self.logger.setLevel(self.old_level)2762 if self.handler:2763 self.logger.removeHandler(self.handler)2764 if self.handler and self.close:2765 self.handler.close()2766 # неявный возврат None => не подавлять исключения2767```27682769Если указать значение уровня, уровень регистратора устанавливается на это значение в области действия блока with, охватываемого контекстным менеджером. Если указать обработчик, он добавляется к регистратору при входе в блок и удаляется при выходе из блока. Также можно попросить менеджер закрыть обработчик при выходе из блока – это можно сделать, если обработчик больше не нужен.27702771Чтобы проиллюстрировать, как это работает, можно добавить следующий блок кода к предыдущему:27722773```python2774if __name__ == '__main__':2775 logger = logging.getLogger('foo')2776 logger.addHandler(logging.StreamHandler())2777 logger.setLevel(logging.INFO)2778 logger.info('1. This should appear just once on stderr.')2779 logger.debug('2. This should not appear.')2780 with LoggingContext(logger, level=logging.DEBUG):2781 logger.debug('3. This should appear once on stderr.')2782 logger.debug('4. This should not appear.')2783 h = logging.StreamHandler(sys.stdout)2784 with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):2785 logger.debug('5. This should appear twice - once on stderr and once on stdout.')2786 logger.info('6. This should appear just once on stderr.')2787 logger.debug('7. This should not appear.')2788```27892790Изначально устанавливаем уровень регистратора равным `INFO`, поэтому сообщение №1 отображается, а сообщение №2 – нет. Затем временно меняем уровень на `DEBUG` в следующем блоке `with`, и сообщение №3 отображается. После выхода из блока уровень регистратора восстанавливается до `INFO`, поэтому сообщение №4 не отображается. В следующем блоке `with` снова устанавливаем уровень `DEBUG`, но также добавляем обработчик, записывающий в `sys.stdout`. Таким образом, сообщение №5 отображается дважды на консоли (один раз через `stderr` и один раз через `stdout`). После завершения оператора `with` состояние возвращается к исходному, поэтому сообщение №6 отображается (как сообщение №1), а сообщение №7 – нет (как сообщение №2).27912792Если запустить полученный скрипт, результат будет следующим:27932794```console2795$ python logctx.py27961. This should appear just once on stderr.27973. This should appear once on stderr.27985. This should appear twice - once on stderr and once on stdout.27995. This should appear twice - once on stderr and once on stdout.28006. This should appear just once on stderr.2801```28022803Если запустить его снова, но перенаправить `stderr` в `/dev/null`, мы увидим следующее, что является единственным сообщением, записанным в `stdout`:28042805```console2806$ python logctx.py 2>/dev/null28075. This should appear twice - once on stderr and once on stdout.2808```28092810Ещё раз, но перенаправляя `stdout` в `/dev/null`, получаем:28112812```console2813$ python logctx.py >/dev/null28141. This should appear just once on stderr.28153. This should appear once on stderr.28165. This should appear twice - once on stderr and once on stdout.28176. This should appear just once on stderr.2818```28192820В этом случае сообщение №5, выведенное в `stdout`, не отображается, как и ожидалось.28212822Разумеется, описанный подход можно обобщить, например, для временного подключения фильтров журналирования. Обратите внимание, что приведённый выше код работает как в Python 2, так и в Python 3.28232824## Шаблон для запуска CLI-приложения28252826Вот пример, показывающий, как можно:28272828- Использовать уровень журналирования на основе аргументов командной строки2829- Перенаправлять вызовы к нескольким подкомандам в отдельных файлах, все с журналированием на одном уровне согласованным образом2830- Использовать простую минимальную конфигурацию28312832Предположим, у нас есть приложение командной строки, которое останавливает, запускает или перезапускает некоторые службы. Для иллюстрации это может быть организовано в виде файла `app.py`, который является главным скриптом приложения, с отдельными командами, реализованными в `start.py`, `stop.py` и `restart.py`. Предположим также, что мы хотим управлять степенью подробности вывода приложения через аргумент командной строки с значением по умолчанию `logging.INFO`. Вот один из способов, как мог бы быть написан `app.py`:28332834```python2835import argparse2836import importlib2837import logging2838import os2839import sys28402841def main(args=None):2842 scriptname = os.path.basename(__file__)2843 parser = argparse.ArgumentParser(scriptname)2844 levels = ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')2845 parser.add_argument('--log-level', default='INFO', choices=levels)2846 subparsers = parser.add_subparsers(dest='command',2847 help='Available commands:')2848 start_cmd = subparsers.add_parser('start', help='Start a service')2849 start_cmd.add_argument('name', metavar='NAME',2850 help='Name of service to start')2851 stop_cmd = subparsers.add_parser('stop',2852 help='Stop one or more services')2853 stop_cmd.add_argument('names', metavar='NAME', nargs='+',2854 help='Name of service to stop')2855 restart_cmd = subparsers.add_parser('restart',2856 help='Restart one or more services')2857 restart_cmd.add_argument('names', metavar='NAME', nargs='+',2858 help='Name of service to restart')2859 options = parser.parse_args()2860 # весь код для отправки команд мог бы быть в этом файле. Для целей2861 # только в целях иллюстрации каждая команда реализована в отдельном модуле.2862 try:2863 mod = importlib.import_module(options.command)2864 cmd = getattr(mod, 'command')2865 except (ImportError, AttributeError):2866 print('Unable to find the code for command \'%s\'' % options.command)2867 return 12868 # Здесь можно было бы сделать по-хитрому и загрузить конфигурацию из файла или словаря2869 logging.basicConfig(level=options.log_level,2870 format='%(levelname)s %(name)s %(message)s')2871 cmd(options)28722873if __name__ == '__main__':2874 sys.exit(main())2875```28762877А команды `start`, `stop` и `restart` могут быть реализованы в отдельных модулях, например, для запуска:28782879```python2880# start.py2881import logging28822883logger = logging.getLogger(__name__)28842885def command(options):2886 logger.debug('About to start %s', options.name)2887 # здесь происходит фактическая обработка команды...2888 logger.info('Started the \'%s\' service.', options.name)2889```28902891и аналогично для остановки:28922893```python2894# stop.py2895import logging28962897logger = logging.getLogger(__name__)28982899def command(options):2900 n = len(options.names)2901 if n == 1:2902 plural = ''2903 services = '\'%s\'' % options.names[0]2904 else:2905 plural = 's'2906 services = ', '.join('\'%s\'' % name for name in options.names)2907 i = services.rfind(', ')2908 services = services[:i] + ' and ' + services[i + 2:]2909 logger.debug('About to stop %s', services)2910 # здесь происходит фактическая обработка команды...2911 logger.info('Stopped the %s service%s.', services, plural)2912```29132914и аналогично для перезапуска:29152916```python2917# restart.py2918import logging29192920logger = logging.getLogger(__name__)29212922def command(options):2923 n = len(options.names)2924 if n == 1:2925 plural = ''2926 services = '\'%s\'' % options.names[0]2927 else:2928 plural = 's'2929 services = ', '.join('\'%s\'' % name for name in options.names)2930 i = services.rfind(', ')2931 services = services[:i] + ' and ' + services[i + 2:]2932 logger.debug('About to restart %s', services)2933 # здесь происходит фактическая обработка команды...2934 logger.info('Restarted the %s service%s.', services, plural)2935```29362937Если запустить это приложение с уровнем журналирования по умолчанию, мы получим примерно такой вывод:29382939```console2940$ python app.py start foo2941INFO start Started the 'foo' service.29422943$ python app.py stop foo bar2944INFO stop Stopped the 'foo' and 'bar' services.29452946$ python app.py restart foo bar baz2947INFO restart Restarted the 'foo', 'bar' and 'baz' services.2948```29492950Первое слово – уровень журналирования, а второе – имя модуля или пакета, в котором было зарегистрировано событие.29512952Если изменить уровень журналирования, можно изменить объём информации, отправляемой в журнал. Например, чтобы получить больше информации:29532954```console2955$ python app.py --log-level DEBUG start foo2956DEBUG start About to start foo2957INFO start Started the 'foo' service.29582959$ python app.py --log-level DEBUG stop foo bar2960DEBUG stop About to stop 'foo' and 'bar'2961INFO stop Stopped the 'foo' and 'bar' services.29622963$ python app.py --log-level DEBUG restart foo bar baz2964DEBUG restart About to restart 'foo', 'bar' and 'baz'2965INFO restart Restarted the 'foo', 'bar' and 'baz' services.2966```29672968А если нужно меньше:29692970```console2971$ python app.py --log-level WARNING start foo2972$ python app.py --log-level WARNING stop foo bar2973$ python app.py --log-level WARNING restart foo bar baz2974```29752976В этом случае команды ничего не выводят в консоль, поскольку ни одно сообщение уровня `WARNING` и выше ими не записывается.29772978## Графический интерфейс Qt для журналирования29792980Время от времени возникает вопрос о том, как вести журналирование в приложении с графическим интерфейсом. Фреймворк [Qt](https://python-all.ru/3.15/howto/logging-cookbook.html) – популярный кроссплатформенный инструмент для создания UI, имеющий привязки к Python через библиотеки [PySide2](https://python-all.ru/3.15/howto/logging-cookbook.html) или [PyQt5](https://python-all.ru/3.15/howto/logging-cookbook.html).29812982В следующем примере показано, как выполнять журналирование в графический интерфейс Qt. Он представляет простой класс `QtHandler`, который принимает вызываемый объект – слот главного потока, обновляющий GUI. Также создаётся рабочий поток, чтобы продемонстрировать возможность журналирования как из самого интерфейса (через кнопку для ручной записи), так и из фонового рабочего потока (который в данном случае просто выводит сообщения со случайными уровнями и случайными короткими задержками).29832984Рабочий поток реализован с помощью класса `QThread` из Qt, а не модуля [`threading`](https://python-all.ru/3.15/library/threading.html#module-threading), поскольку бывают ситуации, когда необходимо использовать `QThread`, который обеспечивает лучшую интеграцию с другими компонентами `Qt`.29852986Код должен работать с последними версиями `PySide6`, `PyQt6`, `PySide2` или `PyQt5`. Вы сможете адаптировать этот подход для более ранних версий Qt. Обратитесь к комментариям в примере кода за более подробной информацией.29872988```python2989import logging2990import random2991import sys2992import time29932994# Обработка небольших различий между разными пакетами Qt2995try:2996 from PySide6 import QtCore, QtGui, QtWidgets2997 Signal = QtCore.Signal2998 Slot = QtCore.Slot2999except ImportError:3000 try:3001 from PyQt6 import QtCore, QtGui, QtWidgets3002 Signal = QtCore.pyqtSignal3003 Slot = QtCore.pyqtSlot3004 except ImportError:3005 try:3006 from PySide2 import QtCore, QtGui, QtWidgets3007 Signal = QtCore.Signal3008 Slot = QtCore.Slot3009 except ImportError:3010 from PyQt5 import QtCore, QtGui, QtWidgets3011 Signal = QtCore.pyqtSignal3012 Slot = QtCore.pyqtSlot30133014logger = logging.getLogger(__name__)30153016#3017# Сигналы должны содержаться в QObject или подклассе, чтобы корректно3018# инициализироваться.3019#3020class Signaller(QtCore.QObject):3021 signal = Signal(str, logging.LogRecord)30223023#3024# Вывод в графический интерфейс Qt должен происходить только в главном потоке. Поэтому данный3025# обработчик спроектирован так, чтобы принимать функцию-слот, настроенную на выполнение в главном3026# потоке. В этом примере функция принимает строковый аргумент, который является3027# отформатированным сообщением лога, и запись лога, которая его породила. Отформатированная3028# строка – это просто удобство; можно отформатировать строку для вывода любым способом3029# в самой функции-слоте.3030#3031# Функцию-слот можно настроить на любые нужные обновления GUI. Обработчик3032# не знает и не заботится о конкретных элементах интерфейса.3033#3034class QtHandler(logging.Handler):3035 def __init__(self, slotfunc, *args, **kwargs):3036 super().__init__(*args, **kwargs)3037 self.signaller = Signaller()3038 self.signaller.signal.connect(slotfunc)30393040 def emit(self, record):3041 s = self.format(record)3042 self.signaller.signal.emit(s, record)30433044#3045# В этом примере используются QThreads, что означает, что потоки на уровне Python3046# называются как-то вроде "Dummy-1". Функция ниже получает имя Qt3047# текущего потока.3048#3049def ctname():3050 return QtCore.QThread.currentThread().objectName()30513052#3053# Используется для генерации случайных уровней для логирования.3054#3055LEVELS = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,3056 logging.CRITICAL)30573058#3059# Этот класс-воркер представляет работу, выполняемую в потоке, отдельном от3060# главного потока. Поток запускается на выполнение работы по нажатию кнопки,3061# которая соединяется со слотом в воркере.3062#3063# Поскольку значение threadName по умолчанию в LogRecord не очень полезно, мы добавляем3064# qThreadName, содержащий имя QThread, вычисленное выше, и передаём это3065# значение в словаре "extra", который используется для обновления LogRecord с помощью3066# имя QThread.3067#3068# Этот пример рабочего просто выводит сообщения последовательно, перемежая их случайными задержками порядка нескольких секунд.3069# Позволяет потоку выполняться до прерывания. Это обеспечивает достаточно чистую остановку потока.3070#3071class Worker(QtCore.QObject):3072 @Slot()3073 def start(self):3074 extra = {'qThreadName': ctname() }3075 logger.debug('Started work', extra=extra)3076 i = 13077 # Реализует простой пользовательский интерфейс для этого примера из кулинарной книги. Он содержит:3078 # * Окно текстового редактора только для чтения, которое содержит форматированные сообщения журнала3079 while not QtCore.QThread.currentThread().isInterruptionRequested():3080 delay = 0.5 + random.random() * 23081 time.sleep(delay)3082 try:3083 if random.random() < 0.1:3084 raise ValueError('Exception raised: %d' % i)3085 else:3086 level = random.choice(LEVELS)3087 logger.log(level, 'Message after delay of %3.1f: %d', delay, i, extra=extra)3088 except ValueError as e:3089 logger.exception('Failed: %s', e, extra=extra)3090 i += 130913092#3093# * Кнопка запуска работы и записи в журнал в отдельном потоке3094#3095# * Кнопка записи чего-либо из основного потока3096# * Кнопка очистки окна журнала3097# Устанавливает моноширинный шрифт, принятый по умолчанию на платформе3098# для Qt63099#3100class Window(QtWidgets.QWidget):31013102 COLORS = {3103 logging.DEBUG: 'black',3104 logging.INFO: 'blue',3105 logging.WARNING: 'orange',3106 logging.ERROR: 'red',3107 logging.CRITICAL: 'purple',3108 }31093110 def __init__(self, app):3111 super().__init__()3112 self.app = app3113 self.textedit = te = QtWidgets.QPlainTextEdit(self)3114 # Устанавливает моноширинный шрифт по умолчанию для платформы3115 f = QtGui.QFont('nosuchfont')3116 if hasattr(f, 'Monospace'):3117 f.setStyleHint(f.Monospace)3118 else:3119 f.setStyleHint(f.StyleHint.Monospace) # для Qt63120 te.setFont(f)3121 te.setReadOnly(True)3122 PB = QtWidgets.QPushButton3123 self.work_button = PB('Start background work', self)3124 self.log_button = PB('Log a message at a random level', self)3125 self.clear_button = PB('Clear log window', self)3126 self.handler = h = QtHandler(self.update_status)3127 # Размещает все виджеты3128 fs = '%(asctime)s %(qThreadName)-12s %(levelname)-8s %(message)s'3129 formatter = logging.Formatter(fs)3130 h.setFormatter(formatter)3131 logger.addHandler(h)3132 # Подключает слоты и сигналы, не относящиеся к рабочему3133 app.aboutToQuit.connect(self.force_quit)31343135 # Запускает новый рабочий поток и подключает слоты для рабочего3136 layout = QtWidgets.QVBoxLayout(self)3137 layout.addWidget(te)3138 layout.addWidget(self.work_button)3139 layout.addWidget(self.log_button)3140 layout.addWidget(self.clear_button)3141 self.setFixedSize(900, 400)31423143 # После запуска кнопка должна быть отключена3144 self.log_button.clicked.connect(self.manual_update)3145 self.clear_button.clicked.connect(self.clear_display)31463147 # Запустить новый рабочий поток и подключить слоты для рабочего3148 self.start_thread()3149 self.work_button.clicked.connect(self.worker.start)3150 # Это запустит цикл событий в рабочем потоке3151 self.work_button.clicked.connect(lambda : self.work_button.setEnabled(False))31523153 def start_thread(self):3154 self.worker = Worker()3155 self.worker_thread = QtCore.QThread()3156 self.worker.setObjectName('Worker')3157 self.worker_thread.setObjectName('WorkerThread') # Просто скажите рабочему остановиться, затем скажите ему выйти и дождитесь этого3158 self.worker.moveToThread(self.worker_thread)3159 # Для использования при закрытии окна3160 self.worker_thread.start()31613162 def kill_thread(self):3163 # Функции ниже обновляют интерфейс и выполняются в основном потоке, поскольку слоты настроены именно там3164 # Эта функция использует переданное форматированное сообщение, но также использует информацию из записи, чтобы отформатировать сообщение подходящим цветом в соответствии с его серьёзностью (уровнем).3165 self.worker_thread.requestInterruption()3166 if self.worker_thread.isRunning():3167 self.worker_thread.quit()3168 self.worker_thread.wait()3169 else:3170 print('worker has already exited.')31713172 def force_quit(self):3173 # Для использования при закрытии окна3174 if self.worker_thread.isRunning():3175 self.kill_thread()31763177 # Функции ниже обновляют пользовательский интерфейс и выполняются в главном потоке, потому что3178 # здесь настраиваются слоты31793180 @Slot(str, logging.LogRecord)3181 def update_status(self, status, record):3182 color = self.COLORS.get(record.levelno, 'black')3183 s = '<pre><font color="%s">%s</font></pre>' % (color, status)3184 self.textedit.appendHtml(s)31853186 @Slot()3187 def manual_update(self):3188 # Эта функция использует переданное форматированное сообщение, а также использует3189 # информацию из записи для форматирования сообщения в подходящий3190 # цвет в соответствии с его серьёзностью (уровнем).3191 level = random.choice(LEVELS)3192 extra = {'qThreadName': ctname() }3193 logger.log(level, 'Manually logged!', extra=extra)31943195 @Slot()3196 def clear_display(self):3197 self.textedit.clear()31983199def main():3200 QtCore.QThread.currentThread().setObjectName('MainThread')3201 logging.getLogger().setLevel(logging.DEBUG)3202 app = QtWidgets.QApplication(sys.argv)3203 example = Window(app)3204 example.show()3205 if hasattr(app, 'exec'):3206 rc = app.exec()3207 else:3208 rc = app.exec_()3209 sys.exit(rc)32103211if __name__=='__main__':3212 main()3213```32143215## Журналирование в syslog с поддержкой RFC 542432163217Хотя [**RFC 5424**](https://python-all.ru/3.15/howto/logging-cookbook.html) датируется 2009 годом, большинство syslog-серверов по умолчанию настроены на использование более старого [**RFC 3164**](https://python-all.ru/3.15/howto/logging-cookbook.html), который появился в 2001 году. Когда `logging` был добавлен в Python в 2003 году, он поддерживал тогдашний (и единственный существующий) протокол. С момента выхода RFC 5424, из-за отсутствия его широкого распространения среди syslog-серверов, функциональность [`SysLogHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.handlers.SysLogHandler) не обновлялась.32183219RFC 5424 содержит полезные возможности, такие как поддержка структурированных данных. Если необходимо вести журналирование на syslog-сервер с поддержкой этого протокола, это можно сделать с помощью подкласса обработчика, который выглядит примерно так:32203221```python3222import datetime as dt3223import logging.handlers3224import re3225import socket3226import time32273228class SysLogHandler5424(logging.handlers.SysLogHandler):32293230 tz_offset = re.compile(r'([+-]\d{2})(\d{2})$')3231 escaped = re.compile(r'([\]"\\])')32323233 def __init__(self, *args, **kwargs):3234 self.msgid = kwargs.pop('msgid', None)3235 self.appname = kwargs.pop('appname', None)3236 super().__init__(*args, **kwargs)32373238 def format(self, record):3239 version = 13240 asctime = dt.datetime.fromtimestamp(record.created).isoformat()3241 m = self.tz_offset.prefixmatch(time.strftime('%z'))3242 has_offset = False3243 if m and time.timezone:3244 hrs, mins = m.groups()3245 if int(hrs) or int(mins):3246 has_offset = True3247 if not has_offset:3248 asctime += 'Z'3249 else:3250 asctime += f'{hrs}:{mins}'3251 try:3252 hostname = socket.gethostname()3253 except Exception:3254 hostname = '-'3255 appname = self.appname or '-'3256 procid = record.process3257 msgid = '-'3258 msg = super().format(record)3259 sdata = '-'3260 if hasattr(record, 'structured_data'):3261 sd = record.structured_data3262 # Это должен быть словарь, где ключи – SD-ID, а значение –3263 # словарь, отображающий PARAM-NAME на PARAM-VALUE (обратитесь к RFC, чтобы узнать, что эти3264 # означают)3265 # Здесь нет проверки ошибок – это только для иллюстрации, и вы3266 # можете адаптировать этот код для использования в производственных средах3267 parts = []32683269 def replacer(m):3270 g = m.groups()3271 return '\\' + g[0]32723273 for sdid, dv in sd.items():3274 part = f'[{sdid}'3275 for k, v in dv.items():3276 s = str(v)3277 s = self.escaped.sub(replacer, s)3278 part += f' {k}="{s}"'3279 part += ']'3280 parts.append(part)3281 sdata = ''.join(parts)3282 return f'{version} {asctime} {hostname} {appname} {procid} {msgid} {sdata} {msg}'3283```32843285Чтобы полностью разобраться в приведённом коде, потребуется знакомство с RFC 5424. Возможно, ваши потребности будут несколько иными (например, в способе передачи структурированных данных в журнал). Тем не менее, приведённый код можно адаптировать под конкретные нужды. С таким обработчиком структурированные данные передаются, например, так:32863287```python3288sd = {3289 'foo@12345': {'bar': 'baz', 'baz': 'bozz', 'fizz': r'buzz'},3290 'foo@54321': {'rab': 'baz', 'zab': 'bozz', 'zzif': r'buzz'}3291}3292extra = {'structured_data': sd}3293i = 13294logger.debug('Message %d', i, extra=extra)3295```32963297## Как использовать объект Logger как выходной поток32983299Иногда возникает необходимость взаимодействовать со сторонним API, который ожидает объект, подобный файлу, для записи, но при этом нужно перенаправить вывод API в журнал. Это можно сделать с помощью класса, который оборачивает объект Logger, предоставляя файлоподобный интерфейс. Вот короткий скрипт, иллюстрирующий такой класс:33003301```python3302import logging33033304class LoggerWriter:3305 def __init__(self, logger, level):3306 self.logger = logger3307 self.level = level33083309 def write(self, message):3310 if message != '\n': # избегайте печати пустых строк, если хотите3311 self.logger.log(self.level, message)33123313 def flush(self):3314 # на самом деле ничего не делает, но может ожидаться от файлоподобного3315 # объекта – так что опционально в зависимости от вашей ситуации3316 pass33173318 def close(self):3319 # на самом деле ничего не делает, но может ожидаться от файлоподобного3320 # объекта – так что опционально в зависимости от вашей ситуации. Возможно, вы захотите3321 # установить флаг, чтобы последующие вызовы write вызывали исключение3322 pass33233324def main():3325 logging.basicConfig(level=logging.DEBUG)3326 logger = logging.getLogger('demo')3327 info_fp = LoggerWriter(logger, logging.INFO)3328 debug_fp = LoggerWriter(logger, logging.DEBUG)3329 print('An INFO message', file=info_fp)3330 print('A DEBUG message', file=debug_fp)33313332if __name__ == "__main__":3333 main()3334```33353336При запуске этот скрипт выводит33373338```text3339INFO:demo:An INFO message3340DEBUG:demo:A DEBUG message3341```33423343Можно также использовать `LoggerWriter` для перенаправления `sys.stdout` и `sys.stderr`, сделав примерно так:33443345```python3346import sys33473348sys.stdout = LoggerWriter(logger, logging.INFO)3349sys.stderr = LoggerWriter(logger, logging.WARNING)3350```33513352Это следует делать *после* настройки журналирования под свои нужды. В приведённом выше примере вызов [`basicConfig()`](https://python-all.ru/3.15/library/logging.html#logging.basicConfig) делает это (используя значение `sys.stderr` *до* того, как оно будет перезаписано экземпляром `LoggerWriter`). В результате получится примерно такой вывод:33533354```pycon3355>>> print('Foo')3356INFO:demo:Foo3357>>> print('Bar', file=sys.stderr)3358WARNING:demo:Bar3359>>>3360```33613362Разумеется, приведённые выше примеры показывают вывод в формате, используемом [`basicConfig()`](https://python-all.ru/3.15/library/logging.html#logging.basicConfig), но при настройке журналирования можно использовать другой форматтер.33633364Обратите внимание, что при такой схеме вы в значительной степени зависите от буферизации и порядка вызовов write, которые перехватываете. Например, при определении `LoggerWriter` выше, если есть такой фрагмент кода:33653366```python3367sys.stderr = LoggerWriter(logger, logging.WARNING)33681 / 03369```33703371то запуск скрипта даёт33723373```text3374WARNING:demo:Traceback (most recent call last):33753376WARNING:demo: File "/home/runner/cookbook-loggerwriter/test.py", line 53, in <module>33773378WARNING:demo:3379WARNING:demo:main()3380WARNING:demo: File "/home/runner/cookbook-loggerwriter/test.py", line 49, in main33813382WARNING:demo:3383WARNING:demo:1 / 03384WARNING:demo:ZeroDivisionError3385WARNING:demo::3386WARNING:demo:division by zero3387```33883389Как видите, такой вывод неидеален. Это происходит потому, что код, который пишет в `sys.stderr`, выполняет несколько записей, и каждая из них приводит к отдельной строке в журнале (например, три последние строки выше). Чтобы обойти эту проблему, нужно буферизовать данные и выводить строки журнала только при появлении символов новой строки. Давайте используем немного улучшенную реализацию `LoggerWriter`:33903391```python3392class BufferingLoggerWriter(LoggerWriter):3393 def __init__(self, logger, level):3394 super().__init__(logger, level)3395 self.buffer = ''33963397 def write(self, message):3398 if '\n' not in message:3399 self.buffer += message3400 else:3401 parts = message.split('\n')3402 if self.buffer:3403 s = self.buffer + parts.pop(0)3404 self.logger.log(self.level, s)3405 self.buffer = parts.pop()3406 for part in parts:3407 self.logger.log(self.level, part)3408```34093410Этот код просто буферизует данные до появления символа новой строки, после чего записывает полные строки. С таким подходом вывод становится лучше:34113412```text3413WARNING:demo:Traceback (most recent call last):3414WARNING:demo: File "/home/runner/cookbook-loggerwriter/main.py", line 55, in <module>3415WARNING:demo: main()3416WARNING:demo: File "/home/runner/cookbook-loggerwriter/main.py", line 52, in main3417WARNING:demo: 1/03418WARNING:demo:ZeroDivisionError: division by zero3419```34203421## Как единообразно обрабатывать символы новой строки в выводе журнала34223423Обычно записываемые в журнал сообщения (например, в консоль или файл) состоят из одной строки текста. Однако иногда возникает необходимость обрабатывать сообщения, содержащие несколько строк – будь то из-за того, что форматная строка логгера содержит символы новой строки, или сами данные содержат такие символы. Чтобы единообразно обрабатывать такие сообщения, при этом каждая строка в записанном сообщении форматировалась так, как если бы она была записана отдельно, можно использовать примесь-обработчик, как в следующем примере:34243425```python3426# Предположим, это находится в модуле mymixins.py3427import copy34283429class MultilineMixin:3430 def emit(self, record):3431 s = record.getMessage()3432 if '\n' not in s:3433 super().emit(record)3434 else:3435 lines = s.splitlines()3436 rec = copy.copy(record)3437 rec.args = None3438 for line in lines:3439 rec.msg = line3440 super().emit(rec)3441```34423443Использовать эту примесь можно, как в следующем скрипте:34443445```python3446import logging34473448from mymixins import MultilineMixin34493450logger = logging.getLogger(__name__)34513452class StreamHandler(MultilineMixin, logging.StreamHandler):3453 pass34543455if __name__ == '__main__':3456 logging.basicConfig(level=logging.DEBUG, format='%(asctime)s %(levelname)-9s %(message)s',3457 handlers = [StreamHandler()])3458 logger.debug('Single line')3459 logger.debug('Multiple lines:\nfool me once ...')3460 logger.debug('Another single line')3461 logger.debug('Multiple lines:\n%s', 'fool me ...\ncan\'t get fooled again')3462```34633464Скрипт при запуске выводит примерно следующее:34653466```text34672025-07-02 13:54:47,234 DEBUG Single line34682025-07-02 13:54:47,234 DEBUG Multiple lines:34692025-07-02 13:54:47,234 DEBUG fool me once ...34702025-07-02 13:54:47,234 DEBUG Another single line34712025-07-02 13:54:47,234 DEBUG Multiple lines:34722025-07-02 13:54:47,234 DEBUG fool me ...34732025-07-02 13:54:47,234 DEBUG can't get fooled again3474```34753476Если же вас беспокоит [внедрение в журнал (log injection)](https://python-all.ru/3.15/howto/logging-cookbook.html), можно использовать форматтер, экранирующий символы новой строки, как в следующем примере:34773478```python3479import logging34803481logger = logging.getLogger(__name__)34823483class EscapingFormatter(logging.Formatter):3484 def format(self, record):3485 s = super().format(record)3486 return s.replace('\n', r'\n')34873488if __name__ == '__main__':3489 h = logging.StreamHandler()3490 h.setFormatter(EscapingFormatter('%(asctime)s %(levelname)-9s %(message)s'))3491 logging.basicConfig(level=logging.DEBUG, handlers = [h])3492 logger.debug('Single line')3493 logger.debug('Multiple lines:\nfool me once ...')3494 logger.debug('Another single line')3495 logger.debug('Multiple lines:\n%s', 'fool me ...\ncan\'t get fooled again')3496```34973498Разумеется, можно применять любую схему экранирования, наиболее подходящую для ваших задач. При запуске скрипт должен выдать вывод, похожий на этот:34993500```text35012025-07-09 06:47:33,783 DEBUG Single line35022025-07-09 06:47:33,783 DEBUG Multiple lines:\nfool me once ...35032025-07-09 06:47:33,783 DEBUG Another single line35042025-07-09 06:47:33,783 DEBUG Multiple lines:\nfool me ...\ncan't get fooled again3505```35063507Поведение с экранированием не может быть установлено по умолчанию в stdlib, поскольку это нарушило бы обратную совместимость.35083509## Шаблоны, которых следует избегать35103511Хотя в предыдущих разделах были описаны способы решения задач, с которыми вы можете столкнуться, стоит упомянуть некоторые шаблоны использования, которые *бесполезны* и в большинстве случаев их следует избегать. Следующие разделы приведены в произвольном порядке.35123513### Многократное открытие одного и того же файла журнала35143515В Windows обычно не получится открыть один и тот же файл несколько раз, так как это приведёт к ошибке «файл используется другим процессом». Однако на платформах POSIX никаких ошибок при многократном открытии одного файла не возникнет. Это может произойти случайно, например:35163517- Добавление файлового обработчика более одного раза со ссылкой на один и тот же файл (например, из-за ошибки копирования/вставки/забыли изменить).3518- Открытие двух файлов, которые выглядят разными (у них разные имена), но на самом деле являются одним и тем же файлом, так как один – символическая ссылка на другой.3519- Порождение процесса (форк), после которого и родительский, и дочерний процесс имеют ссылку на один и тот же файл. Это может происходить, например, при использовании модуля [`multiprocessing`](https://python-all.ru/3.15/library/multiprocessing.html#module-multiprocessing).35203521Многократное открытие файла может *выглядеть* работающим большую часть времени, но на практике может привести к ряду проблем:35223523- Вывод логирования может искажаться, поскольку несколько потоков или процессов пытаются писать в один и тот же файл. Хотя логирование защищает от одновременного использования одного и того же экземпляра обработчика несколькими потоками, такой защиты нет, если одновременную запись пытаются выполнить два разных потока, использующие два разных экземпляра обработчика, которые указывают на один и тот же файл.3524- Попытка удалить файл (например, во время ротации) молча завершается неудачей, потому что есть другая ссылка на него. Это может привести к путанице и потере времени на отладку – записи журнала оказываются в неожиданных местах или полностью теряются. Или файл, который должен был быть перемещён, остаётся на месте и неожиданно растёт в размерах, несмотря на то что ротация по размеру якобы настроена.35253526Используйте методы, описанные в [Логирование в один файл из нескольких процессов](https://python-all.ru/3.15/howto/logging-cookbook.html#multiple-processes), чтобы обойти такие проблемы.35273528### Использование логгеров в качестве атрибутов класса или передача их в качестве параметров35293530Хотя могут быть необычные случаи, когда это необходимо, в целом в этом нет смысла, потому что логгеры – синглтоны. Код всегда может получить доступ к нужному экземпляру логгера по имени с помощью `logging.getLogger(name)`, поэтому передавать экземпляры повсюду и хранить их в качестве атрибутов экземпляра бессмысленно. Обратите внимание, что в других языках, таких как Java и C#, логгеры часто являются статическими атрибутами класса. Однако этот шаблон не имеет смысла в Python, где модуль (а не класс) является единицей декомпозиции программного обеспечения.35313532### Добавление обработчиков, отличных от [`NullHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.NullHandler), к логгеру в библиотеке35333534Настройка логирования путём добавления обработчиков, форматировщиков и фильтров – это ответственность разработчика приложения, а не разработчика библиотеки. Если вы поддерживаете библиотеку, убедитесь, что не добавляете обработчики ни к одному из своих логгеров, кроме экземпляра [`NullHandler`](https://python-all.ru/3.15/library/logging.handlers.html#logging.NullHandler).35353536### Создание большого количества логгеров35373538Логгеры – это синглтоны, которые никогда не освобождаются во время выполнения скрипта, поэтому создание большого количества логгеров приведёт к расходу памяти, которую затем нельзя освободить. Вместо того чтобы создавать логгер для каждого обрабатываемого файла или сетевого соединения, используйте [существующие механизмы](https://python-all.ru/3.15/howto/logging-cookbook.html#context-info) для передачи контекстной информации в ваши журналы и ограничьте создаваемые логгеры теми, которые описывают области вашего приложения (обычно модули, но иногда и с чуть большей детализацией).35393540## Другие ресурсы35413542> **См. также**3543>3544> **Модуль [`logging`](https://python-all.ru/3.15/library/logging.html#module-logging)**3545>3546> Справочник API для модуля logging.3547>3548> **Модуль [`logging.config`](https://python-all.ru/3.15/library/logging.config.html#module-logging.config)**3549>3550> API конфигурации для модуля logging.3551>3552> **Модуль [`logging.handlers`](https://python-all.ru/3.15/library/logging.handlers.html#module-logging.handlers)**3553>3554> Полезные обработчики, входящие в состав модуля logging.3555>3556> [Базовое руководство](https://python-all.ru/3.15/howto/logging.html#logging-basic-tutorial)3557>3558> [Продвинутое руководство](https://python-all.ru/3.15/howto/logging.html#logging-advanced-tutorial)3559