logging-cookbook.md
1> **Источник:** https://python-all.ru/3.2/howto/logging-cookbook.html2>3> «Документация Python на русском» – неофициальный перевод официальной документации Python: версии от 2.6 до 3.16, полнотекстовый поиск, английский оригинал рядом с переводом. Эта Markdown-версия страницы предназначена для работы с LLM: вставьте её в ChatGPT, Claude или Cursor.45---67# Сборник рецептов по логированию89| Автор: | Vinay Sajip \<vinay\_sajip at red-dove dot com\> |10| --- | --- |1112На этой странице представлен ряд рецептов, связанных с логированием, которые оказались полезными на практике.1314## Использование логирования в нескольких модулях1516Многократные вызовы `logging.getLogger('someLogger')` возвращают ссылку на один и тот же объект логгера. Это верно не только в пределах одного модуля, но и между модулями, пока они находятся в одном процессе интерпретатора Python. Это верно для ссылок на один и тот же объект; кроме того, код приложения может определить и настроить родительский логгер в одном модуле и создать (но не настраивать) дочерний логгер в отдельном модуле, и все вызовы логгера к дочернему будут передаваться родительскому. Вот главный модуль:1718```python19import logging20import auxiliary_module2122# создать логгер с именем 'spam_application'23logger = logging.getLogger('spam_application')24logger.setLevel(logging.DEBUG)25# создать файловый обработчик, записывающий даже отладочные сообщения26fh = logging.FileHandler('spam.log')27fh.setLevel(logging.DEBUG)28# создать консольный обработчик с более высоким уровнем логирования29ch = logging.StreamHandler()30ch.setLevel(logging.ERROR)31# создать форматтер и добавить его к обработчикам32formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')33fh.setFormatter(formatter)34ch.setFormatter(formatter)35# добавить обработчики к логгеру36logger.addHandler(fh)37logger.addHandler(ch)3839logger.info('creating an instance of auxiliary_module.Auxiliary')40a = auxiliary_module.Auxiliary()41logger.info('created an instance of auxiliary_module.Auxiliary')42logger.info('calling auxiliary_module.Auxiliary.do_something')43a.do_something()44logger.info('finished auxiliary_module.Auxiliary.do_something')45logger.info('calling auxiliary_module.some_function()')46auxiliary_module.some_function()47logger.info('done with auxiliary_module.some_function()')48```4950А вот вспомогательный модуль:5152```python53import logging5455# создать логгер56module_logger = logging.getLogger('spam_application.auxiliary')5758class Auxiliary:59 def __init__(self):60 self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')61 self.logger.info('creating an instance of Auxiliary')62 def do_something(self):63 self.logger.info('doing something')64 a = 1 + 165 self.logger.info('done doing something')6667def some_function():68 module_logger.info('received a call to "some_function"')69```7071Вывод выглядит так:7273```python742005-03-23 23:47:11,663 - spam_application - INFO -75 creating an instance of auxiliary_module.Auxiliary762005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -77 creating an instance of Auxiliary782005-03-23 23:47:11,665 - spam_application - INFO -79 created an instance of auxiliary_module.Auxiliary802005-03-23 23:47:11,668 - spam_application - INFO -81 calling auxiliary_module.Auxiliary.do_something822005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -83 doing something842005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -85 done doing something862005-03-23 23:47:11,670 - spam_application - INFO -87 finished auxiliary_module.Auxiliary.do_something882005-03-23 23:47:11,671 - spam_application - INFO -89 calling auxiliary_module.some_function()902005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -91 received a call to 'some_function'922005-03-23 23:47:11,673 - spam_application - INFO -93 done with auxiliary_module.some_function()94```9596## Несколько обработчиков и форматировщиков9798Логгеры – это обычные объекты Python. У метода `addHandler()` нет минимального или максимального ограничения на количество добавляемых обработчиков. Иногда бывает полезно, чтобы приложение записывало все сообщения всех уровней в текстовый файл и одновременно выводило ошибки и выше на консоль. Чтобы это настроить, достаточно сконфигурировать соответствующие обработчики. Вызовы логирования в коде приложения останутся без изменений. Вот небольшая модификация предыдущего простого примера конфигурации на основе модуля:99100```python101import logging102103logger = logging.getLogger('simple_example')104logger.setLevel(logging.DEBUG)105# создать файловый обработчик, записывающий даже отладочные сообщения106fh = logging.FileHandler('spam.log')107fh.setLevel(logging.DEBUG)108# создать консольный обработчик с более высоким уровнем логирования109ch = logging.StreamHandler()110ch.setLevel(logging.ERROR)111# создать форматтер и добавить его к обработчикам112formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')113ch.setFormatter(formatter)114fh.setFormatter(formatter)115# добавить обработчики в логгер116logger.addHandler(ch)117logger.addHandler(fh)118119# код 'приложения'120logger.debug('debug message')121logger.info('info message')122logger.warn('warn message')123logger.error('error message')124logger.critical('critical message')125```126127Обратите внимание, что «прикладной» код не заботится о нескольких обработчиках. Единственное, что изменилось – добавление и настройка нового обработчика с именем *fh*.128129Возможность создавать новые обработчики с фильтрами более высокого или низкого уровня серьезности может быть очень полезна при написании и тестировании приложения. Вместо использования множества операторов `print` для отладки используйте `logger.debug`: в отличие от операторов print, которые вам придется удалить или закомментировать позже, операторы logger.debug могут оставаться в исходном коде и оставаться неактивными до тех пор, пока они снова не понадобятся. В этом случае единственное, что нужно сделать, – изменить уровень серьезности логгера и/или обработчика на debug.130131## Журналирование в несколько мест назначения132133Допустим, вы хотите вести журнал в консоль и файл с разными форматами сообщений и в разных ситуациях. Предположим, вы хотите записывать сообщения уровня DEBUG и выше в файл, а сообщения уровня INFO и выше – в консоль. Также предположим, что файл должен содержать временные метки, а консольные сообщения – нет. Вот как это можно сделать:134135```python136import logging137138# настроить логирование в файл – подробнее см. предыдущий раздел139logging.basicConfig(level=logging.DEBUG,140 format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',141 datefmt='%m-%d %H:%M',142 filename='/temp/myapp.log',143 filemode='w')144# Определяет обработчик, который записывает сообщения уровня INFO и выше в sys.stderr.145console = logging.StreamHandler()146console.setLevel(logging.INFO)147# Задает формат, упрощенный для вывода в консоль.148formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')149# Указывает обработчику использовать этот формат.150console.setFormatter(formatter)151# Добавляет обработчик в корневой логгер.152logging.getLogger('').addHandler(console)153154# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...155logging.info('Jackdaws love my big sphinx of quartz.')156157# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:158# приложение:159160logger1 = logging.getLogger('myapp.area1')161logger2 = logging.getLogger('myapp.area2')162163logger1.debug('Quick zephyrs blow, vexing daft Jim.')164logger1.info('How quickly daft jumping zebras vex.')165logger2.warning('Jail zesty vixen who grabbed pay from quack.')166logger2.error('The five boxing wizards jump quickly.')167```168169При запуске на консоли вы увидите170171```python172root : INFO Jackdaws love my big sphinx of quartz.173myapp.area1 : INFO How quickly daft jumping zebras vex.174myapp.area2 : WARNING Jail zesty vixen who grabbed pay from quack.175myapp.area2 : ERROR The five boxing wizards jump quickly.176```177178а в файле увидите примерно такое179180```python18110-22 22:19 root INFO Jackdaws love my big sphinx of quartz.18210-22 22:19 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim.18310-22 22:19 myapp.area1 INFO How quickly daft jumping zebras vex.18410-22 22:19 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack.18510-22 22:19 myapp.area2 ERROR The five boxing wizards jump quickly.186```187188Как видите, сообщение DEBUG отображается только в файле. Остальные сообщения отправляются в оба места назначения.189190В этом примере используются консольный и файловый обработчики, но вы можете использовать любое количество и любое сочетание обработчиков по своему выбору.191192## Пример сервера конфигурации193194Вот пример модуля, использующего сервер конфигурации журналирования:195196```python197import logging198import logging.config199import time200import os201202# Прочитать начальный конфигурационный файл.203logging.config.fileConfig('logging.conf')204205# Создать и запустить слушатель на порту 9999.206t = logging.config.listen(9999)207t.start()208209logger = logging.getLogger('simpleExample')210211try:212 # Прокрутить вызовы логирования, чтобы увидеть разницу.213 # Создавать новые конфигурации до нажатия Ctrl+C.214 while True:215 logger.debug('debug message')216 logger.info('info message')217 logger.warn('warn message')218 logger.error('error message')219 logger.critical('critical message')220 time.sleep(5)221except KeyboardInterrupt:222 # очистка223 logging.config.stopListening()224 t.join()225```226227А вот скрипт, который принимает имя файла и отправляет этот файл на сервер, предварив его двоично-закодированной длиной, в качестве новой конфигурации журналирования:228229```python230#!/usr/bin/env python231import socket, sys, struct232233with open(sys.argv[1], 'rb') as f:234 data_to_send = f.read()235236HOST = 'localhost'237PORT = 9999238s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)239print('connecting...')240s.connect((HOST, PORT))241print('sending config...')242s.send(struct.pack('>L', len(data_to_send)))243s.send(data_to_send)244s.close()245print('complete')246```247248## Работа с блокирующими обработчиками249250Иногда требуется, чтобы обработчики логирования выполняли свою работу, не блокируя поток, из которого ведется логирование. Это часто встречается в веб-приложениях, хотя, конечно, бывает и в других сценариях.251252Часто виновником медленной работы является [`SMTPHandler`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.SMTPHandler): отправка писем может занимать много времени по ряду причин, не зависящих от разработчика (например, плохая производительность почтовой или сетевой инфраструктуры). Но почти любой сетевой обработчик может блокироваться: даже операция [`SocketHandler`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.SocketHandler) может выполнять DNS-запрос внутри, который слишком медленный (и этот запрос может находиться глубоко в коде библиотеки сокетов, ниже уровня Python, и вне вашего контроля).253254Одно из решений – использовать двухчастный подход. На первом этапе прикрепите только [`QueueHandler`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.QueueHandler) к тем логгерам, к которым обращаются из критичных по производительности потоков. Они просто пишут в свою очередь, которая может быть настроена на достаточно большую емкость или инициализирована без верхнего ограничения размера. Запись в очередь обычно принимается быстро, хотя вам, вероятно, потребуется перехватывать исключение [`queue.Full`](https://python-all.ru/3.2/library/queue.html#queue.Full) в качестве меры предосторожности в коде. Если вы разработчик библиотеки, и в вашем коде есть критичные по производительности потоки, обязательно задокументируйте это (вместе с рекомендацией прикреплять только `QueueHandlers` к вашим логгерам) на благо других разработчиков, которые будут использовать ваш код.255256Вторая часть решения – [`QueueListener`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.QueueListener), который был разработан как аналог [`QueueHandler`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.QueueHandler). [`QueueListener`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.QueueListener) очень прост: ему передаются очередь и несколько обработчиков, и он запускает внутренний поток, который слушает свою очередь на предмет LogRecords, отправленных от `QueueHandlers` (или любого другого источника `LogRecords`, если на то пошло). `LogRecords` извлекаются из очереди и передаются обработчикам для обработки.257258Преимущество отдельного класса [`QueueListener`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.QueueListener) в том, что можно использовать один и тот же экземпляр для обслуживания нескольких `QueueHandlers`. Это более эффективно по ресурсам, чем, скажем, создание многопоточных версий существующих классов обработчиков, которые потребляют по одному потоку на обработчик без особой пользы.259260Ниже приведён пример использования этих двух классов (импорты опущены):261262```python263que = queue.Queue(-1) # Без ограничения размера.264queue_handler = QueueHandler(que)265handler = logging.StreamHandler()266listener = QueueListener(que, handler)267root = logging.getLogger()268root.addHandler(queue_handler)269formatter = logging.Formatter('%(threadName)s: %(message)s')270handler.setFormatter(formatter)271listener.start()272# Вывод лога будет отображать поток, создавший событие (главный поток), а не внутренний поток,273# отслеживающий внутреннюю очередь.274# Именно это и должно происходить.275# то, что должно произойти.276root.warning('Look out!')277listener.stop()278```279280который при запуске выведет:281282```python283MainThread: Look out!284```285286## Отправка и получение событий логирования по сети287288Допустим, вы хотите отправлять события логирования по сети и обрабатывать их на принимающей стороне. Простой способ сделать это – прикрепить экземпляр [`SocketHandler`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.SocketHandler) к корневому логгеру на отправляющей стороне:289290```python291import logging, logging.handlers292293rootLogger = logging.getLogger('')294rootLogger.setLevel(logging.DEBUG)295socketHandler = logging.handlers.SocketHandler('localhost',296 logging.handlers.DEFAULT_TCP_LOGGING_PORT)297# Не нужно использовать форматтер, так как сокет-обработчик отправляет событие в виде неформатированного пикла.298# неформатированный pickle299rootLogger.addHandler(socketHandler)300301# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...302logging.info('Jackdaws love my big sphinx of quartz.')303304# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:305# приложение:306307logger1 = logging.getLogger('myapp.area1')308logger2 = logging.getLogger('myapp.area2')309310logger1.debug('Quick zephyrs blow, vexing daft Jim.')311logger1.info('How quickly daft jumping zebras vex.')312logger2.warning('Jail zesty vixen who grabbed pay from quack.')313logger2.error('The five boxing wizards jump quickly.')314```315316На принимающей стороне можно настроить приемник с помощью модуля [`socketserver`](https://python-all.ru/3.2/library/socketserver.html#module-socketserver). Вот базовый рабочий пример:317318```python319import pickle320import logging321import logging.handlers322import socketserver323import struct324325class LogRecordStreamHandler(socketserver.StreamRequestHandler):326 """Обработчик для потокового запроса логирования.327328 Это по сути записывает запись, используя ту политику логирования, которая настроена локально.329 настроено локально.330 """331332 def handle(self):333 """334 Обрабатывает несколько запросов – каждый ожидается в формате: 4-байтовая длина, затем запись журнала в формате пикл.335 Записывает запись в соответствии с политикой, настроенной локально.336 согласно локально настроенной политике.337 """338 while True:339 chunk = self.connection.recv(4)340 if len(chunk) < 4:341 break342 slen = struct.unpack('>L', chunk)[0]343 chunk = self.connection.recv(slen)344 while len(chunk) < slen:345 chunk = chunk + self.connection.recv(slen - len(chunk))346 obj = self.unPickle(chunk)347 record = logging.makeLogRecord(obj)348 self.handleLogRecord(record)349350 def unPickle(self, data):351 return pickle.loads(data)352353 def handleLogRecord(self, record):354 # Если указано имя, используется именованный логгер, а не тот, что355 # подразумевается записью.356 if self.server.logname is not None:357 name = self.server.logname358 else:359 name = record.name360 logger = logging.getLogger(name)361 # Примечание: КАЖДАЯ запись попадает в журнал. Это связано с тем, что Logger.handle362 # обычно вызывается ПОСЛЕ фильтрации на уровне регистратора. Если требуется363 # выполнять фильтрацию, делайте это на стороне клиента, чтобы не тратить364 # циклы процессора и сетевую пропускную способность!365 logger.handle(record)366367class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):368 """369 Простой приёмник журнала на основе TCP-сокетов, подходящий для тестирования.370 """371372 allow_reuse_address = 1373374 def __init__(self, host='localhost',375 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,376 handler=LogRecordStreamHandler):377 socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)378 self.abort = 0379 self.timeout = 1380 self.logname = None381382 def serve_until_stopped(self):383 import select384 abort = 0385 while not abort:386 rd, wr, ex = select.select([self.socket.fileno()],387 [], [],388 self.timeout)389 if rd:390 self.handle_request()391 abort = self.abort392393def main():394 logging.basicConfig(395 format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')396 tcpserver = LogRecordSocketReceiver()397 print('About to start TCP server...')398 tcpserver.serve_until_stopped()399400if __name__ == '__main__':401 main()402```403404Сначала запустите сервер, затем клиент. На стороне клиента в консоль ничего не выводится; на стороне сервера вы должны увидеть что-то вроде:405406```python407About to start TCP server...408 59 root INFO Jackdaws love my big sphinx of quartz.409 59 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim.410 69 myapp.area1 INFO How quickly daft jumping zebras vex.411 69 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack.412 69 myapp.area2 ERROR The five boxing wizards jump quickly.413```414415Обратите внимание, что в некоторых сценариях использование pickle связано с рисками безопасности. Если это вас касается, вы можете использовать альтернативную схему сериализации, переопределив метод `makePickle()` и реализовав свою альтернативу в нём, а также адаптировав приведённый выше скрипт для работы с вашей сериализацией.416417## Добавление контекстной информации в вывод журнала418419Иногда требуется, чтобы вывод логирования содержал контекстную информацию в дополнение к параметрам, переданным в вызов логирования. Например, в сетевом приложении может быть желательно регистрировать специфичную для клиента информацию в журнале (например, имя пользователя удаленного клиента или IP-адрес). Хотя вы можете использовать параметр *extra* для этого, не всегда удобно передавать информацию таким образом. Хотя может возникнуть соблазн создавать экземпляры `Logger` для каждого соединения, это не очень хорошая идея, потому что эти экземпляры не собираются сборщиком мусора. Хотя на практике это не проблема, когда количество экземпляров `Logger` зависит от уровня детализации, которую вы хотите использовать при логировании приложения, это может быть трудно управляемым, если количество экземпляров `Logger` становится фактически неограниченным.420421### Использование LoggerAdapter для добавления контекстной информации422423Простой способ передавать контекстную информацию для вывода вместе с информацией о событии логирования – использовать класс `LoggerAdapter`. Этот класс разработан так, чтобы выглядеть как `Logger`, так что вы можете вызывать `debug()`, `info()`, `warning()`, `error()`, `exception()`, `critical()` и `log()`. Эти методы имеют те же сигнатуры, что и их аналоги в `Logger`, поэтому вы можете использовать экземпляры обоих типов взаимозаменяемо.424425Когда вы создаете экземпляр `LoggerAdapter`, вы передаете ему экземпляр `Logger` и объект, подобный словарю, который содержит вашу контекстную информацию. Когда вы вызываете один из методов логирования на экземпляре `LoggerAdapter`, он делегирует вызов базовому экземпляру `Logger`, переданному его конструктору, и обеспечивает передачу контекстной информации в делегированном вызове. Вот фрагмент из кода `LoggerAdapter`:426427```python428def debug(self, msg, *args, **kwargs):429 """430 Передаёт вызов отладки нижележащему регистратору после добавления431 контекстной информации из данного экземпляра адаптера.432 """433 msg, kwargs = self.process(msg, kwargs)434 self.logger.debug(msg, *args, **kwargs)435```436437Метод `process()` класса `LoggerAdapter` – это место, где контекстная информация добавляется к выводу логирования. Ему передаются сообщение и именованные аргументы вызова логирования, и он возвращает (потенциально) изменённые версии этих значений для использования при вызове нижележащего логгера. Реализация по умолчанию этого метода оставляет сообщение без изменений, но добавляет ключ 'extra' в именованные аргументы, значением которого является dict-подобный объект, переданный конструктору. Конечно, если вы передали именованный аргумент 'extra' в вызове адаптера, он будет молча перезаписан.438439Преимущество использования 'extra' в том, что значения из dict-подобного объекта сливаются в `LogRecord`.\_\_dict\_\_, что позволяет использовать настраиваемые строки с экземплярами `Formatter`, которые знают о ключах dict-подобного объекта. Если нужен другой подход, например, если вы хотите добавлять контекстную информацию до или после строки сообщения, достаточно создать подкласс `LoggerAdapter` и переопределить `process()` так, как вам нужно. Вот пример скрипта, использующего этот класс, который также показывает, какое dict-подобное поведение требуется от произвольного 'dict-подобного' объекта для использования в конструкторе:440441```python442import logging443444class ConnInfo:445 """446 Пример класса, который показывает, как произвольный класс можно использовать в качестве447 хранилища контекстной информации 'extra', передаваемого LoggerAdapter.448 """449450 def __getitem__(self, name):451 """452 Чтобы этот экземпляр выглядел как словарь.453 """454 from random import choice455 if name == 'ip':456 result = choice(['127.0.0.1', '192.168.0.1'])457 elif name == 'user':458 result = choice(['jim', 'fred', 'sheila'])459 else:460 result = self.__dict__.get(name, '?')461 return result462463 def __iter__(self):464 """465 Чтобы разрешить итерацию по ключам, которые будут объединены в466 словарь LogRecord перед форматированием и выводом.467 """468 keys = ['ip', 'user']469 keys.extend(self.__dict__.keys())470 return keys.__iter__()471472if __name__ == '__main__':473 from random import choice474 levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)475 a1 = logging.LoggerAdapter(logging.getLogger('a.b.c'),476 { 'ip' : '123.231.231.123', 'user' : 'sheila' })477 logging.basicConfig(level=logging.DEBUG,478 format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')479 a1.debug('A debug message')480 a1.info('An info message with %s', 'some parameters')481 a2 = logging.LoggerAdapter(logging.getLogger('d.e.f'), ConnInfo())482 for x in range(10):483 lvl = choice(levels)484 lvlname = logging.getLevelName(lvl)485 a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')486```487488При запуске этого скрипта вывод должен выглядеть примерно так:489490```python4912008-01-18 14:49:54,023 a.b.c DEBUG IP: 123.231.231.123 User: sheila A debug message4922008-01-18 14:49:54,023 a.b.c INFO IP: 123.231.231.123 User: sheila An info message with some parameters4932008-01-18 14:49:54,023 d.e.f CRITICAL IP: 192.168.0.1 User: jim A message at CRITICAL level with 2 parameters4942008-01-18 14:49:54,033 d.e.f INFO IP: 192.168.0.1 User: jim A message at INFO level with 2 parameters4952008-01-18 14:49:54,033 d.e.f WARNING IP: 192.168.0.1 User: sheila A message at WARNING level with 2 parameters4962008-01-18 14:49:54,033 d.e.f ERROR IP: 127.0.0.1 User: fred A message at ERROR level with 2 parameters4972008-01-18 14:49:54,033 d.e.f ERROR IP: 127.0.0.1 User: sheila A message at ERROR level with 2 parameters4982008-01-18 14:49:54,033 d.e.f WARNING IP: 192.168.0.1 User: sheila A message at WARNING level with 2 parameters4992008-01-18 14:49:54,033 d.e.f WARNING IP: 192.168.0.1 User: jim A message at WARNING level with 2 parameters5002008-01-18 14:49:54,033 d.e.f INFO IP: 192.168.0.1 User: fred A message at INFO level with 2 parameters5012008-01-18 14:49:54,033 d.e.f WARNING IP: 192.168.0.1 User: sheila A message at WARNING level with 2 parameters5022008-01-18 14:49:54,033 d.e.f WARNING IP: 127.0.0.1 User: jim A message at WARNING level with 2 parameters503```504505### Использование фильтров для добавления контекстной информации506507Вы также можете добавить контекстную информацию в вывод журнала с помощью пользовательского `Filter`. Экземпляры `Filter` могут изменять переданные им `LogRecords`, включая добавление дополнительных атрибутов, которые затем можно выводить с помощью подходящей строки формата или, при необходимости, пользовательского `Formatter`.508509Например, в веб-приложении обрабатываемый запрос (или, по крайней мере, его интересные части) может храниться в переменной threadlocal ([`threading.local`](https://python-all.ru/3.2/library/threading.html#threading.local)), а затем извлекаться из `Filter` для добавления, скажем, информации из запроса – например, удаленного IP-адреса и имени пользователя – в `LogRecord`, используя имена атрибутов 'ip' и 'user', как в примере с `LoggerAdapter` выше. В этом случае можно использовать ту же строку формата для получения аналогичного вывода, показанного выше. Вот пример скрипта:510511```python512import logging513from random import choice514515class ContextFilter(logging.Filter):516 """517 Это фильтр, который внедряет контекстную информацию в журнал.518519 Вместо использования реальной контекстной информации в данном примере используются случайные520 данные.521 """522523 USERS = ['jim', 'fred', 'sheila']524 IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']525526 def filter(self, record):527528 record.ip = choice(ContextFilter.IPS)529 record.user = choice(ContextFilter.USERS)530 return True531532if __name__ == '__main__':533 levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)534 logging.basicConfig(level=logging.DEBUG,535 format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')536 a1 = logging.getLogger('a.b.c')537 a2 = logging.getLogger('d.e.f')538539 f = ContextFilter()540 a1.addFilter(f)541 a2.addFilter(f)542 a1.debug('A debug message')543 a1.info('An info message with %s', 'some parameters')544 for x in range(10):545 lvl = choice(levels)546 lvlname = logging.getLevelName(lvl)547 a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')548```549550который при запуске выдаёт примерно следующее:551552```python5532010-09-06 22:38:15,292 a.b.c DEBUG IP: 123.231.231.123 User: fred A debug message5542010-09-06 22:38:15,300 a.b.c INFO IP: 192.168.0.1 User: sheila An info message with some parameters5552010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters5562010-09-06 22:38:15,300 d.e.f ERROR IP: 127.0.0.1 User: jim A message at ERROR level with 2 parameters5572010-09-06 22:38:15,300 d.e.f DEBUG IP: 127.0.0.1 User: sheila A message at DEBUG level with 2 parameters5582010-09-06 22:38:15,300 d.e.f ERROR IP: 123.231.231.123 User: fred A message at ERROR level with 2 parameters5592010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1 User: jim A message at CRITICAL level with 2 parameters5602010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters5612010-09-06 22:38:15,300 d.e.f DEBUG IP: 192.168.0.1 User: jim A message at DEBUG level with 2 parameters5622010-09-06 22:38:15,301 d.e.f ERROR IP: 127.0.0.1 User: sheila A message at ERROR level with 2 parameters5632010-09-06 22:38:15,301 d.e.f DEBUG IP: 123.231.231.123 User: fred A message at DEBUG level with 2 parameters5642010-09-06 22:38:15,301 d.e.f INFO IP: 123.231.231.123 User: fred A message at INFO level with 2 parameters565```566567## Ведение журнала в один файл из нескольких процессов568569Хотя логирование потокобезопасно, и запись в один файл из нескольких потоков в одном процессе *поддерживается*, запись в один файл из *нескольких процессов* *не* поддерживается, поскольку в Python нет стандартного способа сериализовать доступ к одному файлу из нескольких процессов. Если вам нужно логировать в один файл из нескольких процессов, один из способов – заставить все процессы отправлять логи в [`SocketHandler`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.SocketHandler), и запустить отдельный процесс, который реализует сокетный сервер, читает из сокета и записывает логи в файл. (Если хотите, можно выделить один поток в одном из существующих процессов для выполнения этой функции.) [*В этом разделе*](https://python-all.ru/3.2/howto/logging-cookbook.html#network-logging) подробно описывается данный подход и приводится рабочий приёмник сокета, который можно использовать как отправную точку для адаптации в своих приложениях.570571Если вы используете свежую версию Python, включающую модуль [`multiprocessing`](https://python-all.ru/3.2/library/multiprocessing.html#module-multiprocessing), вы можете написать свой обработчик, который использует класс `Lock` из этого модуля для сериализации доступа к файлу из ваших процессов. Существующие `FileHandler` и его подклассы в настоящее время не используют [`multiprocessing`](https://python-all.ru/3.2/library/multiprocessing.html#module-multiprocessing), хотя в будущем могут. Обратите внимание, что на данный момент модуль [`multiprocessing`](https://python-all.ru/3.2/library/multiprocessing.html#module-multiprocessing) не предоставляет работающую функциональность блокировок на всех платформах (см. [http://bugs.python.org/issue3770](https://python-all.ru/3.2/howto/logging-cookbook.html)).572573В качестве альтернативы вы можете использовать `Queue` и [`QueueHandler`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.QueueHandler) для отправки всех событий логирования одному из процессов вашего многопроцессного приложения. Следующий пример скрипта демонстрирует, как это можно сделать; в примере отдельный процесс-слушатель прослушивает события, отправленные другими процессами, и регистрирует их в соответствии со своей собственной конфигурацией логирования. Хотя пример демонстрирует только один способ (например, вы можете захотеть использовать поток-слушатель вместо отдельного процесса-слушателя – реализация была бы аналогичной), он допускает полностью различные конфигурации логирования для слушателя и других процессов вашего приложения и может использоваться как основа для кода, удовлетворяющего вашим конкретным требованиям:574575```python576# Вам понадобятся эти импорты в вашем коде.577import logging578import logging.handlers579import multiprocessing580581# Следующие две строки импорта только для этой демонстрации.582from random import choice, random583import time584585#586# Поскольку нужно задать настройки логирования для слушателя и рабочих процессов, функции587# слушателя и рабочего процесса принимают параметр configurer – вызываемый объект для588# настройки логирования этого процесса. Эти функции также получают очередь, которую589# используют для взаимодействия.590#591# На практике слушателя можно настроить как угодно, но заметьте: в этом простом592# примере слушатель не применяет логику уровней или фильтров к полученным записям.593# На практике эту логику, вероятно, стоит вынести в рабочие процессы, чтобы не594# пересылать между процессами события, которые всё равно будут отфильтрованы.595#596# Размер файлов при ротации намеренно сделан небольшим, чтобы результат был хорошо виден.597def listener_configurer():598 root = logging.getLogger()599 h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)600 f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')601 h.setFormatter(f)602 root.addHandler(h)603604# Это главный цикл процесса-слушателя: ждём события логирования605# (LogRecords) в очереди и обрабатываем их; завершаем работу, когда получаем None вместо606# LogRecord.607def listener_process(queue, configurer):608 configurer()609 while True:610 try:611 record = queue.get()612 if record is None: # Отправляем это как сигнал завершения, чтобы слушатель остановился.613 break614 logger = logging.getLogger(record.name)615 logger.handle(record) # Никакой логики уровней и фильтров – просто делаем дело!616 except (KeyboardInterrupt, SystemExit):617 raise618 except:619 import sys, traceback620 print('Whoops! Problem:', file=sys.stderr)621 traceback.print_exc(file=sys.stderr)622623# Массивы для случайного выбора в этой демонстрации.624625LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,626 logging.ERROR, logging.CRITICAL]627628LOGGERS = ['a.b.c', 'd.e.f']629630MESSAGES = [631 'Random message #1',632 'Random message #2',633 'Random message #3',634]635636# Настройка рабочего процесса выполняется в начале его работы.637# Обратите внимание: в Windows нельзя полагаться на семантику fork, поэтому каждый процесс638# будет выполнять код настройки логирования при запуске.639def worker_configurer(queue):640 h = logging.handlers.QueueHandler(queue) # Нужен только один обработчик.641 root = logging.getLogger()642 root.addHandler(h)643 root.setLevel(logging.DEBUG) # Отправляем все сообщения для демонстрации; никакой другой логики уровней или фильтров.644645# Это главный цикл рабочего процесса, который просто логирует десять событий с646# случайные задержки перед завершением.647# Сообщения print нужны лишь для того, чтобы было видно, что программа работает.648def worker_process(queue, configurer):649 configurer(queue)650 name = multiprocessing.current_process().name651 print('Worker started: %s' % name)652 for i in range(10):653 time.sleep(random())654 logger = logging.getLogger(choice(LOGGERS))655 level = choice(LEVELS)656 message = choice(MESSAGES)657 logger.log(level, message)658 print('Worker finished: %s' % name)659660# Здесь организуется демонстрация. Создать очередь, создать и запустить661# слушатель, создать десять рабочих процессов и запустить их, дождаться их завершения,662# затем отправить None в очередь, чтобы сообщить слушателю о завершении.663def main():664 queue = multiprocessing.Queue(-1)665 listener = multiprocessing.Process(target=listener_process,666 args=(queue, listener_configurer))667 listener.start()668 workers = []669 for i in range(10):670 worker = multiprocessing.Process(target=worker_process,671 args=(queue, worker_configurer))672 workers.append(worker)673 worker.start()674 for w in workers:675 w.join()676 queue.put_nowait(None)677 listener.join()678679if __name__ == '__main__':680 main()681```682683Вариант приведённого выше сценария оставляет ведение журнала в главном процессе, в отдельном потоке:684685```python686import logging687import logging.config688import logging.handlers689from multiprocessing import Process, Queue690import random691import threading692import time693694def logger_thread(q):695 while True:696 record = q.get()697 if record is None:698 break699 logger = logging.getLogger(record.name)700 logger.handle(record)701702def worker_process(q):703 qh = logging.handlers.QueueHandler(q)704 root = logging.getLogger()705 root.setLevel(logging.DEBUG)706 root.addHandler(qh)707 levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,708 logging.CRITICAL]709 loggers = ['foo', 'foo.bar', 'foo.bar.baz',710 'spam', 'spam.ham', 'spam.ham.eggs']711 for i in range(100):712 lvl = random.choice(levels)713 logger = logging.getLogger(random.choice(loggers))714 logger.log(lvl, 'Message no. %d', i)715716if __name__ == '__main__':717 q = Queue()718 d = {719 'version': 1,720 'formatters': {721 'detailed': {722 'class': 'logging.Formatter',723 'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'724 }725 },726 'handlers': {727 'console': {728 'class': 'logging.StreamHandler',729 'level': 'INFO',730 },731 'file': {732 'class': 'logging.FileHandler',733 'filename': 'mplog.log',734 'mode': 'w',735 'formatter': 'detailed',736 },737 'foofile': {738 'class': 'logging.FileHandler',739 'filename': 'mplog-foo.log',740 'mode': 'w',741 'formatter': 'detailed',742 },743 'errors': {744 'class': 'logging.FileHandler',745 'filename': 'mplog-errors.log',746 'mode': 'w',747 'level': 'ERROR',748 'formatter': 'detailed',749 },750 },751 'loggers': {752 'foo': {753 'handlers' : ['foofile']754 }755 },756 'root': {757 'level': 'DEBUG',758 'handlers': ['console', 'file', 'errors']759 },760 }761 workers = []762 for i in range(5):763 wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))764 workers.append(wp)765 wp.start()766 logging.config.dictConfig(d)767 lp = threading.Thread(target=logger_thread, args=(q,))768 lp.start()769 # На этом этапе главный процесс может заняться своей полезной работой770 # Когда он с этим закончит, он может дождаться завершения рабочих процессов...771 for wp in workers:772 wp.join()773 # А теперь указать потоку журналирования завершиться774 q.put(None)775 lp.join()776```777778Этот вариант показывает, как можно, например, применить конфигурацию для конкретных логгеров – например, логгер `foo` имеет специальный обработчик, который сохраняет все события подсистемы `foo` в файл `mplog-foo.log`. Это будет использоваться механизмом логирования в главном процессе (даже если события логирования генерируются в рабочих процессах) для направления сообщений в соответствующие места назначения.779780## Использование ротации файлов781782Иногда требуется позволить файлу лога вырасти до определённого размера, а затем открыть новый файл и писать в него. Может понадобиться хранить определённое количество таких файлов, и когда это количество будет создано, выполнять ротацию, чтобы и количество файлов, и их размер оставались в заданных пределах. Для такого сценария использования пакет logging предоставляет [`RotatingFileHandler`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.RotatingFileHandler):783784```python785import glob786import logging787import logging.handlers788789LOG_FILENAME = 'logging_rotatingfile_example.out'790791# Настроить конкретный регистратор с нужным уровнем вывода792my_logger = logging.getLogger('MyLogger')793my_logger.setLevel(logging.DEBUG)794795# Добавить обработчик сообщений журнала в регистратор796handler = logging.handlers.RotatingFileHandler(797 LOG_FILENAME, maxBytes=20, backupCount=5)798799my_logger.addHandler(handler)800801# Записать несколько сообщений802for i in range(20):803 my_logger.debug('i = %d' % i)804805# Посмотреть, какие файлы созданы806logfiles = glob.glob('%s*' % LOG_FILENAME)807808for filename in logfiles:809 print(filename)810```811812В результате должно получиться 6 отдельных файлов, каждый из которых содержит часть истории журнала приложения:813814```python815logging_rotatingfile_example.out816logging_rotatingfile_example.out.1817logging_rotatingfile_example.out.2818logging_rotatingfile_example.out.3819logging_rotatingfile_example.out.4820logging_rotatingfile_example.out.5821```822823Самый текущий файл всегда называется `logging_rotatingfile_example.out`, и каждый раз, когда он достигает предельного размера, он переименовывается с суффиксом `.1`. Каждый из существующих резервных файлов переименовывается для увеличения суффикса (`.1` становится `.2` и т.д.), а файл `.6` удаляется.824825Разумеется, в этом примере размер файла журнала установлен слишком маленьким для наглядности. В реальности нужно установить *maxBytes* в подходящее значение.826827## Использование альтернативных стилей форматирования828829Когда логирование было добавлено в стандартную библиотеку Python, единственным способом форматирования сообщений с переменным содержимым был метод %-форматирования. С тех пор в Python появились два новых подхода к форматированию: [`string.Template`](https://python-all.ru/3.2/library/string.html#string.Template) (добавлено в Python 2.4) и [`str.format()`](https://python-all.ru/3.2/library/stdtypes.html#str.format) (добавлено в Python 2.6).830831Логирование (начиная с версии 3.2) обеспечивает улучшенную поддержку этих двух дополнительных стилей форматирования. Класс `Formatter` был расширен, чтобы принимать дополнительный необязательный именованный параметр с именем `style`. По умолчанию он равен `'%'`, но другими возможными значениями являются `'{'` и `'$'`, которые соответствуют двум другим стилям форматирования. Обратная совместимость поддерживается по умолчанию (как и ожидается), но при явном указании параметра style вы получаете возможность задавать строки формата, которые работают с [`str.format()`](https://python-all.ru/3.2/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.2/library/string.html#string.Template). Вот пример сеанса консоли, показывающий возможности:832833```pycon834>>> import logging835>>> root = logging.getLogger()836>>> root.setLevel(logging.DEBUG)837>>> handler = logging.StreamHandler()838>>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}',839... style='{')840>>> handler.setFormatter(bf)841>>> root.addHandler(handler)842>>> logger = logging.getLogger('foo.bar')843>>> logger.debug('This is a DEBUG message')8442010-10-28 15:11:55,341 foo.bar DEBUG This is a DEBUG message845>>> logger.critical('This is a CRITICAL message')8462010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message847>>> df = logging.Formatter('$asctime $name ${levelname} $message',848... style='$')849>>> handler.setFormatter(df)850>>> logger.debug('This is a DEBUG message')8512010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message852>>> logger.critical('This is a CRITICAL message')8532010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message854>>>855```856857Обратите внимание: форматирование сообщений журнала для конечного вывода в файлы совершенно не зависит от того, как конструируется отдельное сообщение. Оно по-прежнему может использовать %-форматирование, как показано ниже:858859```python860>>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')8612010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message862>>>863```864865Вызовы логирования (`logger.debug()`, `logger.info()` и т.д.) принимают только позиционные параметры для самого сообщения логирования, а именованные параметры используются только для определения параметров обработки самого вызова логирования (например, именованный параметр `exc_info` для указания, что следует регистрировать трассировку стека, или именованный параметр `extra` для указания дополнительной контекстной информации, добавляемой в журнал). Поэтому вы не можете напрямую делать вызовы логирования, используя синтаксис [`str.format()`](https://python-all.ru/3.2/library/stdtypes.html#str.format) или [`string.Template`](https://python-all.ru/3.2/library/string.html#string.Template), потому что внутри пакет logging использует %-форматирование для объединения строки формата и переменных аргументов. Это невозможно изменить, сохраняя обратную совместимость, поскольку все существующие вызовы логирования в существующем коде будут использовать %-строки формата.866867Однако есть способ использовать форматирование {}- и $- для построения отдельных сообщений журнала. Напомним, что в качестве строки формата сообщения можно использовать произвольный объект, и пакет logging вызовет `str()` для этого объекта, чтобы получить фактическую строку формата. Рассмотрим следующие два класса:868869```python870class BraceMessage:871 def __init__(self, fmt, *args, **kwargs):872 self.fmt = fmt873 self.args = args874 self.kwargs = kwargs875876 def __str__(self):877 return self.fmt.format(*self.args, **self.kwargs)878879class DollarMessage:880 def __init__(self, fmt, **kwargs):881 self.fmt = fmt882 self.kwargs = kwargs883884 def __str__(self):885 from string import Template886 return Template(self.fmt).substitute(**self.kwargs)887```888889Любой из них можно использовать вместо строки формата, чтобы разрешить {}- или $-форматирование для построения фактической части «message», которая появляется в форматированном выводе журнала вместо «%(message)s» или «{message}» или «$message». Использовать имена классов всякий раз, когда нужно что-то записать, немного неудобно, но вполне приемлемо, если использовать псевдоним, например \_\_ (двойное подчеркивание – не путать с \_, одиночным подчеркиванием, используемым как синоним/псевдоним для [`gettext.gettext()`](https://python-all.ru/3.2/library/gettext.html#gettext.gettext) или его собратьев).890891Вышеуказанные классы не входят в состав Python, но их достаточно легко скопировать и вставить в свой код. Использовать их можно следующим образом (при условии, что они объявлены в модуле с именем `wherever`):892893```pycon894>>> from wherever import BraceMessage as __895>>> print(__('Message with {0} {name}', 2, name='placeholders'))896Message with 2 placeholders897>>> class Point: pass898...899>>> p = Point()900>>> p.x = 0.5901>>> p.y = 0.5902>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})',903... point=p))904Message with coordinates: (0.50, 0.50)905>>> from wherever import DollarMessage as __906>>> print(__('Message with $num $what', num=2, what='placeholders'))907Message with 2 placeholders908>>>909```910911Хотя в приведённых выше примерах используется `print()` для демонстрации работы форматирования, в реальном логировании, конечно, применяется `logger.debug()` или аналогичный метод.912913Следует отметить, что этот подход не даёт значительного снижения производительности с этим подходом: фактическое форматирование происходит не тогда, когда вы делаете вызов регистрации, а когда (и если) регистрируемое сообщение действительно должно быть выведено в журнал с помощью обработчика. Поэтому единственное, что может сбить с толку, – это то, что скобки ставятся вокруг строки формата и аргументов, а не только вокруг строки формата. Это потому, что нотация \_\_ – это просто синтаксический сахар для вызова конструктора одного из классов XXXMessage.914915## Настройка `LogRecord`916917Каждое событие логирования представлено экземпляром [`LogRecord`](https://python-all.ru/3.2/library/logging.html#logging.LogRecord). Когда событие логируется и не отфильтровывается по уровню регистратора, создаётся [`LogRecord`](https://python-all.ru/3.2/library/logging.html#logging.LogRecord), заполняется информацией о событии и передаётся обработчикам этого регистратора (и его предкам, вплоть до регистратора, у которого дальнейшее распространение вверх по иерархии отключено). До Python 3.2 создание выполнялось только в двух местах:918919- [`Logger.makeRecord()`](https://python-all.ru/3.2/library/logging.html#logging.Logger.makeRecord) – вызывается в обычном процессе записи события. Он напрямую обращался к [`LogRecord`](https://python-all.ru/3.2/library/logging.html#logging.LogRecord) для создания экземпляра.920- [`makeLogRecord()`](https://python-all.ru/3.2/library/logging.html#logging.makeLogRecord), which is called with a dictionary containing attributes to be added to the LogRecord. This is typically invoked when a suitable dictionary has been received over the network (e.g. in pickle form via a [`SocketHandler`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.SocketHandler), or in JSON form via an [`HTTPHandler`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.HTTPHandler)).921922Обычно это означало, что если требуется что-то особенное с [`LogRecord`](https://python-all.ru/3.2/library/logging.html#logging.LogRecord), приходилось делать одно из следующего.923924- Создать собственный подкласс [`Logger`](https://python-all.ru/3.2/library/logging.html#logging.Logger), переопределяющий [`Logger.makeRecord()`](https://python-all.ru/3.2/library/logging.html#logging.Logger.makeRecord), и установить его с помощью [`setLoggerClass()`](https://python-all.ru/3.2/library/logging.html#logging.setLoggerClass) до того, как будут созданы какие-либо нужные регистраторы.925- Добавить [`Filter`](https://python-all.ru/3.2/library/logging.html#logging.Filter) в регистратор или обработчик, который выполняет необходимые специальные манипуляции при вызове его метода [`filter()`](https://python-all.ru/3.2/library/logging.html#logging.Filter.filter).926927Первый подход был бы несколько громоздким, если, скажем, несколько разных библиотек хотели делать разные вещи. Каждая пыталась бы установить собственный подкласс [`Logger`](https://python-all.ru/3.2/library/logging.html#logging.Logger), и победила бы та, которая сделала это последней.928929Второй подход во многих случаях работает достаточно хорошо, но не позволяет, например, использовать специализированный подкласс [`LogRecord`](https://python-all.ru/3.2/library/logging.html#logging.LogRecord). Разработчики библиотек могут установить подходящий фильтр для своих регистраторов, но им придётся помнить об этом каждый раз, когда они создают новый регистратор (что они делают, просто добавляя новые пакеты или модули и выполняя930931```python932logger = logging.getLogger(__name__)933```934935на уровне модуля). Вероятно, это лишняя забота. Разработчики могли бы также добавить фильтр в [`NullHandler`](https://python-all.ru/3.2/library/logging.handlers.html#logging.NullHandler), прикреплённый к их корневому регистратору, но он не будет вызываться, если разработчик приложения присоединит обработчик к нижележащему библиотечному регистратору – тогда вывод этого обработчика не отразит намерений разработчика библиотеки.936937В Python 3.2 и новее создание [`LogRecord`](https://python-all.ru/3.2/library/logging.html#logging.LogRecord) осуществляется через фабрику, которую можно указать. Фабрика – это просто вызываемый объект, который можно установить с помощью [`setLogRecordFactory()`](https://python-all.ru/3.2/library/logging.html#logging.setLogRecordFactory) и запросить через [`getLogRecordFactory()`](https://python-all.ru/3.2/library/logging.html#logging.getLogRecordFactory). Фабрика вызывается с той же сигнатурой, что и конструктор [`LogRecord`](https://python-all.ru/3.2/library/logging.html#logging.LogRecord), поскольку [`LogRecord`](https://python-all.ru/3.2/library/logging.html#logging.LogRecord) является настройкой по умолчанию для фабрики.938939Этот подход позволяет пользовательской фабрике контролировать все аспекты создания LogRecord. Например, можно вернуть подкласс или просто добавить несколько дополнительных атрибутов к записи после ее создания, используя шаблон, подобный следующему:940941```python942old_factory = logging.getLogRecordFactory()943944def record_factory(*args, **kwargs):945 record = old_factory(*args, **kwargs)946 record.custom_attribute = 0xdecafbad947 return record948949logging.setLogRecordFactory(record_factory)950```951952Такой подход позволяет разным библиотекам объединять фабрики в цепочку, и пока они не перезаписывают атрибуты друг друга или случайно не переопределяют стандартные атрибуты, неожиданностей быть не должно. Однако следует помнить, что каждое звено в цепочке добавляет дополнительные накладные расходы во время выполнения всех операций логирования, и этот метод следует использовать только тогда, когда применение [`Filter`](https://python-all.ru/3.2/library/logging.html#logging.Filter) не даёт желаемого результата.953954## Создание подкласса QueueHandler – пример с ZeroMQ955956Можно использовать подкласс `QueueHandler` для отправки сообщений в очереди других типов, например, в сокет «публикации» ZeroMQ. В примере ниже сокет создаётся отдельно и передаётся обработчику (в качестве его «очереди»):957958```python959import zmq # с использованием pyzmq, привязки Python к ZeroMQ960import json # для переносимой сериализации записей961962ctx = zmq.Context()963sock = zmq.Socket(ctx, zmq.PUB) # или zmq.PUSH, или другое подходящее значение964sock.bind('tcp://*:5556') # или где угодно965966class ZeroMQSocketHandler(QueueHandler):967 def enqueue(self, record):968 data = json.dumps(record.__dict__)969 self.queue.send(data)970971handler = ZeroMQSocketHandler(sock)972```973974Конечно, есть и другие способы организации этого, например, передача данных, необходимых обработчику для создания сокета:975976```python977class ZeroMQSocketHandler(QueueHandler):978 def __init__(self, uri, socktype=zmq.PUB, ctx=None):979 self.ctx = ctx or zmq.Context()980 socket = zmq.Socket(self.ctx, socktype)981 socket.bind(uri)982 QueueHandler.__init__(self, socket)983984 def enqueue(self, record):985 data = json.dumps(record.__dict__)986 self.queue.send(data)987988 def close(self):989 self.queue.close()990```991992## Создание подкласса QueueListener – пример с ZeroMQ993994Также можно создать подкласс `QueueListener` для получения сообщений из очередей других типов, например, из сокета «подписки» ZeroMQ. Вот пример:995996```python997class ZeroMQSocketListener(QueueListener):998 def __init__(self, uri, *handlers, **kwargs):999 self.ctx = kwargs.get('ctx') or zmq.Context()1000 socket = zmq.Socket(self.ctx, zmq.SUB)1001 socket.setsockopt(zmq.SUBSCRIBE, '') # подписаться на всё1002 socket.connect(uri)10031004 def dequeue(self):1005 msg = self.queue.recv()1006 return logging.makeLogRecord(json.loads(msg))1007```10081009> **См. также**1010>1011> **Модуль [`logging`](https://python-all.ru/3.2/library/logging.html#module-logging)**1012>1013> Справочник API для модуля logging.1014>1015> **Модуль [`logging.config`](https://python-all.ru/3.2/library/logging.config.html#module-logging.config)**1016>1017> API конфигурации для модуля logging.1018>1019> **Модуль [`logging.handlers`](https://python-all.ru/3.2/library/logging.handlers.html#module-logging.handlers)**1020>1021> Полезные обработчики, входящие в состав модуля logging.1022>1023> [*Базовое руководство по логированию*](https://python-all.ru/3.2/howto/logging.html#logging-basic-tutorial)1024>1025> [*Более продвинутое руководство по логированию*](https://python-all.ru/3.2/howto/logging.html#logging-advanced-tutorial)10261027## Пример конфигурации на основе словаря10281029Ниже приведён пример словаря конфигурации логирования – он взят из [документации проекта Django](https://python-all.ru/3.2/howto/logging-cookbook.html). Этот словарь передаётся в [`dictConfig()`](https://python-all.ru/3.2/library/logging.config.html#logging.config.dictConfig) для применения конфигурации:10301031```python1032LOGGING = {1033 'version': 1,1034 'disable_existing_loggers': True,1035 'formatters': {1036 'verbose': {1037 'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'1038 },1039 'simple': {1040 'format': '%(levelname)s %(message)s'1041 },1042 },1043 'filters': {1044 'special': {1045 '()': 'project.logging.SpecialFilter',1046 'foo': 'bar',1047 }1048 },1049 'handlers': {1050 'null': {1051 'level':'DEBUG',1052 'class':'django.utils.log.NullHandler',1053 },1054 'console':{1055 'level':'DEBUG',1056 'class':'logging.StreamHandler',1057 'formatter': 'simple'1058 },1059 'mail_admins': {1060 'level': 'ERROR',1061 'class': 'django.utils.log.AdminEmailHandler',1062 'filters': ['special']1063 }1064 },1065 'loggers': {1066 'django': {1067 'handlers':['null'],1068 'propagate': True,1069 'level':'INFO',1070 },1071 'django.request': {1072 'handlers': ['mail_admins'],1073 'level': 'ERROR',1074 'propagate': False,1075 },1076 'myproject.custom': {1077 'handlers': ['console', 'mail_admins'],1078 'level': 'INFO',1079 'filters': ['special']1080 }1081 }1082}1083```10841085Для получения дополнительной информации об этой конфигурации можно обратиться к [соответствующему разделу](https://python-all.ru/3.2/howto/logging-cookbook.html) документации Django.10861087## Более сложный пример с многопроцессностью10881089Следующий рабочий пример показывает, как можно использовать логирование с многопроцессностью с помощью файлов конфигурации. Конфигурации довольно просты, но служат иллюстрацией того, как можно реализовать более сложные в реальном сценарии многопроцессной обработки.10901091В примере главный процесс порождает процесс-слушатель и несколько рабочих процессов. Каждый из главного процесса, слушателя и рабочих имеет три отдельные конфигурации (все рабочие используют одну и ту же конфигурацию). Видно ведение журнала в главном процессе, как рабочие пишут в QueueHandler, а слушатель реализует QueueListener и более сложную конфигурацию ведения журнала, и организует отправку событий, полученных через очередь, обработчикам, указанным в конфигурации. Обратите внимание, что эти конфигурации чисто иллюстративные, но этот пример можно адаптировать под свой сценарий.10921093Вот скрипт – строки документации и комментарии, надеюсь, поясняют, как он работает:10941095```python1096import logging1097import logging.config1098import logging.handlers1099from multiprocessing import Process, Queue, Event, current_process1100import os1101import random1102import time11031104class MyHandler:1105 """1106 Простой обработчик для событий логирования. Он выполняется в процессе-слушателе и1107 распределяет события по логгерам на основе имени в полученной записи,1108 которые затем передаются системой логирования обработчикам,1109 настроенным для этих логгеров.1110 """1111 def handle(self, record):1112 logger = logging.getLogger(record.name)1113 # Имя процесса преобразуется только для того, чтобы показать, что это слушатель1114 # выполняет логирование в файлы и консоль.1115 record.processName = '%s (for %s)' % (current_process().name, record.processName)1116 logger.handle(record)11171118def listener_process(q, stop_event, config):1119 """1120 Это можно было бы сделать в главном процессе, но сделано в отдельном1121 процессе для наглядности.11221123 Это инициализирует логирование согласно указанной конфигурации1124 запускает слушатель и ожидает сигнала от главного процесса о завершении1125 через событие. Затем слушатель останавливается, и процесс завершается.1126 """1127 logging.config.dictConfig(config)1128 listener = logging.handlers.QueueListener(q, MyHandler())1129 listener.start()1130 if os.name == 'posix':1131 # В POSIX логгер setup уже был настроен в1132 # родительском процессе, но должен был быть отключён после вызова1133 # dictConfig.1134 # В Windows, поскольку fork не используется, логгер setup не будет1135 # существовать в дочернем процессе, поэтому он будет создан, и сообщение1136 # появится – отсюда и конструкция "if posix".1137 logger = logging.getLogger('setup')1138 logger.critical('Should not appear, because of disabled logger ...')1139 stop_event.wait()1140 listener.stop()11411142def worker_process(config):1143 """1144 Некоторое количество таких процессов порождается для иллюстрации. На1145 на практике это может быть разнородная группа процессов, а не1146 идентичные друг другу.11471148 Это инициализирует логирование согласно указанной конфигурации1149 и записывает сотню сообщений со случайными уровнями в случайно выбранные1150 логгеры.11511152 Добавлена небольшая задержка, чтобы дать другим процессам шанс выполниться. Это1153 не является строго необходимым, но позволяет немного перемешать вывод от разных1154 процессов больше, чем если бы её не было.1155 """1156 logging.config.dictConfig(config)1157 levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,1158 logging.CRITICAL]1159 loggers = ['foo', 'foo.bar', 'foo.bar.baz',1160 'spam', 'spam.ham', 'spam.ham.eggs']1161 if os.name == 'posix':1162 # В POSIX логгер setup уже был настроен в1163 # родительском процессе, но должен был быть отключён после вызова1164 # dictConfig.1165 # В Windows, поскольку fork не используется, логгер setup не будет1166 # существовать в дочернем процессе, поэтому он будет создан, и сообщение1167 # появится – отсюда и конструкция "if posix".1168 logger = logging.getLogger('setup')1169 logger.critical('Should not appear, because of disabled logger ...')1170 for i in range(100):1171 lvl = random.choice(levels)1172 logger = logging.getLogger(random.choice(loggers))1173 logger.log(lvl, 'Message no. %d', i)1174 time.sleep(0.01)11751176def main():1177 q = Queue()1178 # Главный процесс получает простую конфигурацию, которая выводит информацию в консоль.1179 config_initial = {1180 'version': 1,1181 'formatters': {1182 'detailed': {1183 'class': 'logging.Formatter',1184 'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1185 }1186 },1187 'handlers': {1188 'console': {1189 'class': 'logging.StreamHandler',1190 'level': 'INFO',1191 },1192 },1193 'root': {1194 'level': 'DEBUG',1195 'handlers': ['console']1196 },1197 }1198 # Конфигурация рабочего процесса представляет собой QueueHandler, прикреплённый к1199 # корневому логгеру, что позволяет отправлять все сообщения в очередь.1200 # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1201 # родительском процессе. Это необходимо в POSIX, потому что логгер будет1202 # присутствовать в дочернем процессе после вызова fork().1203 config_worker = {1204 'version': 1,1205 'disable_existing_loggers': True,1206 'handlers': {1207 'queue': {1208 'class': 'logging.handlers.QueueHandler',1209 'queue': q,1210 },1211 },1212 'root': {1213 'level': 'DEBUG',1214 'handlers': ['queue']1215 },1216 }1217 # Конфигурация процесса-слушателя показывает, что вся гибкость1218 # конфигурации логирования доступна для отправки событий обработчикам так, как1219 # требуется.1220 # Мы отключаем существующие логгеры, чтобы отключить логгер "setup", используемый в1221 # родительском процессе. Это необходимо в POSIX, потому что логгер будет1222 # присутствовать в дочернем процессе после вызова fork().1223 config_listener = {1224 'version': 1,1225 'disable_existing_loggers': True,1226 'formatters': {1227 'detailed': {1228 'class': 'logging.Formatter',1229 'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1230 },1231 'simple': {1232 'class': 'logging.Formatter',1233 'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'1234 }1235 },1236 'handlers': {1237 'console': {1238 'class': 'logging.StreamHandler',1239 'level': 'INFO',1240 'formatter': 'simple',1241 },1242 'file': {1243 'class': 'logging.FileHandler',1244 'filename': 'mplog.log',1245 'mode': 'w',1246 'formatter': 'detailed',1247 },1248 'foofile': {1249 'class': 'logging.FileHandler',1250 'filename': 'mplog-foo.log',1251 'mode': 'w',1252 'formatter': 'detailed',1253 },1254 'errors': {1255 'class': 'logging.FileHandler',1256 'filename': 'mplog-errors.log',1257 'mode': 'w',1258 'level': 'ERROR',1259 'formatter': 'detailed',1260 },1261 },1262 'loggers': {1263 'foo': {1264 'handlers' : ['foofile']1265 }1266 },1267 'root': {1268 'level': 'DEBUG',1269 'handlers': ['console', 'file', 'errors']1270 },1271 }1272 # Записываем несколько начальных событий, просто чтобы показать, что логирование в родительском процессе работает1273 # нормально.1274 logging.config.dictConfig(config_initial)1275 logger = logging.getLogger('setup')1276 logger.info('About to create workers ...')1277 workers = []1278 for i in range(5):1279 wp = Process(target=worker_process, name='worker %d' % (i + 1),1280 args=(config_worker,))1281 workers.append(wp)1282 wp.start()1283 logger.info('Started worker: %s', wp.name)1284 logger.info('About to create listener ...')1285 stop_event = Event()1286 lp = Process(target=listener_process, name='listener',1287 args=(q, stop_event, config_listener))1288 lp.start()1289 logger.info('Started listener')1290 # Теперь ожидаем завершения работы рабочих процессов.1291 for wp in workers:1292 wp.join()1293 # Все рабочие процессы завершены, теперь можно остановить прослушивание.1294 # Логирование в родительском процессе всё ещё работает нормально.1295 logger.info('Telling listener to stop ...')1296 stop_event.set()1297 lp.join()1298 logger.info('All done.')12991300if __name__ == '__main__':1301 main()1302```13031304## Вставка BOM в сообщения, отправляемые в SysLogHandler13051306[RFC 5424](https://python-all.ru/3.2/howto/logging-cookbook.html) требует, чтобы Unicode-сообщение отправлялось демону syslog в виде набора байтов следующей структуры: необязательный компонент, состоящий только из ASCII, затем метка порядка байтов (BOM) UTF-8, затем Unicode, закодированный в UTF-8. (См. [соответствующий раздел спецификации](https://python-all.ru/3.2/howto/logging-cookbook.html).)13071308В Python 3.1 в [`SysLogHandler`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.SysLogHandler) был добавлен код для вставки метки BOM в сообщение, но, к сожалению, он был реализован неправильно: BOM появлялся в начале сообщения, не позволяя никакому чисто ASCII-компоненту находиться перед ним.13091310Поскольку такое поведение некорректно, код, неправильно вставляющий BOM, удаляется из Python 3.2.4 и более поздних версий. Однако он не заменяется, и если требуется создавать сообщения, совместимые с RFC 5424, которые содержат BOM, необязательную последовательность символов только из ASCII перед ним и произвольный Unicode после него, закодированные в UTF-8, то необходимо сделать следующее:131113121. Прикрепите экземпляр [`Formatter`](https://python-all.ru/3.2/library/logging.html#logging.Formatter) к своему экземпляру [`SysLogHandler`](https://python-all.ru/3.2/library/logging.handlers.html#logging.handlers.SysLogHandler) со строкой формата, например:13131314 ```python1315 'ASCII section\ufeffUnicode section'1316 ```13171318 Кодовая точка Unicode U+FEFF при кодировании UTF-8 будет закодирована как метка BOM UTF-8 – строка байтов `b'\xef\xbb\xbf'`.13192. ASCII-часть следует заменить на любые подходящие заполнители, но необходимо следить, чтобы данные, которые появляются там после подстановки, всегда были в ASCII (таким образом, они останутся без изменений после кодирования UTF-8).13203. Unicode-часть следует заменить на любые заполнители; если данные после подстановки содержат символы за пределами диапазона ASCII, это нормально – они будут закодированы в UTF-8.13211322Отформатированное сообщение *будет* закодировано `SysLogHandler` в кодировке UTF-8. Если соблюдать приведённые выше правила, можно создавать сообщения, совместимые с RFC 5424. В противном случае логирование может не жаловаться, но сообщения не будут соответствовать RFC 5424, и ваш демон syslog может начать жаловаться.13231324## Реализация структурированного ведения журнала13251326Хотя большинство сообщений лога предназначены для чтения человеком и поэтому нелегко разбираются машиной, могут возникнуть ситуации, когда нужно выводить сообщения в структурированном формате, *который* может быть проанализирован программой (без необходимости сложных регулярных выражений для разбора сообщения лога). Это легко достигается с помощью пакета logging. Есть несколько способов это сделать, но ниже приведён простой подход, использующий JSON для сериализации события в машиночитаемом виде:13271328```python1329import json1330import logging13311332class StructuredMessage(object):1333 def __init__(self, message, **kwargs):1334 self.message = message1335 self.kwargs = kwargs13361337 def __str__(self):1338 return '%s >>> %s' % (self.message, json.dumps(self.kwargs))13391340_ = StructuredMessage # необязательно, для улучшения читаемости13411342logging.basicConfig(level=logging.INFO, format='%(message)s')1343logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))1344```13451346Если запустить приведённый выше скрипт, он выведет:13471348```python1349message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}1350```13511352Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.13531354Если требуется более специализированная обработка, можно использовать пользовательский кодировщик JSON, как в следующем полном примере:13551356```python1357from __future__ import unicode_literals13581359import json1360import logging13611362# Следующий фрагмент предназначен для того, чтобы скрипт работал без изменений в версиях 2.x и 3.x.1363try:1364 unicode1365except NameError:1366 unicode = str13671368class Encoder(json.JSONEncoder):1369 def default(self, o):1370 if isinstance(o, set):1371 return tuple(o)1372 elif isinstance(o, unicode):1373 return o.encode('unicode_escape').decode('ascii')1374 return super(Encoder, self).default(o)13751376class StructuredMessage(object):1377 def __init__(self, message, **kwargs):1378 self.message = message1379 self.kwargs = kwargs13801381 def __str__(self):1382 s = Encoder().encode(self.kwargs)1383 return '%s >>> %s' % (self.message, s)13841385_ = StructuredMessage # необязательно, для улучшения читаемости13861387def main():1388 logging.basicConfig(level=logging.INFO, format='%(message)s')1389 logging.info(_('message 1', set_value=set([1, 2, 3]), snowman='\u2603'))13901391if __name__ == '__main__':1392 main()1393```13941395При запуске приведённого выше скрипта он выведет:13961397```python1398message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}1399```14001401Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.1402