logging-cookbook.md
1> **Источник:** https://python-all.ru/2.7/howto/logging-cookbook.html2>3> «Документация Python на русском» – неофициальный перевод официальной документации Python: версии от 2.6 до 3.16, полнотекстовый поиск, английский оригинал рядом с переводом. Эта Markdown-версия страницы предназначена для работы с LLM: вставьте её в ChatGPT, Claude или Cursor.45---67# Сборник рецептов по логированию89**Автор**1011Vinay Sajip \<vinay\_sajip at red-dove dot com\>1213На этой странице представлен ряд рецептов, связанных с логированием, которые оказались полезными на практике.1415## Использование логирования в нескольких модулях1617Многократные вызовы `logging.getLogger('someLogger')` возвращают ссылку на один и тот же объект логгера. Это верно не только в пределах одного модуля, но и для разных модулей, если они выполняются в одном процессе интерпретатора Python. Кроме того, код приложения может определить и настроить родительский логгер в одном модуле, а затем создать (но не настраивать) дочерний логгер в другом модуле – все вызовы логгера у дочернего будут передаваться родительскому. Вот главный модуль:1819```python20import logging21import auxiliary_module2223# создать логгер с именем 'spam_application'24logger = logging.getLogger('spam_application')25logger.setLevel(logging.DEBUG)26# создать файловый обработчик, записывающий даже отладочные сообщения27fh = logging.FileHandler('spam.log')28fh.setLevel(logging.DEBUG)29# создать консольный обработчик с более высоким уровнем логирования30ch = logging.StreamHandler()31ch.setLevel(logging.ERROR)32# создать форматтер и добавить его к обработчикам33formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')34fh.setFormatter(formatter)35ch.setFormatter(formatter)36# добавить обработчики к логгеру37logger.addHandler(fh)38logger.addHandler(ch)3940logger.info('creating an instance of auxiliary_module.Auxiliary')41a = auxiliary_module.Auxiliary()42logger.info('created an instance of auxiliary_module.Auxiliary')43logger.info('calling auxiliary_module.Auxiliary.do_something')44a.do_something()45logger.info('finished auxiliary_module.Auxiliary.do_something')46logger.info('calling auxiliary_module.some_function()')47auxiliary_module.some_function()48logger.info('done with auxiliary_module.some_function()')49```5051А вот вспомогательный модуль:5253```python54import logging5556# создать логгер57module_logger = logging.getLogger('spam_application.auxiliary')5859class Auxiliary:60 def __init__(self):61 self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')62 self.logger.info('creating an instance of Auxiliary')6364 def do_something(self):65 self.logger.info('doing something')66 a = 1 + 167 self.logger.info('done doing something')6869def some_function():70 module_logger.info('received a call to "some_function"')71```7273Вывод выглядит так:7475```python762005-03-23 23:47:11,663 - spam_application - INFO -77 creating an instance of auxiliary_module.Auxiliary782005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -79 creating an instance of Auxiliary802005-03-23 23:47:11,665 - spam_application - INFO -81 created an instance of auxiliary_module.Auxiliary822005-03-23 23:47:11,668 - spam_application - INFO -83 calling auxiliary_module.Auxiliary.do_something842005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -85 doing something862005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -87 done doing something882005-03-23 23:47:11,670 - spam_application - INFO -89 finished auxiliary_module.Auxiliary.do_something902005-03-23 23:47:11,671 - spam_application - INFO -91 calling auxiliary_module.some_function()922005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -93 received a call to 'some_function'942005-03-23 23:47:11,673 - spam_application - INFO -95 done with auxiliary_module.some_function()96```9798## Журналирование из нескольких потоков99100Логирование из нескольких потоков не требует особых усилий. Следующий пример показывает логирование из главного (начального) потока и другого потока:101102```python103import logging104import threading105import time106107def worker(arg):108 while not arg['stop']:109 logging.debug('Hi from myfunc')110 time.sleep(0.5)111112def main():113 logging.basicConfig(level=logging.DEBUG, format='%(relativeCreated)6d %(threadName)s %(message)s')114 info = {'stop': False}115 thread = threading.Thread(target=worker, args=(info,))116 thread.start()117 while True:118 try:119 logging.debug('Hello from main')120 time.sleep(0.75)121 except KeyboardInterrupt:122 info['stop'] = True123 break124 thread.join()125126if __name__ == '__main__':127 main()128```129130При запуске скрипт должен вывести что-то вроде следующего:131132```python133 0 Thread-1 Hi from myfunc134 3 MainThread Hello from main135 505 Thread-1 Hi from myfunc136 755 MainThread Hello from main1371007 Thread-1 Hi from myfunc1381507 MainThread Hello from main1391508 Thread-1 Hi from myfunc1402010 Thread-1 Hi from myfunc1412258 MainThread Hello from main1422512 Thread-1 Hi from myfunc1433009 MainThread Hello from main1443013 Thread-1 Hi from myfunc1453515 Thread-1 Hi from myfunc1463761 MainThread Hello from main1474017 Thread-1 Hi from myfunc1484513 MainThread Hello from main1494518 Thread-1 Hi from myfunc150```151152Как и следовало ожидать, вывод журнала перемежается. Разумеется, такой подход работает и для большего количества потоков, чем показано здесь.153154## Несколько обработчиков и форматировщиков155156Логгеры – это обычные объекты Python. У метода [`addHandler()`](https://python-all.ru/2.7/library/logging.html#logging.Logger.addHandler) нет минимального или максимального ограничения на количество добавляемых обработчиков. Иногда приложению полезно записывать все сообщения всех уровней в текстовый файл и одновременно выводить ошибки и сообщения выше в консоль. Чтобы это настроить, достаточно сконфигурировать нужные обработчики. Вызовы журналирования в коде приложения останутся без изменений. Вот небольшая модификация предыдущего простого примера конфигурации на основе модуля:157158```python159import logging160161logger = logging.getLogger('simple_example')162logger.setLevel(logging.DEBUG)163# создать файловый обработчик, записывающий даже отладочные сообщения164fh = logging.FileHandler('spam.log')165fh.setLevel(logging.DEBUG)166# создать консольный обработчик с более высоким уровнем логирования167ch = logging.StreamHandler()168ch.setLevel(logging.ERROR)169# создать форматтер и добавить его к обработчикам170formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')171ch.setFormatter(formatter)172fh.setFormatter(formatter)173# добавить обработчики в логгер174logger.addHandler(ch)175logger.addHandler(fh)176177# код 'приложения'178logger.debug('debug message')179logger.info('info message')180logger.warn('warn message')181logger.error('error message')182logger.critical('critical message')183```184185Обратите внимание, что «прикладной» код не заботится о нескольких обработчиках. Единственное, что изменилось – добавление и настройка нового обработчика с именем *fh*.186187Возможность создавать новые обработчики с фильтрами более высокого или низкого уровня очень полезна при написании и тестировании приложения. Вместо множества операторов `print` для отладки используйте `logger.debug`: в отличие от операторов print, которые позже придётся удалять или закомментировать, вызовы logger.debug могут оставаться в исходном коде и оставаться неактивными, пока они снова не понадобятся. В тот момент единственное, что нужно изменить – уровень журналирования логгера и/или обработчика на DEBUG.188189## Журналирование в несколько мест назначения190191Допустим, вы хотите вести журнал в консоль и файл с разными форматами сообщений и в разных ситуациях. Предположим, вы хотите записывать сообщения уровня DEBUG и выше в файл, а сообщения уровня INFO и выше – в консоль. Также предположим, что файл должен содержать временные метки, а консольные сообщения – нет. Вот как это можно сделать:192193```python194import logging195196# настроить логирование в файл – подробнее см. предыдущий раздел197logging.basicConfig(level=logging.DEBUG,198 format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',199 datefmt='%m-%d %H:%M',200 filename='/temp/myapp.log',201 filemode='w')202# Определяет обработчик, который записывает сообщения уровня INFO и выше в sys.stderr.203console = logging.StreamHandler()204console.setLevel(logging.INFO)205# Задает формат, упрощенный для вывода в консоль.206formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')207# Указывает обработчику использовать этот формат.208console.setFormatter(formatter)209# Добавляет обработчик в корневой логгер.210logging.getLogger('').addHandler(console)211212# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...213logging.info('Jackdaws love my big sphinx of quartz.')214215# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:216# приложение:217218logger1 = logging.getLogger('myapp.area1')219logger2 = logging.getLogger('myapp.area2')220221logger1.debug('Quick zephyrs blow, vexing daft Jim.')222logger1.info('How quickly daft jumping zebras vex.')223logger2.warning('Jail zesty vixen who grabbed pay from quack.')224logger2.error('The five boxing wizards jump quickly.')225```226227При запуске на консоли вы увидите228229```python230root : INFO Jackdaws love my big sphinx of quartz.231myapp.area1 : INFO How quickly daft jumping zebras vex.232myapp.area2 : WARNING Jail zesty vixen who grabbed pay from quack.233myapp.area2 : ERROR The five boxing wizards jump quickly.234```235236а в файле увидите примерно такое237238```python23910-22 22:19 root INFO Jackdaws love my big sphinx of quartz.24010-22 22:19 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim.24110-22 22:19 myapp.area1 INFO How quickly daft jumping zebras vex.24210-22 22:19 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack.24310-22 22:19 myapp.area2 ERROR The five boxing wizards jump quickly.244```245246Как видите, сообщение DEBUG отображается только в файле. Остальные сообщения отправляются в оба места назначения.247248В этом примере используются консольный и файловый обработчики, но вы можете использовать любое количество и любое сочетание обработчиков по своему выбору.249250## Пример сервера конфигурации251252Вот пример модуля, использующего сервер конфигурации журналирования:253254```python255import logging256import logging.config257import time258import os259260# Прочитать начальный конфигурационный файл.261logging.config.fileConfig('logging.conf')262263# Создать и запустить слушатель на порту 9999.264t = logging.config.listen(9999)265t.start()266267logger = logging.getLogger('simpleExample')268269try:270 # Прокрутить вызовы логирования, чтобы увидеть разницу.271 # Создавать новые конфигурации до нажатия Ctrl+C.272 while True:273 logger.debug('debug message')274 logger.info('info message')275 logger.warn('warn message')276 logger.error('error message')277 logger.critical('critical message')278 time.sleep(5)279except KeyboardInterrupt:280 # очистка281 logging.config.stopListening()282 t.join()283```284285А вот скрипт, который принимает имя файла и отправляет этот файл на сервер, предварив его двоично-закодированной длиной, в качестве новой конфигурации журналирования:286287```python288#!/usr/bin/env python289import socket, sys, struct290291with open(sys.argv[1], 'rb') as f:292 data_to_send = f.read()293294HOST = 'localhost'295PORT = 9999296s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)297print('connecting...')298s.connect((HOST, PORT))299print('sending config...')300s.send(struct.pack('>L', len(data_to_send)))301s.send(data_to_send)302s.close()303print('complete')304```305306## Отправка и получение событий логирования по сети307308Допустим, вы хотите отправлять события логирования по сети и обрабатывать их на принимающей стороне. Простой способ – подключить экземпляр `SocketHandler` к корневому логгеру на отправляющей стороне:309310```python311import logging, logging.handlers312313rootLogger = logging.getLogger('')314rootLogger.setLevel(logging.DEBUG)315socketHandler = logging.handlers.SocketHandler('localhost',316 logging.handlers.DEFAULT_TCP_LOGGING_PORT)317# Не нужно использовать форматтер, так как сокет-обработчик отправляет событие в виде неформатированного пикла.318# неформатированный pickle319rootLogger.addHandler(socketHandler)320321# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...322logging.info('Jackdaws love my big sphinx of quartz.')323324# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:325# приложение:326327logger1 = logging.getLogger('myapp.area1')328logger2 = logging.getLogger('myapp.area2')329330logger1.debug('Quick zephyrs blow, vexing daft Jim.')331logger1.info('How quickly daft jumping zebras vex.')332logger2.warning('Jail zesty vixen who grabbed pay from quack.')333logger2.error('The five boxing wizards jump quickly.')334```335336На принимающей стороне можно настроить приёмник с помощью модуля [`SocketServer`](https://python-all.ru/2.7/library/socketserver.html#module-SocketServer). Вот простой работающий пример:337338```python339import pickle340import logging341import logging.handlers342import SocketServer343import struct344345class LogRecordStreamHandler(SocketServer.StreamRequestHandler):346 """Обработчик для потокового запроса логирования.347348 Это по сути записывает запись, используя ту политику логирования, которая настроена локально.349 настроено локально.350 """351352 def handle(self):353 """354 Обрабатывает несколько запросов – каждый ожидается в формате: 4-байтовая длина, затем запись журнала в формате пикл.355 Записывает запись в соответствии с политикой, настроенной локально.356 согласно локально настроенной политике.357 """358 while True:359 chunk = self.connection.recv(4)360 if len(chunk) < 4:361 break362 slen = struct.unpack('>L', chunk)[0]363 chunk = self.connection.recv(slen)364 while len(chunk) < slen:365 chunk = chunk + self.connection.recv(slen - len(chunk))366 obj = self.unPickle(chunk)367 record = logging.makeLogRecord(obj)368 self.handleLogRecord(record)369370 def unPickle(self, data):371 return pickle.loads(data)372373 def handleLogRecord(self, record):374 # Если указано имя, используется именованный логгер, а не тот, что375 # подразумевается записью.376 if self.server.logname is not None:377 name = self.server.logname378 else:379 name = record.name380 logger = logging.getLogger(name)381 # Примечание: КАЖДАЯ запись попадает в журнал. Это связано с тем, что Logger.handle382 # обычно вызывается ПОСЛЕ фильтрации на уровне регистратора. Если требуется383 # выполнять фильтрацию, делайте это на стороне клиента, чтобы не тратить384 # циклы процессора и сетевую пропускную способность!385 logger.handle(record)386387class LogRecordSocketReceiver(SocketServer.ThreadingTCPServer):388 """389 Простой приёмник журнала на основе TCP-сокетов, подходящий для тестирования.390 """391392 allow_reuse_address = 1393394 def __init__(self, host='localhost',395 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,396 handler=LogRecordStreamHandler):397 SocketServer.ThreadingTCPServer.__init__(self, (host, port), handler)398 self.abort = 0399 self.timeout = 1400 self.logname = None401402 def serve_until_stopped(self):403 import select404 abort = 0405 while not abort:406 rd, wr, ex = select.select([self.socket.fileno()],407 [], [],408 self.timeout)409 if rd:410 self.handle_request()411 abort = self.abort412413def main():414 logging.basicConfig(415 format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')416 tcpserver = LogRecordSocketReceiver()417 print('About to start TCP server...')418 tcpserver.serve_until_stopped()419420if __name__ == '__main__':421 main()422```423424Сначала запустите сервер, затем клиент. На стороне клиента в консоль ничего не выводится; на стороне сервера вы должны увидеть что-то вроде:425426```python427About to start TCP server...428 59 root INFO Jackdaws love my big sphinx of quartz.429 59 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim.430 69 myapp.area1 INFO How quickly daft jumping zebras vex.431 69 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack.432 69 myapp.area2 ERROR The five boxing wizards jump quickly.433```434435Обратите внимание, что в некоторых сценариях существуют проблемы безопасности с pickle. Если они вас затрагивают, вы можете использовать альтернативную схему сериализации, переопределив метод [`makePickle()`](https://python-all.ru/2.7/library/logging.handlers.html#logging.handlers.SocketHandler.makePickle) и реализовав свою альтернативу там, а также адаптировав вышеприведённый скрипт для использования вашей альтернативной сериализации.436437## Добавление контекстной информации в вывод журнала438439Иногда требуется, чтобы вывод журнала содержал контекстную информацию в дополнение к параметрам, переданным в вызове логирования. Например, в сетевом приложении может быть желательно записывать в журнал информацию, специфичную для клиента (например, имя пользователя удалённого клиента или IP-адрес). Хотя для этого можно использовать параметр *extra*, не всегда удобно передавать информацию таким образом. Может возникнуть соблазн создавать экземпляры [`Logger`](https://python-all.ru/2.7/library/logging.html#logging.Logger) для каждого соединения, но это плохая идея, поскольку такие экземпляры не собираются сборщиком мусора. Хотя на практике это не проблема, когда количество экземпляров [`Logger`](https://python-all.ru/2.7/library/logging.html#logging.Logger) зависит от уровня детализации, используемого при логировании приложения, управление ими может стать сложным, если количество экземпляров [`Logger`](https://python-all.ru/2.7/library/logging.html#logging.Logger) станет фактически неограниченным.440441### Использование LoggerAdapter для добавления контекстной информации442443Простой способ передавать контекстную информацию для вывода вместе с информацией о событиях логирования – использовать класс [`LoggerAdapter`](https://python-all.ru/2.7/library/logging.html#logging.LoggerAdapter). Этот класс спроектирован так, чтобы выглядеть как [`Logger`](https://python-all.ru/2.7/library/logging.html#logging.Logger), что позволяет вызывать [`debug()`](https://python-all.ru/2.7/library/logging.html#logging.debug), [`info()`](https://python-all.ru/2.7/library/logging.html#logging.info), [`warning()`](https://python-all.ru/2.7/library/logging.html#logging.warning), [`error()`](https://python-all.ru/2.7/library/logging.html#logging.error), [`exception()`](https://python-all.ru/2.7/library/logging.html#logging.exception), [`critical()`](https://python-all.ru/2.7/library/logging.html#logging.critical) и [`log()`](https://python-all.ru/2.7/library/logging.html#logging.log). Эти методы имеют те же сигнатуры, что и их аналоги в [`Logger`](https://python-all.ru/2.7/library/logging.html#logging.Logger), поэтому экземпляры обоих типов можно использовать взаимозаменяемо.444445При создании экземпляра [`LoggerAdapter`](https://python-all.ru/2.7/library/logging.html#logging.LoggerAdapter) вы передаёте ему экземпляр [`Logger`](https://python-all.ru/2.7/library/logging.html#logging.Logger) и объект, подобный словарю, содержащий вашу контекстную информацию. Когда вы вызываете один из методов логирования на экземпляре [`LoggerAdapter`](https://python-all.ru/2.7/library/logging.html#logging.LoggerAdapter), он делегирует вызов базовому экземпляру [`Logger`](https://python-all.ru/2.7/library/logging.html#logging.Logger), переданному в конструктор, и организует передачу контекстной информации в этом делегированном вызове. Вот фрагмент кода [`LoggerAdapter`](https://python-all.ru/2.7/library/logging.html#logging.LoggerAdapter):446447```python448def debug(self, msg, *args, **kwargs):449 """450 Передаёт вызов отладки нижележащему регистратору после добавления451 контекстной информации из данного экземпляра адаптера.452 """453 msg, kwargs = self.process(msg, kwargs)454 self.logger.debug(msg, *args, **kwargs)455```456457Метод [`process()`](https://python-all.ru/2.7/library/logging.html#logging.LoggerAdapter.process) класса [`LoggerAdapter`](https://python-all.ru/2.7/library/logging.html#logging.LoggerAdapter) – это то место, где контекстная информация добавляется в вывод журнала. Ему передаются сообщение и именованные аргументы вызова логирования, а он возвращает (потенциально) изменённые версии для использования в вызове базового регистратора. В реализации по умолчанию этот метод оставляет сообщение без изменений, но вставляет ключ 'extra' в именованные аргументы, значением которого является объект, подобный словарю, переданный конструктору. Конечно, если вы передали именованный аргумент 'extra' в вызове адаптера, он будет молча перезаписан.458459Преимущество использования 'extra' в том, что значения из объекта, подобного словарю, сливаются в \_\_dict\_\_ экземпляра [`LogRecord`](https://python-all.ru/2.7/library/logging.html#logging.LogRecord), что позволяет использовать настроенные строки с экземплярами [`Formatter`](https://python-all.ru/2.7/library/logging.html#logging.Formatter), которые знают о ключах этого объекта. Если вам нужен другой метод, например, добавить контекстную информацию в начало или конец строки сообщения, достаточно создать подкласс [`LoggerAdapter`](https://python-all.ru/2.7/library/logging.html#logging.LoggerAdapter) и переопределить [`process()`](https://python-all.ru/2.7/library/logging.html#logging.LoggerAdapter.process) для нужного поведения. Вот простой пример:460461```python462class CustomAdapter(logging.LoggerAdapter):463 """464 Данный пример адаптера ожидает, что переданный объект, подобный словарю, содержит465 ключ 'connid', значение которого в квадратных скобках добавляется к началу сообщения журнала.466 """467 def process(self, msg, kwargs):468 return '[%s] %s' % (self.extra['connid'], msg), kwargs469```470471который можно использовать так:472473```python474logger = logging.getLogger(__name__)475adapter = CustomAdapter(logger, {'connid': some_conn_id})476```477478Тогда все события, регистрируемые через адаптер, будут содержать значение `some_conn_id`, добавленное в начало сообщений журнала.479480#### Использование объектов, отличных от словарей, для передачи контекстной информации481482Необязательно передавать в [`LoggerAdapter`](https://python-all.ru/2.7/library/logging.html#logging.LoggerAdapter) именно словарь – можно передать экземпляр класса, реализующего `__getitem__` и `__iter__`, чтобы он выглядел как словарь для системы логирования. Это полезно, если нужно генерировать значения динамически (тогда как значения в словаре были бы постоянными).483484### Использование фильтров для добавления контекстной информации485486Вы также можете добавлять контекстную информацию в вывод журнала с помощью определённого пользователем [`Filter`](https://python-all.ru/2.7/library/logging.html#logging.Filter). Экземплярам `Filter` разрешено изменять `LogRecords`, переданный им, включая добавление дополнительных атрибутов, которые затем можно выводить с помощью подходящей форматной строки или, если необходимо, пользовательского [`Formatter`](https://python-all.ru/2.7/library/logging.html#logging.Formatter).487488Например, в веб-приложении обрабатываемый запрос (или, по крайней мере, его интересные части) можно сохранить в потоковой локальной переменной ([`threading.local`](https://python-all.ru/2.7/library/threading.html#threading.local)), а затем из `Filter` получить к ней доступ, чтобы добавить, скажем, информацию из запроса – например, удалённый IP-адрес и имя пользователя – в `LogRecord`, используя имена атрибутов 'ip' и 'user', как в примере с `LoggerAdapter` выше. В этом случае можно использовать ту же форматную строку для получения вывода, аналогичного показанному выше. Вот пример скрипта:489490```python491import logging492from random import choice493494class ContextFilter(logging.Filter):495 """496 Это фильтр, который внедряет контекстную информацию в журнал.497498 Вместо использования реальной контекстной информации в данном примере используются случайные499 данные.500 """501502 USERS = ['jim', 'fred', 'sheila']503 IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']504505 def filter(self, record):506507 record.ip = choice(ContextFilter.IPS)508 record.user = choice(ContextFilter.USERS)509 return True510511if __name__ == '__main__':512 levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)513 logging.basicConfig(level=logging.DEBUG,514 format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')515 a1 = logging.getLogger('a.b.c')516 a2 = logging.getLogger('d.e.f')517518 f = ContextFilter()519 a1.addFilter(f)520 a2.addFilter(f)521 a1.debug('A debug message')522 a1.info('An info message with %s', 'some parameters')523 for x in range(10):524 lvl = choice(levels)525 lvlname = logging.getLevelName(lvl)526 a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')527```528529который при запуске выдаёт примерно следующее:530531```python5322010-09-06 22:38:15,292 a.b.c DEBUG IP: 123.231.231.123 User: fred A debug message5332010-09-06 22:38:15,300 a.b.c INFO IP: 192.168.0.1 User: sheila An info message with some parameters5342010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters5352010-09-06 22:38:15,300 d.e.f ERROR IP: 127.0.0.1 User: jim A message at ERROR level with 2 parameters5362010-09-06 22:38:15,300 d.e.f DEBUG IP: 127.0.0.1 User: sheila A message at DEBUG level with 2 parameters5372010-09-06 22:38:15,300 d.e.f ERROR IP: 123.231.231.123 User: fred A message at ERROR level with 2 parameters5382010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1 User: jim A message at CRITICAL level with 2 parameters5392010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters5402010-09-06 22:38:15,300 d.e.f DEBUG IP: 192.168.0.1 User: jim A message at DEBUG level with 2 parameters5412010-09-06 22:38:15,301 d.e.f ERROR IP: 127.0.0.1 User: sheila A message at ERROR level with 2 parameters5422010-09-06 22:38:15,301 d.e.f DEBUG IP: 123.231.231.123 User: fred A message at DEBUG level with 2 parameters5432010-09-06 22:38:15,301 d.e.f INFO IP: 123.231.231.123 User: fred A message at INFO level with 2 parameters544```545546## Ведение журнала в один файл из нескольких процессов547548Хотя модуль logging является потокобезопасным и запись в один файл из нескольких потоков в одном процессе *поддерживается*, запись в один файл из *нескольких процессов* *не* поддерживается, поскольку в Python нет стандартного способа сериализовать доступ к одному файлу из нескольких процессов. Если нужно вести журнал в один файл из нескольких процессов, один из способов – сделать так, чтобы все процессы записывали данные в [`SocketHandler`](https://python-all.ru/2.7/library/logging.handlers.html#logging.handlers.SocketHandler), а отдельный процесс реализовывал сокет-сервер, который читает из сокета и записывает в файл. (Если хотите, можно выделить один поток в одном из существующих процессов для выполнения этой функции.) [В этом разделе](https://python-all.ru/2.7/howto/logging-cookbook.html#network-logging) подробно описывается данный подход и приводится рабочий приёмник сокета, который можно использовать как отправную точку для адаптации в своих приложениях.549550Если используется недавняя версия Python, включающая модуль [`multiprocessing`](https://python-all.ru/2.7/library/multiprocessing.html#module-multiprocessing), можно написать собственный обработчик, который использует класс [`Lock`](https://python-all.ru/2.7/library/multiprocessing.html#multiprocessing.Lock) из этого модуля для сериализации доступа к файлу из процессов. Существующие [`FileHandler`](https://python-all.ru/2.7/library/logging.handlers.html#logging.FileHandler) и подклассы в настоящее время не используют [`multiprocessing`](https://python-all.ru/2.7/library/multiprocessing.html#module-multiprocessing), хотя в будущем могут. Обратите внимание, что на данный момент модуль [`multiprocessing`](https://python-all.ru/2.7/library/multiprocessing.html#module-multiprocessing) не предоставляет работающую функциональность блокировок на всех платформах (см. [https://bugs.python.org/issue3770](https://python-all.ru/2.7/howto/logging-cookbook.html)).551552## Использование ротации файлов553554Иногда требуется позволить файлу журнала расти до определённого размера, затем открыть новый файл и вести запись в него. Может потребоваться сохранять определённое количество таких файлов, и когда будет создано заданное число файлов, выполнять ротацию, чтобы и количество, и размер файлов оставались в заданных границах. Для такого сценария использования пакет logging предоставляет [`RotatingFileHandler`](https://python-all.ru/2.7/library/logging.handlers.html#logging.handlers.RotatingFileHandler):555556```python557import glob558import logging559import logging.handlers560561LOG_FILENAME = 'logging_rotatingfile_example.out'562563# Настроить конкретный регистратор с нужным уровнем вывода564my_logger = logging.getLogger('MyLogger')565my_logger.setLevel(logging.DEBUG)566567# Добавить обработчик сообщений журнала в регистратор568handler = logging.handlers.RotatingFileHandler(569 LOG_FILENAME, maxBytes=20, backupCount=5)570571my_logger.addHandler(handler)572573# Записать несколько сообщений574for i in range(20):575 my_logger.debug('i = %d' % i)576577# Посмотреть, какие файлы созданы578logfiles = glob.glob('%s*' % LOG_FILENAME)579580for filename in logfiles:581 print(filename)582```583584В результате должно получиться 6 отдельных файлов, каждый из которых содержит часть истории журнала приложения:585586```python587logging_rotatingfile_example.out588logging_rotatingfile_example.out.1589logging_rotatingfile_example.out.2590logging_rotatingfile_example.out.3591logging_rotatingfile_example.out.4592logging_rotatingfile_example.out.5593```594595Самый свежий файл всегда называется `logging_rotatingfile_example.out`, и каждый раз при достижении ограничения по размеру он переименовывается с суффиксом `.1`. Каждый из существующих резервных файлов переименовывается с увеличением суффикса (`.1` становится `.2` и т.д.), а файл `.6` удаляется.596597Разумеется, в этом примере размер файла журнала установлен слишком маленьким для наглядности. В реальности нужно установить *maxBytes* в подходящее значение.598599## Пример конфигурации на основе словаря600601Ниже приведен пример словаря конфигурации логирования – он взят из [документации проекта Django](https://python-all.ru/2.7/howto/logging-cookbook.html). Этот словарь передается в [`dictConfig()`](https://python-all.ru/2.7/library/logging.config.html#logging.config.dictConfig) для применения конфигурации:602603```python604LOGGING = {605 'version': 1,606 'disable_existing_loggers': True,607 'formatters': {608 'verbose': {609 'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'610 },611 'simple': {612 'format': '%(levelname)s %(message)s'613 },614 },615 'filters': {616 'special': {617 '()': 'project.logging.SpecialFilter',618 'foo': 'bar',619 }620 },621 'handlers': {622 'null': {623 'level':'DEBUG',624 'class':'django.utils.log.NullHandler',625 },626 'console':{627 'level':'DEBUG',628 'class':'logging.StreamHandler',629 'formatter': 'simple'630 },631 'mail_admins': {632 'level': 'ERROR',633 'class': 'django.utils.log.AdminEmailHandler',634 'filters': ['special']635 }636 },637 'loggers': {638 'django': {639 'handlers':['null'],640 'propagate': True,641 'level':'INFO',642 },643 'django.request': {644 'handlers': ['mail_admins'],645 'level': 'ERROR',646 'propagate': False,647 },648 'myproject.custom': {649 'handlers': ['console', 'mail_admins'],650 'level': 'INFO',651 'filters': ['special']652 }653 }654}655```656657Для получения дополнительной информации об этой конфигурации можно обратиться к [соответствующему разделу](https://python-all.ru/2.7/howto/logging-cookbook.html) документации Django.658659## Вставка BOM в сообщения, отправляемые в SysLogHandler660661[RFC 5424](https://python-all.ru/2.7/howto/logging-cookbook.html) требует, чтобы Unicode-сообщение отправлялось демону syslog в виде набора байтов следующей структуры: необязательный компонент, состоящий только из ASCII, затем метка порядка байтов (BOM) UTF-8, затем Unicode, закодированный в UTF-8. (См. [соответствующий раздел спецификации](https://python-all.ru/2.7/howto/logging-cookbook.html).)662663В Python 2.6 и 2.7 в [`SysLogHandler`](https://python-all.ru/2.7/library/logging.handlers.html#logging.handlers.SysLogHandler) был добавлен код для вставки BOM в сообщение, но, к сожалению, он был реализован некорректно: BOM появлялся в начале сообщения и не позволял разместить перед ним ни одного чисто ASCII-компонента.664665Поскольку такое поведение ошибочно, некорректный код вставки BOM удаляется из Python 2.7.4 и более поздних версий. Однако он не заменяется, и если требуется создавать сообщения, соответствующие RFC 5424, которые включают BOM, необязательную чисто ASCII-последовательность перед ним и произвольный Unicode после него, закодированный с помощью UTF-8, то необходимо сделать следующее:6666671. Необходимо присоединить экземпляр [`Formatter`](https://python-all.ru/2.7/library/logging.html#logging.Formatter) к экземпляру [`SysLogHandler`](https://python-all.ru/2.7/library/logging.handlers.html#logging.handlers.SysLogHandler), указав строку формата, например:668669 ```python670 u'ASCII section\ufeffUnicode section'671 ```672673 Кодовая точка Unicode `u'\ufeff'` при кодировании в UTF-8 будет закодирована как UTF-8 BOM – байтовая строка `'\xef\xbb\xbf'`.6742. ASCII-часть следует заменить на любые подходящие заполнители, но необходимо следить, чтобы данные, которые появляются там после подстановки, всегда были в ASCII (таким образом, они останутся без изменений после кодирования UTF-8).6753. Unicode-часть следует заменить на любые заполнители; если данные после подстановки содержат символы за пределами диапазона ASCII, это нормально – они будут закодированы в UTF-8.676677Если форматированное сообщение является Unicode, оно *будет* закодировано с использованием UTF-8 с помощью `SysLogHandler`. Если следовать приведенным выше правилам, можно будет создавать сообщения, соответствующие RFC 5424. Если нет, логирование может не жаловаться, но сообщения не будут соответствовать RFC 5424, и ваш системный демон syslog может жаловаться.678679## Реализация структурированного ведения журнала680681Хотя большинство сообщений журнала предназначены для чтения человеком и поэтому не предназначены для машинного разбора, могут возникнуть ситуации, когда требуется выводить сообщения в структурированном формате, *который* может быть разобран программой (без необходимости в сложных регулярных выражениях). Это легко достигается с помощью пакета logging. Существует несколько способов, но ниже приведён простой подход, использующий JSON для сериализации события в машиночитаемом виде.682683```python684import json685import logging686687class StructuredMessage(object):688 def __init__(self, message, **kwargs):689 self.message = message690 self.kwargs = kwargs691692 def __str__(self):693 return '%s >>> %s' % (self.message, json.dumps(self.kwargs))694695_ = StructuredMessage # необязательно, для улучшения читаемости696697logging.basicConfig(level=logging.INFO, format='%(message)s')698logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))699```700701Если запустить приведённый выше скрипт, он выведет:702703```python704message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}705```706707Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.708709Если требуется более специализированная обработка, можно использовать пользовательский кодировщик JSON, как в следующем полном примере:710711```python712from __future__ import unicode_literals713714import json715import logging716717# Следующий фрагмент предназначен для того, чтобы скрипт работал без изменений в версиях 2.x и 3.x.718try:719 unicode720except NameError:721 unicode = str722723class Encoder(json.JSONEncoder):724 def default(self, o):725 if isinstance(o, set):726 return tuple(o)727 elif isinstance(o, unicode):728 return o.encode('unicode_escape').decode('ascii')729 return super(Encoder, self).default(o)730731class StructuredMessage(object):732 def __init__(self, message, **kwargs):733 self.message = message734 self.kwargs = kwargs735736 def __str__(self):737 s = Encoder().encode(self.kwargs)738 return '%s >>> %s' % (self.message, s)739740_ = StructuredMessage # необязательно, для улучшения читаемости741742def main():743 logging.basicConfig(level=logging.INFO, format='%(message)s')744 logging.info(_('message 1', set_value=set([1, 2, 3]), snowman='\u2603'))745746if __name__ == '__main__':747 main()748```749750При запуске приведённого выше скрипта он выведет:751752```python753message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}754```755756Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.757758## Настройка обработчиков с помощью [`dictConfig()`](https://python-all.ru/2.7/library/logging.config.html#logging.config.dictConfig)759760Иногда требуется настроить обработчики логирования особым образом, и при использовании [`dictConfig()`](https://python-all.ru/2.7/library/logging.config.html#logging.config.dictConfig) это можно сделать без создания подклассов. Например, может потребоваться установить владельца файла журнала. В POSIX это легко сделать с помощью [`os.chown()`](https://python-all.ru/2.7/library/os.html#os.chown), но файловые обработчики в стандартной библиотеке не предоставляют встроенной поддержки. Можно настроить создание обработчика с помощью обычной функции, такой как:761762```python763def owned_file_handler(filename, mode='a', encoding=None, owner=None):764 if owner:765 import os, pwd, grp766 # преобразовать имена пользователей и групп в uid и gid767 uid = pwd.getpwnam(owner[0]).pw_uid768 gid = grp.getgrnam(owner[1]).gr_gid769 owner = (uid, gid)770 if not os.path.exists(filename):771 open(filename, 'a').close()772 os.chown(filename, *owner)773 return logging.FileHandler(filename, mode, encoding)774```775776Затем в конфигурации логирования, передаваемой в [`dictConfig()`](https://python-all.ru/2.7/library/logging.config.html#logging.config.dictConfig), можно указать, что обработчик должен быть создан вызовом этой функции:777778```python779LOGGING = {780 'version': 1,781 'disable_existing_loggers': False,782 'formatters': {783 'default': {784 'format': '%(asctime)s %(levelname)s %(name)s %(message)s'785 },786 },787 'handlers': {788 'file':{789 # Значения ниже извлекаются из этого словаря и790 # используются для создания обработчика, установки его уровня и791 # его форматтера.792 '()': owned_file_handler,793 'level':'DEBUG',794 'formatter': 'default',795 # Значения ниже передаются вызываемому объекту-создателю обработчика796 # в качестве именованных аргументов.797 'owner': ['pulse', 'pulse'],798 'filename': 'chowntest.log',799 'mode': 'w',800 'encoding': 'utf-8',801 },802 },803 'root': {804 'handlers': ['file'],805 'level': 'DEBUG',806 },807}808```809810В этом примере для иллюстрации права владения устанавливаются с использованием пользователя и группы `pulse`. Собирая всё вместе в рабочий скрипт, `chowntest.py`:811812```python813import logging, logging.config, os, shutil814815def owned_file_handler(filename, mode='a', encoding=None, owner=None):816 if owner:817 if not os.path.exists(filename):818 open(filename, 'a').close()819 shutil.chown(filename, *owner)820 return logging.FileHandler(filename, mode, encoding)821822LOGGING = {823 'version': 1,824 'disable_existing_loggers': False,825 'formatters': {826 'default': {827 'format': '%(asctime)s %(levelname)s %(name)s %(message)s'828 },829 },830 'handlers': {831 'file':{832 # Значения ниже извлекаются из этого словаря и833 # используются для создания обработчика, установки его уровня и834 # его форматтера.835 '()': owned_file_handler,836 'level':'DEBUG',837 'formatter': 'default',838 # Значения ниже передаются вызываемому объекту-создателю обработчика839 # в качестве именованных аргументов.840 'owner': ['pulse', 'pulse'],841 'filename': 'chowntest.log',842 'mode': 'w',843 'encoding': 'utf-8',844 },845 },846 'root': {847 'handlers': ['file'],848 'level': 'DEBUG',849 },850}851852logging.config.dictConfig(LOGGING)853logger = logging.getLogger('mylogger')854logger.debug('A debug message')855```856857Для запуска, вероятно, потребуется выполнить от имени `root`:858859```console860$ sudo python3.3 chowntest.py861$ cat chowntest.log8622013-11-05 09:34:51,128 DEBUG mylogger A debug message863$ ls -l chowntest.log864-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log865```866867Обратите внимание, что в этом примере используется Python 3.3, потому что в нём появился `shutil.chown()`. Этот подход должен работать с любой версией Python, поддерживающей [`dictConfig()`](https://python-all.ru/2.7/library/logging.config.html#logging.config.dictConfig) – а именно Python 2.7, 3.2 или новее. В версиях до 3.3 потребовалось бы реализовать фактическую смену владельца, например, с помощью [`os.chown()`](https://python-all.ru/2.7/library/os.html#os.chown).868869На практике функция создания обработчика может находиться в служебном модуле где-нибудь в вашем проекте. Вместо строки в конфигурации:870871```python872'()': owned_file_handler,873```874875можно использовать, например:876877```python878'()': 'ext://project.util.owned_file_handler',879```880881где `project.util` можно заменить на фактическое имя пакета, в котором находится функция. В приведённом рабочем скрипте должно сработать использование `'ext://__main__.owned_file_handler'`. Здесь фактический вызываемый объект разрешается с помощью [`dictConfig()`](https://python-all.ru/2.7/library/logging.config.html#logging.config.dictConfig) из спецификации `ext://`.882883Этот пример, надеюсь, также показывает, как можно реализовать другие типы изменений файлов – например, установку определённых битов разрешений POSIX – аналогичным образом, с помощью [`os.chmod()`](https://python-all.ru/2.7/library/os.html#os.chmod).884885Разумеется, этот подход можно распространить и на другие типы обработчиков, помимо [`FileHandler`](https://python-all.ru/2.7/library/logging.handlers.html#logging.FileHandler) – например, на один из вращающихся файловых обработчиков или на совершенно другой тип обработчика.886887## Настройка фильтров с помощью [`dictConfig()`](https://python-all.ru/2.7/library/logging.config.html#logging.config.dictConfig)888889*Можно* настраивать фильтры с помощью [`dictConfig()`](https://python-all.ru/2.7/library/logging.config.html#logging.config.dictConfig), хотя с первого взгляда может быть неочевидно, как это сделать (поэтому и дан этот рецепт). Поскольку [`Filter`](https://python-all.ru/2.7/library/logging.html#logging.Filter) – единственный класс фильтра, включенный в стандартную библиотеку, и вряд ли он удовлетворит многие требования (он присутствует только как базовый класс), вам, как правило, потребуется определить свой собственный подкласс [`Filter`](https://python-all.ru/2.7/library/logging.html#logging.Filter) с переопределенным методом [`filter()`](https://python-all.ru/2.7/library/logging.html#logging.Filter.filter). Для этого укажите ключ `()` в словаре конфигурации для фильтра, указав вызываемый объект, который будет использоваться для создания фильтра (класс – наиболее очевидный вариант, но вы можете предоставить любой вызываемый объект, возвращающий экземпляр [`Filter`](https://python-all.ru/2.7/library/logging.html#logging.Filter)). Вот полный пример:890891```python892import logging893import logging.config894import sys895896class MyFilter(logging.Filter):897 def __init__(self, param=None):898 self.param = param899900 def filter(self, record):901 if self.param is None:902 allow = True903 else:904 allow = self.param not in record.msg905 if allow:906 record.msg = 'changed: ' + record.msg907 return allow908909LOGGING = {910 'version': 1,911 'filters': {912 'myfilter': {913 '()': MyFilter,914 'param': 'noshow',915 }916 },917 'handlers': {918 'console': {919 'class': 'logging.StreamHandler',920 'filters': ['myfilter']921 }922 },923 'root': {924 'level': 'DEBUG',925 'handlers': ['console']926 },927}928929if __name__ == '__main__':930 logging.config.dictConfig(LOGGING)931 logging.debug('hello')932 logging.debug('hello - noshow')933```934935Этот пример показывает, как можно передавать конфигурационные данные вызываемому объекту, который создает экземпляр, в виде именованных параметров. При запуске приведенный выше скрипт выведет:936937```python938changed: hello939```940941что показывает, что фильтр работает в соответствии с настройками.942943Несколько дополнительных моментов, на которые стоит обратить внимание:944945- Если вы не можете сослаться на вызываемый объект напрямую в конфигурации (например, если он находится в другом модуле, и вы не можете импортировать его напрямую в том месте, где находится словарь конфигурации), вы можете использовать форму `ext://...`, как описано в разделе [Доступ к внешним объектам](https://python-all.ru/2.7/library/logging.config.html#logging-config-dict-externalobj). Например, в приведенном выше примере можно было использовать текст `'ext://__main__.MyFilter'` вместо `MyFilter`.946- Помимо фильтров, этот метод также можно использовать для настройки пользовательских обработчиков и форматтеров. Смотрите раздел [Пользовательские объекты](https://python-all.ru/2.7/library/logging.config.html#logging-config-dict-userdef) для получения дополнительной информации о том, как logging поддерживает использование пользовательских объектов в своей конфигурации, а также см. другой рецепт из этой книги рецептов [Настройка обработчиков с помощью dictConfig()](https://python-all.ru/2.7/howto/logging-cookbook.html#custom-handlers) выше.947948## Настраиваемое форматирование исключений949950Могут возникнуть ситуации, когда вы захотите настроить форматирование исключений – для примера, предположим, вы хотите ровно одну строку на каждое событие лога, даже если присутствует информация об исключении. Вы можете сделать это с помощью пользовательского класса форматтера, как показано в следующем примере:951952```python953import logging954955class OneLineExceptionFormatter(logging.Formatter):956 def formatException(self, exc_info):957 """958 Форматировать исключение так, чтобы оно выводилось одной строкой.959 """960 result = super(OneLineExceptionFormatter, self).formatException(exc_info)961 return repr(result) # или форматировать одной строкой по своему усмотрению962963 def format(self, record):964 s = super(OneLineExceptionFormatter, self).format(record)965 if record.exc_text:966 s = s.replace('\n', '') + '|'967 return s968969def configure_logging():970 fh = logging.FileHandler('output.txt', 'w')971 f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',972 '%d/%m/%Y %H:%M:%S')973 fh.setFormatter(f)974 root = logging.getLogger()975 root.setLevel(logging.DEBUG)976 root.addHandler(fh)977978def main():979 configure_logging()980 logging.info('Sample message')981 try:982 x = 1 / 0983 except ZeroDivisionError as e:984 logging.exception('ZeroDivisionError: %s', e)985986if __name__ == '__main__':987 main()988```989990При запуске это создает файл ровно с двумя строками:991992```python99328/01/2015 07:21:23|INFO|Sample message|99428/01/2015 07:21:23|ERROR|ZeroDivisionError: integer division or modulo by zero|'Traceback (most recent call last):\n File "logtest7.py", line 30, in main\n x = 1 / 0\nZeroDivisionError: integer division or modulo by zero'|995```996997Хотя описанный выше подход упрощен, он показывает путь к тому, как можно форматировать информацию об исключениях по своему вкусу. Модуль [`traceback`](https://python-all.ru/2.7/library/traceback.html#module-traceback) может быть полезен для более специализированных нужд.998999## Озвучивание сообщений лога10001001Могут быть ситуации, когда желательно выводить сообщения лога в звуковом, а не визуальном формате. Это легко сделать, если в вашей системе доступна функция преобразования текста в речь (TTS), даже если у нее нет привязки к Python. Большинство TTS-систем имеют программу командной строки, которую можно запустить, и ее можно вызвать из обработчика с помощью [`subprocess`](https://python-all.ru/2.7/library/subprocess.html#module-subprocess). Здесь предполагается, что программы командной строки TTS не будут ожидать взаимодействия с пользователем или занимать много времени для завершения, и что частота сообщений лога не будет настолько высокой, чтобы перегружать пользователя сообщениями, и что допустимо проговаривать сообщения по одному, а не одновременно. В приведенном ниже примере реализации ожидается, пока одно сообщение не будет произнесено, прежде чем обрабатывать следующее, и это может заставить другие обработчики ждать. Вот короткий пример, демонстрирующий подход, который предполагает, что доступен TTS-пакет `espeak`:10021003```python1004import logging1005import subprocess1006import sys10071008class TTSHandler(logging.Handler):1009 def emit(self, record):1010 msg = self.format(record)1011 # Говорить медленно женским английским голосом.1012 cmd = ['espeak', '-s150', '-ven+f3', msg]1013 p = subprocess.Popen(cmd, stdout=subprocess.PIPE,1014 stderr=subprocess.STDOUT)1015 # дождаться завершения программы1016 p.communicate()10171018def configure_logging():1019 h = TTSHandler()1020 root = logging.getLogger()1021 root.addHandler(h)1022 # стандартный форматтер просто возвращает сообщение1023 root.setLevel(logging.DEBUG)10241025def main():1026 logging.info('Hello')1027 logging.debug('Goodbye')10281029if __name__ == '__main__':1030 configure_logging()1031 sys.exit(main())1032```10331034При запуске этот скрипт должен сказать «Hello», а затем «Goodbye» женским голосом.10351036Описанный выше подход, конечно, можно адаптировать для других TTS-систем и даже для других систем, которые могут обрабатывать сообщения через внешние программы, запускаемые из командной строки.10371038## Буферизация сообщений лога и условный вывод10391040Могут возникнуть ситуации, когда вы хотите записывать сообщения во временную область и выводить их только при наступлении определенного условия. Например, вы можете начать запись отладочных событий в функции, и если функция завершится без ошибок, вы не захотите засорять лог собранной отладочной информацией, но если возникнет ошибка, вы захотите вывести всю отладочную информацию вместе с ошибкой.10411042Вот пример, показывающий, как это можно сделать с помощью декоратора для ваших функций, где вы хотите, чтобы логирование вело себя таким образом. Он использует [`logging.handlers.MemoryHandler`](https://python-all.ru/2.7/library/logging.handlers.html#logging.handlers.MemoryHandler), который позволяет буферизовать зарегистрированные события до наступления некоторого условия, после чего буферизованные события `flushed` – передаются другому обработчику (обработчику `target`) для обработки. По умолчанию `MemoryHandler` сбрасывается, когда его буфер заполняется или встречается событие, уровень которого больше или равен указанному порогу. Вы можете использовать этот рецепт с более специализированным подклассом `MemoryHandler`, если хотите настроить поведение сброса.10431044Пример скрипта содержит простую функцию `foo`, которая просто перебирает все уровни логирования, записывая в `sys.stderr` информацию о том, какой уровень будет использоваться, а затем регистрирует сообщение на этом уровне. Вы можете передать параметр в `foo`, который, если равен true, будет регистрировать на уровнях ERROR и CRITICAL – в противном случае он регистрирует только на уровнях DEBUG, INFO и WARNING.10451046Скрипт просто декорирует `foo` декоратором, который выполняет условное логирование по необходимости. Декоратор принимает логгер в качестве параметра и подключает обработчик с буферизацией в памяти на время вызова декорируемой функции. Декоратор можно дополнительно настроить, указав целевой обработчик, уровень, при котором следует сбрасывать буфер, и ёмкость буфера. По умолчанию используются [`StreamHandler`](https://python-all.ru/2.7/library/logging.handlers.html#logging.StreamHandler), который пишет в `sys.stderr`, `logging.ERROR` и `100` соответственно.10471048Вот скрипт:10491050```python1051import logging1052from logging.handlers import MemoryHandler1053import sys10541055logger = logging.getLogger(__name__)1056logger.addHandler(logging.NullHandler())10571058def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):1059 if target_handler is None:1060 target_handler = logging.StreamHandler()1061 if flush_level is None:1062 flush_level = logging.ERROR1063 if capacity is None:1064 capacity = 1001065 handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)10661067 def decorator(fn):1068 def wrapper(*args, **kwargs):1069 logger.addHandler(handler)1070 try:1071 return fn(*args, **kwargs)1072 except Exception:1073 logger.exception('call failed')1074 raise1075 finally:1076 super(MemoryHandler, handler).flush()1077 logger.removeHandler(handler)1078 return wrapper10791080 return decorator10811082def write_line(s):1083 sys.stderr.write('%s\n' % s)10841085def foo(fail=False):1086 write_line('about to log at DEBUG ...')1087 logger.debug('Actually logged at DEBUG')1088 write_line('about to log at INFO ...')1089 logger.info('Actually logged at INFO')1090 write_line('about to log at WARNING ...')1091 logger.warning('Actually logged at WARNING')1092 if fail:1093 write_line('about to log at ERROR ...')1094 logger.error('Actually logged at ERROR')1095 write_line('about to log at CRITICAL ...')1096 logger.critical('Actually logged at CRITICAL')1097 return fail10981099decorated_foo = log_if_errors(logger)(foo)11001101if __name__ == '__main__':1102 logger.setLevel(logging.DEBUG)1103 write_line('Calling undecorated foo with False')1104 assert not foo(False)1105 write_line('Calling undecorated foo with True')1106 assert foo(True)1107 write_line('Calling decorated foo with False')1108 assert not decorated_foo(False)1109 write_line('Calling decorated foo with True')1110 assert decorated_foo(True)1111```11121113При запуске этого скрипта отобразится следующий вывод:11141115```python1116Calling undecorated foo with False1117about to log at DEBUG ...1118about to log at INFO ...1119about to log at WARNING ...1120Calling undecorated foo with True1121about to log at DEBUG ...1122about to log at INFO ...1123about to log at WARNING ...1124about to log at ERROR ...1125about to log at CRITICAL ...1126Calling decorated foo with False1127about to log at DEBUG ...1128about to log at INFO ...1129about to log at WARNING ...1130Calling decorated foo with True1131about to log at DEBUG ...1132about to log at INFO ...1133about to log at WARNING ...1134about to log at ERROR ...1135Actually logged at DEBUG1136Actually logged at INFO1137Actually logged at WARNING1138Actually logged at ERROR1139about to log at CRITICAL ...1140Actually logged at CRITICAL1141```11421143Как видно, фактический вывод журнала происходит только при регистрации события, уровень которого ERROR или выше, но в этом случае также регистрируются все предыдущие события с более низкими уровнями.11441145Конечно, можно использовать обычные средства декорирования:11461147```python1148@log_if_errors(logger)1149def foo(fail=False):1150 ...1151```11521153## Форматирование времени с использованием UTC (GMT) через конфигурацию11541155Иногда требуется форматировать время по UTC, что можно сделать с помощью класса такого как *UTCFormatter*, показанного ниже:11561157```python1158import logging1159import time11601161class UTCFormatter(logging.Formatter):1162 converter = time.gmtime1163```11641165и затем можно использовать `UTCFormatter` в своём коде вместо [`Formatter`](https://python-all.ru/2.7/library/logging.html#logging.Formatter). Если требуется сделать это через конфигурацию, можно воспользоваться API [`dictConfig()`](https://python-all.ru/2.7/library/logging.config.html#logging.config.dictConfig), как показано в следующем полном примере:11661167```python1168import logging1169import logging.config1170import time11711172class UTCFormatter(logging.Formatter):1173 converter = time.gmtime11741175LOGGING = {1176 'version': 1,1177 'disable_existing_loggers': False,1178 'formatters': {1179 'utc': {1180 '()': UTCFormatter,1181 'format': '%(asctime)s %(message)s',1182 },1183 'local': {1184 'format': '%(asctime)s %(message)s',1185 }1186 },1187 'handlers': {1188 'console1': {1189 'class': 'logging.StreamHandler',1190 'formatter': 'utc',1191 },1192 'console2': {1193 'class': 'logging.StreamHandler',1194 'formatter': 'local',1195 },1196 },1197 'root': {1198 'handlers': ['console1', 'console2'],1199 }1200}12011202if __name__ == '__main__':1203 logging.config.dictConfig(LOGGING)1204 logging.warning('The local time is %s', time.asctime())1205```12061207При запуске этого скрипта он должен вывести примерно следующее:12081209```python12102015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 201512112015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 20151212```12131214показывая, как время форматируется как в местном времени, так и в UTC, по одному для каждого обработчика.12151216## Использование контекстного менеджера для выборочного журналирования12171218Бывают ситуации, когда полезно временно изменить конфигурацию журналирования, а затем вернуть её обратно после выполнения каких-то действий. Для этого контекстный менеджер – самый очевидный способ сохранить и восстановить контекст журналирования. Вот простой пример такого контекстного менеджера, который позволяет по желанию изменить уровень журналирования и добавить обработчик журнала исключительно в области действия контекстного менеджера:12191220```python1221import logging1222import sys12231224class LoggingContext(object):1225 def __init__(self, logger, level=None, handler=None, close=True):1226 self.logger = logger1227 self.level = level1228 self.handler = handler1229 self.close = close12301231 def __enter__(self):1232 if self.level is not None:1233 self.old_level = self.logger.level1234 self.logger.setLevel(self.level)1235 if self.handler:1236 self.logger.addHandler(self.handler)12371238 def __exit__(self, et, ev, tb):1239 if self.level is not None:1240 self.logger.setLevel(self.old_level)1241 if self.handler:1242 self.logger.removeHandler(self.handler)1243 if self.handler and self.close:1244 self.handler.close()1245 # неявный возврат None => не подавлять исключения1246```12471248Если указать значение уровня, уровень регистратора устанавливается на это значение в области действия блока with, охватываемого контекстным менеджером. Если указать обработчик, он добавляется к регистратору при входе в блок и удаляется при выходе из блока. Также можно попросить менеджер закрыть обработчик при выходе из блока – это можно сделать, если обработчик больше не нужен.12491250Чтобы проиллюстрировать, как это работает, можно добавить следующий блок кода к предыдущему:12511252```python1253if __name__ == '__main__':1254 logger = logging.getLogger('foo')1255 logger.addHandler(logging.StreamHandler())1256 logger.setLevel(logging.INFO)1257 logger.info('1. This should appear just once on stderr.')1258 logger.debug('2. This should not appear.')1259 with LoggingContext(logger, level=logging.DEBUG):1260 logger.debug('3. This should appear once on stderr.')1261 logger.debug('4. This should not appear.')1262 h = logging.StreamHandler(sys.stdout)1263 with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):1264 logger.debug('5. This should appear twice - once on stderr and once on stdout.')1265 logger.info('6. This should appear just once on stderr.')1266 logger.debug('7. This should not appear.')1267```12681269Изначально устанавливаем уровень регистратора равным `INFO`, поэтому сообщение №1 отображается, а сообщение №2 – нет. Затем временно меняем уровень на `DEBUG` в следующем блоке `with`, и сообщение №3 отображается. После выхода из блока уровень регистратора восстанавливается до `INFO`, поэтому сообщение №4 не отображается. В следующем блоке `with` снова устанавливаем уровень `DEBUG`, но также добавляем обработчик, записывающий в `sys.stdout`. Таким образом, сообщение №5 отображается дважды на консоли (один раз через `stderr` и один раз через `stdout`). После завершения оператора `with` состояние возвращается к исходному, поэтому сообщение №6 отображается (как сообщение №1), а сообщение №7 – нет (как сообщение №2).12701271Если запустить полученный скрипт, результат будет следующим:12721273```console1274$ python logctx.py12751. This should appear just once on stderr.12763. This should appear once on stderr.12775. This should appear twice - once on stderr and once on stdout.12785. This should appear twice - once on stderr and once on stdout.12796. This should appear just once on stderr.1280```12811282Если запустить его снова, но перенаправить `stderr` в `/dev/null`, мы увидим следующее, что является единственным сообщением, записанным в `stdout`:12831284```console1285$ python logctx.py 2>/dev/null12865. This should appear twice - once on stderr and once on stdout.1287```12881289Ещё раз, но перенаправляя `stdout` в `/dev/null`, получаем:12901291```console1292$ python logctx.py >/dev/null12931. This should appear just once on stderr.12943. This should appear once on stderr.12955. This should appear twice - once on stderr and once on stdout.12966. This should appear just once on stderr.1297```12981299В этом случае сообщение №5, выведенное в `stdout`, не отображается, как и ожидалось.13001301Разумеется, описанный подход можно обобщить, например, для временного подключения фильтров журналирования. Обратите внимание, что приведённый выше код работает как в Python 2, так и в Python 3.1302