Содержание страницы

Сборник рецептов по логированию¶Logging Cookbook

Автор: Vinay Sajip <vinay_sajip at red-dove dot com>

На этой странице представлен ряд рецептов, связанных с логированием, которые оказались полезными на практике.

Использование логирования в нескольких модулях¶Using logging in multiple modules

Многократные вызовы logging.getLogger('someLogger') возвращают ссылку на один и тот же объект логгера. Это верно не только в пределах одного модуля, но и для разных модулей, если они выполняются в одном процессе интерпретатора Python. Кроме того, код приложения может определить и настроить родительский логгер в одном модуле, а затем создать (но не настраивать) дочерний логгер в другом модуле – все вызовы логгера у дочернего будут передаваться родительскому. Вот главный модуль:

import logging
import auxiliary_module

# создать логгер с именем 'spam_application'
logger = logging.getLogger('spam_application')
logger.setLevel(logging.DEBUG)
# создать файловый обработчик, записывающий даже отладочные сообщения
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# создать консольный обработчик с более высоким уровнем логирования
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
# создать форматтер и добавить его к обработчикам
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)
# добавить обработчики к логгеру
logger.addHandler(fh)
logger.addHandler(ch)

logger.info('creating an instance of auxiliary_module.Auxiliary')
a = auxiliary_module.Auxiliary()
logger.info('created an instance of auxiliary_module.Auxiliary')
logger.info('calling auxiliary_module.Auxiliary.do_something')
a.do_something()
logger.info('finished auxiliary_module.Auxiliary.do_something')
logger.info('calling auxiliary_module.some_function()')
auxiliary_module.some_function()
logger.info('done with auxiliary_module.some_function()')

А вот вспомогательный модуль:

import logging

# создать логгер
module_logger = logging.getLogger('spam_application.auxiliary')

class Auxiliary:
    def __init__(self):
        self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
        self.logger.info('creating an instance of Auxiliary')

    def do_something(self):
        self.logger.info('doing something')
        a = 1 + 1
        self.logger.info('done doing something')

def some_function():
    module_logger.info('received a call to "some_function"')

Вывод выглядит так:

2005-03-23 23:47:11,663 - spam_application - INFO -
   creating an instance of auxiliary_module.Auxiliary
2005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -
   creating an instance of Auxiliary
2005-03-23 23:47:11,665 - spam_application - INFO -
   created an instance of auxiliary_module.Auxiliary
2005-03-23 23:47:11,668 - spam_application - INFO -
   calling auxiliary_module.Auxiliary.do_something
2005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -
   doing something
2005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -
   done doing something
2005-03-23 23:47:11,670 - spam_application - INFO -
   finished auxiliary_module.Auxiliary.do_something
2005-03-23 23:47:11,671 - spam_application - INFO -
   calling auxiliary_module.some_function()
2005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -
   received a call to 'some_function'
2005-03-23 23:47:11,673 - spam_application - INFO -
   done with auxiliary_module.some_function()

Журналирование из нескольких потоков¶Logging from multiple threads

Логирование из нескольких потоков не требует особых усилий. Следующий пример показывает логирование из главного (начального) потока и другого потока:

import logging
import threading
import time

def worker(arg):
    while not arg['stop']:
        logging.debug('Hi from myfunc')
        time.sleep(0.5)

def main():
    logging.basicConfig(level=logging.DEBUG, format='%(relativeCreated)6d %(threadName)s %(message)s')
    info = {'stop': False}
    thread = threading.Thread(target=worker, args=(info,))
    thread.start()
    while True:
        try:
            logging.debug('Hello from main')
            time.sleep(0.75)
        except KeyboardInterrupt:
            info['stop'] = True
            break
    thread.join()

if __name__ == '__main__':
    main()

При запуске скрипт должен вывести что-то вроде следующего:

Thread-1 Hi from myfunc
MainThread Hello from main
Thread-1 Hi from myfunc
MainThread Hello from main
Thread-1 Hi from myfunc
MainThread Hello from main
Thread-1 Hi from myfunc
Thread-1 Hi from myfunc
MainThread Hello from main
Thread-1 Hi from myfunc
MainThread Hello from main
Thread-1 Hi from myfunc
Thread-1 Hi from myfunc
MainThread Hello from main
Thread-1 Hi from myfunc
MainThread Hello from main
Thread-1 Hi from myfunc

Как и следовало ожидать, вывод журнала перемежается. Разумеется, такой подход работает и для большего количества потоков, чем показано здесь.

Несколько обработчиков и форматировщиков¶Multiple handlers and formatters

Логгеры – это обычные объекты Python. У метода addHandler() нет минимального или максимального ограничения на количество добавляемых обработчиков. Иногда приложению полезно записывать все сообщения всех уровней в текстовый файл и одновременно выводить ошибки и сообщения выше в консоль. Чтобы это настроить, достаточно сконфигурировать нужные обработчики. Вызовы журналирования в коде приложения останутся без изменений. Вот небольшая модификация предыдущего простого примера конфигурации на основе модуля:

import logging

logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)
# создать файловый обработчик, записывающий даже отладочные сообщения
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# создать консольный обработчик с более высоким уровнем логирования
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
# создать форматтер и добавить его к обработчикам
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(formatter)
fh.setFormatter(formatter)
# добавить обработчики в логгер
logger.addHandler(ch)
logger.addHandler(fh)

# код 'приложения'
logger.debug('debug message')
logger.info('info message')
logger.warn('warn message')
logger.error('error message')
logger.critical('critical message')

Обратите внимание, что «прикладной» код не заботится о нескольких обработчиках. Единственное, что изменилось – добавление и настройка нового обработчика с именем fh.

Возможность создавать новые обработчики с фильтрами более высокого или низкого уровня очень полезна при написании и тестировании приложения. Вместо множества операторов print для отладки используйте logger.debug: в отличие от операторов print, которые позже придётся удалять или закомментировать, вызовы logger.debug могут оставаться в исходном коде и оставаться неактивными, пока они снова не понадобятся. В тот момент единственное, что нужно изменить – уровень журналирования логгера и/или обработчика на DEBUG.

Журналирование в несколько мест назначения¶Logging to multiple destinations

Допустим, вы хотите вести журнал в консоль и файл с разными форматами сообщений и в разных ситуациях. Предположим, вы хотите записывать сообщения уровня DEBUG и выше в файл, а сообщения уровня INFO и выше – в консоль. Также предположим, что файл должен содержать временные метки, а консольные сообщения – нет. Вот как это можно сделать:

import logging

# настроить логирование в файл – подробнее см. предыдущий раздел
logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
                    datefmt='%m-%d %H:%M',
                    filename='/temp/myapp.log',
                    filemode='w')
# Определяет обработчик, который записывает сообщения уровня INFO и выше в sys.stderr.
console = logging.StreamHandler()
console.setLevel(logging.INFO)
# Задает формат, упрощенный для вывода в консоль.
formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
# Указывает обработчику использовать этот формат.
console.setFormatter(formatter)
# Добавляет обработчик в корневой логгер.
logging.getLogger('').addHandler(console)

# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...
logging.info('Jackdaws love my big sphinx of quartz.')

# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:
# приложение:

logger1 = logging.getLogger('myapp.area1')
logger2 = logging.getLogger('myapp.area2')

logger1.debug('Quick zephyrs blow, vexing daft Jim.')
logger1.info('How quickly daft jumping zebras vex.')
logger2.warning('Jail zesty vixen who grabbed pay from quack.')
logger2.error('The five boxing wizards jump quickly.')

При запуске на консоли вы увидите

root        : INFO     Jackdaws love my big sphinx of quartz.
myapp.area1 : INFO     How quickly daft jumping zebras vex.
myapp.area2 : WARNING  Jail zesty vixen who grabbed pay from quack.
myapp.area2 : ERROR    The five boxing wizards jump quickly.

а в файле увидите примерно такое

10-22 22:19 root         INFO     Jackdaws love my big sphinx of quartz.
10-22 22:19 myapp.area1  DEBUG    Quick zephyrs blow, vexing daft Jim.
10-22 22:19 myapp.area1  INFO     How quickly daft jumping zebras vex.
10-22 22:19 myapp.area2  WARNING  Jail zesty vixen who grabbed pay from quack.
10-22 22:19 myapp.area2  ERROR    The five boxing wizards jump quickly.

Как видите, сообщение DEBUG отображается только в файле. Остальные сообщения отправляются в оба места назначения.

В этом примере используются консольный и файловый обработчики, но вы можете использовать любое количество и любое сочетание обработчиков по своему выбору.

Пример сервера конфигурации¶Configuration server example

Вот пример модуля, использующего сервер конфигурации журналирования:

import logging
import logging.config
import time
import os

# Прочитать начальный конфигурационный файл.
logging.config.fileConfig('logging.conf')

# Создать и запустить слушатель на порту 9999.
t = logging.config.listen(9999)
t.start()

logger = logging.getLogger('simpleExample')

try:
    # Прокрутить вызовы логирования, чтобы увидеть разницу.
    # Создавать новые конфигурации до нажатия Ctrl+C.
    while True:
        logger.debug('debug message')
        logger.info('info message')
        logger.warn('warn message')
        logger.error('error message')
        logger.critical('critical message')
        time.sleep(5)
except KeyboardInterrupt:
    # очистка
    logging.config.stopListening()
    t.join()

А вот скрипт, который принимает имя файла и отправляет этот файл на сервер, предварив его двоично-закодированной длиной, в качестве новой конфигурации журналирования:

#!/usr/bin/env python
import socket, sys, struct

with open(sys.argv[1], 'rb') as f:
    data_to_send = f.read()

HOST = 'localhost'
PORT = 9999
s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
print('connecting...')
s.connect((HOST, PORT))
print('sending config...')
s.send(struct.pack('>L', len(data_to_send)))
s.send(data_to_send)
s.close()
print('complete')

Отправка и получение событий логирования по сети¶Sending and receiving logging events across a network

Допустим, вы хотите отправлять события логирования по сети и обрабатывать их на принимающей стороне. Простой способ – подключить экземпляр SocketHandler к корневому логгеру на отправляющей стороне:

import logging, logging.handlers

rootLogger = logging.getLogger('')
rootLogger.setLevel(logging.DEBUG)
socketHandler = logging.handlers.SocketHandler('localhost',
                    logging.handlers.DEFAULT_TCP_LOGGING_PORT)
# Не нужно использовать форматтер, так как сокет-обработчик отправляет событие в виде неформатированного пикла.
# неформатированный pickle
rootLogger.addHandler(socketHandler)

# Теперь можно выполнять запись в корневой логгер или любой другой. Сначала корневой...
logging.info('Jackdaws love my big sphinx of quartz.')

# Теперь определите несколько других логгеров, которые могут представлять разные части приложения:
# приложение:

logger1 = logging.getLogger('myapp.area1')
logger2 = logging.getLogger('myapp.area2')

logger1.debug('Quick zephyrs blow, vexing daft Jim.')
logger1.info('How quickly daft jumping zebras vex.')
logger2.warning('Jail zesty vixen who grabbed pay from quack.')
logger2.error('The five boxing wizards jump quickly.')

На принимающей стороне можно настроить приёмник с помощью модуля SocketServer. Вот простой работающий пример:

import pickle
import logging
import logging.handlers
import SocketServer
import struct


class LogRecordStreamHandler(SocketServer.StreamRequestHandler):
    """Обработчик для потокового запроса логирования.

    Это по сути записывает запись, используя ту политику логирования, которая настроена локально.
    настроено локально.
    """

    def handle(self):
        """
        Обрабатывает несколько запросов – каждый ожидается в формате: 4-байтовая длина, затем запись журнала в формате пикл.
        Записывает запись в соответствии с политикой, настроенной локально.
        согласно локально настроенной политике.
        """
        while True:
            chunk = self.connection.recv(4)
            if len(chunk) < 4:
                break
            slen = struct.unpack('>L', chunk)[0]
            chunk = self.connection.recv(slen)
            while len(chunk) < slen:
                chunk = chunk + self.connection.recv(slen - len(chunk))
            obj = self.unPickle(chunk)
            record = logging.makeLogRecord(obj)
            self.handleLogRecord(record)

    def unPickle(self, data):
        return pickle.loads(data)

    def handleLogRecord(self, record):
        # Если указано имя, используется именованный логгер, а не тот, что
        # подразумевается записью.
        if self.server.logname is not None:
            name = self.server.logname
        else:
            name = record.name
        logger = logging.getLogger(name)
        # Примечание: КАЖДАЯ запись попадает в журнал. Это связано с тем, что Logger.handle
        # обычно вызывается ПОСЛЕ фильтрации на уровне регистратора. Если требуется
        # выполнять фильтрацию, делайте это на стороне клиента, чтобы не тратить
        # циклы процессора и сетевую пропускную способность!
        logger.handle(record)

class LogRecordSocketReceiver(SocketServer.ThreadingTCPServer):
    """
    Простой приёмник журнала на основе TCP-сокетов, подходящий для тестирования.
    """

    allow_reuse_address = 1

    def __init__(self, host='localhost',
                 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
                 handler=LogRecordStreamHandler):
        SocketServer.ThreadingTCPServer.__init__(self, (host, port), handler)
        self.abort = 0
        self.timeout = 1
        self.logname = None

    def serve_until_stopped(self):
        import select
        abort = 0
        while not abort:
            rd, wr, ex = select.select([self.socket.fileno()],
                                       [], [],
                                       self.timeout)
            if rd:
                self.handle_request()
            abort = self.abort

def main():
    logging.basicConfig(
        format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')
    tcpserver = LogRecordSocketReceiver()
    print('About to start TCP server...')
    tcpserver.serve_until_stopped()

if __name__ == '__main__':
    main()

Сначала запустите сервер, затем клиент. На стороне клиента в консоль ничего не выводится; на стороне сервера вы должны увидеть что-то вроде:

About to start TCP server...
root            INFO     Jackdaws love my big sphinx of quartz.
myapp.area1     DEBUG    Quick zephyrs blow, vexing daft Jim.
myapp.area1     INFO     How quickly daft jumping zebras vex.
myapp.area2     WARNING  Jail zesty vixen who grabbed pay from quack.
myapp.area2     ERROR    The five boxing wizards jump quickly.

Обратите внимание, что в некоторых сценариях существуют проблемы безопасности с pickle. Если они вас затрагивают, вы можете использовать альтернативную схему сериализации, переопределив метод makePickle() и реализовав свою альтернативу там, а также адаптировав вышеприведённый скрипт для использования вашей альтернативной сериализации.

Добавление контекстной информации в вывод журнала¶Adding contextual information to your logging output

Иногда требуется, чтобы вывод журнала содержал контекстную информацию в дополнение к параметрам, переданным в вызове логирования. Например, в сетевом приложении может быть желательно записывать в журнал информацию, специфичную для клиента (например, имя пользователя удалённого клиента или IP-адрес). Хотя для этого можно использовать параметр extra, не всегда удобно передавать информацию таким образом. Может возникнуть соблазн создавать экземпляры Logger для каждого соединения, но это плохая идея, поскольку такие экземпляры не собираются сборщиком мусора. Хотя на практике это не проблема, когда количество экземпляров Logger зависит от уровня детализации, используемого при логировании приложения, управление ими может стать сложным, если количество экземпляров Logger станет фактически неограниченным.

Использование LoggerAdapter для добавления контекстной информации¶Using LoggerAdapters to impart contextual information

Простой способ передавать контекстную информацию для вывода вместе с информацией о событиях логирования – использовать класс LoggerAdapter. Этот класс спроектирован так, чтобы выглядеть как Logger, что позволяет вызывать debug(), info(), warning(), error(), exception(), critical() и log(). Эти методы имеют те же сигнатуры, что и их аналоги в Logger, поэтому экземпляры обоих типов можно использовать взаимозаменяемо.

При создании экземпляра LoggerAdapter вы передаёте ему экземпляр Logger и объект, подобный словарю, содержащий вашу контекстную информацию. Когда вы вызываете один из методов логирования на экземпляре LoggerAdapter, он делегирует вызов базовому экземпляру Logger, переданному в конструктор, и организует передачу контекстной информации в этом делегированном вызове. Вот фрагмент кода LoggerAdapter:

def debug(self, msg, *args, **kwargs):
    """
    Передаёт вызов отладки нижележащему регистратору после добавления
    контекстной информации из данного экземпляра адаптера.
    """
    msg, kwargs = self.process(msg, kwargs)
    self.logger.debug(msg, *args, **kwargs)

Метод process() класса LoggerAdapter – это то место, где контекстная информация добавляется в вывод журнала. Ему передаются сообщение и именованные аргументы вызова логирования, а он возвращает (потенциально) изменённые версии для использования в вызове базового регистратора. В реализации по умолчанию этот метод оставляет сообщение без изменений, но вставляет ключ 'extra' в именованные аргументы, значением которого является объект, подобный словарю, переданный конструктору. Конечно, если вы передали именованный аргумент 'extra' в вызове адаптера, он будет молча перезаписан.

Преимущество использования 'extra' в том, что значения из объекта, подобного словарю, сливаются в __dict__ экземпляра LogRecord, что позволяет использовать настроенные строки с экземплярами Formatter, которые знают о ключах этого объекта. Если вам нужен другой метод, например, добавить контекстную информацию в начало или конец строки сообщения, достаточно создать подкласс LoggerAdapter и переопределить process() для нужного поведения. Вот простой пример:

class CustomAdapter(logging.LoggerAdapter):
    """
    Данный пример адаптера ожидает, что переданный объект, подобный словарю, содержит
    ключ 'connid', значение которого в квадратных скобках добавляется к началу сообщения журнала.
    """
    def process(self, msg, kwargs):
        return '[%s] %s' % (self.extra['connid'], msg), kwargs

который можно использовать так:

logger = logging.getLogger(__name__)
adapter = CustomAdapter(logger, {'connid': some_conn_id})

Тогда все события, регистрируемые через адаптер, будут содержать значение some_conn_id, добавленное в начало сообщений журнала.

Использование объектов, отличных от словарей, для передачи контекстной информации¶Using objects other than dicts to pass contextual information

Необязательно передавать в LoggerAdapter именно словарь – можно передать экземпляр класса, реализующего __getitem__ и __iter__, чтобы он выглядел как словарь для системы логирования. Это полезно, если нужно генерировать значения динамически (тогда как значения в словаре были бы постоянными).

Использование фильтров для добавления контекстной информации¶Using Filters to impart contextual information

Вы также можете добавлять контекстную информацию в вывод журнала с помощью определённого пользователем Filter. Экземплярам Filter разрешено изменять LogRecords, переданный им, включая добавление дополнительных атрибутов, которые затем можно выводить с помощью подходящей форматной строки или, если необходимо, пользовательского Formatter.

Например, в веб-приложении обрабатываемый запрос (или, по крайней мере, его интересные части) можно сохранить в потоковой локальной переменной (threading.local), а затем из Filter получить к ней доступ, чтобы добавить, скажем, информацию из запроса – например, удалённый IP-адрес и имя пользователя – в LogRecord, используя имена атрибутов 'ip' и 'user', как в примере с LoggerAdapter выше. В этом случае можно использовать ту же форматную строку для получения вывода, аналогичного показанному выше. Вот пример скрипта:

import logging
from random import choice

class ContextFilter(logging.Filter):
    """
    Это фильтр, который внедряет контекстную информацию в журнал.

    Вместо использования реальной контекстной информации в данном примере используются случайные
    данные.
    """

    USERS = ['jim', 'fred', 'sheila']
    IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']

    def filter(self, record):

        record.ip = choice(ContextFilter.IPS)
        record.user = choice(ContextFilter.USERS)
        return True

if __name__ == '__main__':
    levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)
    logging.basicConfig(level=logging.DEBUG,
                        format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')
    a1 = logging.getLogger('a.b.c')
    a2 = logging.getLogger('d.e.f')

    f = ContextFilter()
    a1.addFilter(f)
    a2.addFilter(f)
    a1.debug('A debug message')
    a1.info('An info message with %s', 'some parameters')
    for x in range(10):
        lvl = choice(levels)
        lvlname = logging.getLevelName(lvl)
        a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')

который при запуске выдаёт примерно следующее:

2010-09-06 22:38:15,292 a.b.c DEBUG    IP: 123.231.231.123 User: fred     A debug message
2010-09-06 22:38:15,300 a.b.c INFO     IP: 192.168.0.1     User: sheila   An info message with some parameters
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters
2010-09-06 22:38:15,300 d.e.f ERROR    IP: 127.0.0.1       User: jim      A message at ERROR level with 2 parameters
2010-09-06 22:38:15,300 d.e.f DEBUG    IP: 127.0.0.1       User: sheila   A message at DEBUG level with 2 parameters
2010-09-06 22:38:15,300 d.e.f ERROR    IP: 123.231.231.123 User: fred     A message at ERROR level with 2 parameters
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1     User: jim      A message at CRITICAL level with 2 parameters
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters
2010-09-06 22:38:15,300 d.e.f DEBUG    IP: 192.168.0.1     User: jim      A message at DEBUG level with 2 parameters
2010-09-06 22:38:15,301 d.e.f ERROR    IP: 127.0.0.1       User: sheila   A message at ERROR level with 2 parameters
2010-09-06 22:38:15,301 d.e.f DEBUG    IP: 123.231.231.123 User: fred     A message at DEBUG level with 2 parameters
2010-09-06 22:38:15,301 d.e.f INFO     IP: 123.231.231.123 User: fred     A message at INFO level with 2 parameters

Ведение журнала в один файл из нескольких процессов¶Logging to a single file from multiple processes

Хотя модуль logging является потокобезопасным и запись в один файл из нескольких потоков в одном процессе поддерживается, запись в один файл из нескольких процессов не поддерживается, поскольку в Python нет стандартного способа сериализовать доступ к одному файлу из нескольких процессов. Если нужно вести журнал в один файл из нескольких процессов, один из способов – сделать так, чтобы все процессы записывали данные в SocketHandler, а отдельный процесс реализовывал сокет-сервер, который читает из сокета и записывает в файл. (Если хотите, можно выделить один поток в одном из существующих процессов для выполнения этой функции.) В этом разделе подробно описывается данный подход и приводится рабочий приёмник сокета, который можно использовать как отправную точку для адаптации в своих приложениях.

Если используется недавняя версия Python, включающая модуль multiprocessing, можно написать собственный обработчик, который использует класс Lock из этого модуля для сериализации доступа к файлу из процессов. Существующие FileHandler и подклассы в настоящее время не используют multiprocessing, хотя в будущем могут. Обратите внимание, что на данный момент модуль multiprocessing не предоставляет работающую функциональность блокировок на всех платформах (см. https://bugs.python.org/issue3770).

Использование ротации файлов¶Using file rotation

Иногда требуется позволить файлу журнала расти до определённого размера, затем открыть новый файл и вести запись в него. Может потребоваться сохранять определённое количество таких файлов, и когда будет создано заданное число файлов, выполнять ротацию, чтобы и количество, и размер файлов оставались в заданных границах. Для такого сценария использования пакет logging предоставляет RotatingFileHandler:

import glob
import logging
import logging.handlers

LOG_FILENAME = 'logging_rotatingfile_example.out'

# Настроить конкретный регистратор с нужным уровнем вывода
my_logger = logging.getLogger('MyLogger')
my_logger.setLevel(logging.DEBUG)

# Добавить обработчик сообщений журнала в регистратор
handler = logging.handlers.RotatingFileHandler(
              LOG_FILENAME, maxBytes=20, backupCount=5)

my_logger.addHandler(handler)

# Записать несколько сообщений
for i in range(20):
    my_logger.debug('i = %d' % i)

# Посмотреть, какие файлы созданы
logfiles = glob.glob('%s*' % LOG_FILENAME)

for filename in logfiles:
    print(filename)

В результате должно получиться 6 отдельных файлов, каждый из которых содержит часть истории журнала приложения:

logging_rotatingfile_example.out
logging_rotatingfile_example.out.1
logging_rotatingfile_example.out.2
logging_rotatingfile_example.out.3
logging_rotatingfile_example.out.4
logging_rotatingfile_example.out.5

Самый свежий файл всегда называется logging_rotatingfile_example.out, и каждый раз при достижении ограничения по размеру он переименовывается с суффиксом .1. Каждый из существующих резервных файлов переименовывается с увеличением суффикса (.1 становится .2 и т.д.), а файл .6 удаляется.

Разумеется, в этом примере размер файла журнала установлен слишком маленьким для наглядности. В реальности нужно установить maxBytes в подходящее значение.

Пример конфигурации на основе словаря¶An example dictionary-based configuration

Ниже приведен пример словаря конфигурации логирования – он взят из документации проекта Django. Этот словарь передается в dictConfig() для применения конфигурации:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'verbose': {
            'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'
        },
        'simple': {
            'format': '%(levelname)s %(message)s'
        },
    },
    'filters': {
        'special': {
            '()': 'project.logging.SpecialFilter',
            'foo': 'bar',
        }
    },
    'handlers': {
        'null': {
            'level':'DEBUG',
            'class':'django.utils.log.NullHandler',
        },
        'console':{
            'level':'DEBUG',
            'class':'logging.StreamHandler',
            'formatter': 'simple'
        },
        'mail_admins': {
            'level': 'ERROR',
            'class': 'django.utils.log.AdminEmailHandler',
            'filters': ['special']
        }
    },
    'loggers': {
        'django': {
            'handlers':['null'],
            'propagate': True,
            'level':'INFO',
        },
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': False,
        },
        'myproject.custom': {
            'handlers': ['console', 'mail_admins'],
            'level': 'INFO',
            'filters': ['special']
        }
    }
}

Для получения дополнительной информации об этой конфигурации можно обратиться к соответствующему разделу документации Django.

Вставка BOM в сообщения, отправляемые в SysLogHandler¶Inserting a BOM into messages sent to a SysLogHandler

RFC 5424 требует, чтобы Unicode-сообщение отправлялось демону syslog в виде набора байтов следующей структуры: необязательный компонент, состоящий только из ASCII, затем метка порядка байтов (BOM) UTF-8, затем Unicode, закодированный в UTF-8. (См. соответствующий раздел спецификации.)

В Python 2.6 и 2.7 в SysLogHandler был добавлен код для вставки BOM в сообщение, но, к сожалению, он был реализован некорректно: BOM появлялся в начале сообщения и не позволял разместить перед ним ни одного чисто ASCII-компонента.

Поскольку такое поведение ошибочно, некорректный код вставки BOM удаляется из Python 2.7.4 и более поздних версий. Однако он не заменяется, и если требуется создавать сообщения, соответствующие RFC 5424, которые включают BOM, необязательную чисто ASCII-последовательность перед ним и произвольный Unicode после него, закодированный с помощью UTF-8, то необходимо сделать следующее:

Необходимо присоединить экземпляр Formatter к экземпляру SysLogHandler, указав строку формата, например:
```
u'ASCII section\ufeffUnicode section'
```
Кодовая точка Unicode u'\ufeff' при кодировании в UTF-8 будет закодирована как UTF-8 BOM – байтовая строка '\xef\xbb\xbf'.
ASCII-часть следует заменить на любые подходящие заполнители, но необходимо следить, чтобы данные, которые появляются там после подстановки, всегда были в ASCII (таким образом, они останутся без изменений после кодирования UTF-8).
Unicode-часть следует заменить на любые заполнители; если данные после подстановки содержат символы за пределами диапазона ASCII, это нормально – они будут закодированы в UTF-8.

Если форматированное сообщение является Unicode, оно будет закодировано с использованием UTF-8 с помощью SysLogHandler. Если следовать приведенным выше правилам, можно будет создавать сообщения, соответствующие RFC 5424. Если нет, логирование может не жаловаться, но сообщения не будут соответствовать RFC 5424, и ваш системный демон syslog может жаловаться.

Реализация структурированного ведения журнала¶Implementing structured logging

Хотя большинство сообщений журнала предназначены для чтения человеком и поэтому не предназначены для машинного разбора, могут возникнуть ситуации, когда требуется выводить сообщения в структурированном формате, который может быть разобран программой (без необходимости в сложных регулярных выражениях). Это легко достигается с помощью пакета logging. Существует несколько способов, но ниже приведён простой подход, использующий JSON для сериализации события в машиночитаемом виде.

import json
import logging

class StructuredMessage(object):
    def __init__(self, message, **kwargs):
        self.message = message
        self.kwargs = kwargs

    def __str__(self):
        return '%s >>> %s' % (self.message, json.dumps(self.kwargs))

_ = StructuredMessage   # необязательно, для улучшения читаемости

logging.basicConfig(level=logging.INFO, format='%(message)s')
logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))

Если запустить приведённый выше скрипт, он выведет:

message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}

Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.

Если требуется более специализированная обработка, можно использовать пользовательский кодировщик JSON, как в следующем полном примере:

from __future__ import unicode_literals

import json
import logging

# Следующий фрагмент предназначен для того, чтобы скрипт работал без изменений в версиях 2.x и 3.x.
try:
    unicode
except NameError:
    unicode = str

class Encoder(json.JSONEncoder):
    def default(self, o):
        if isinstance(o, set):
            return tuple(o)
        elif isinstance(o, unicode):
            return o.encode('unicode_escape').decode('ascii')
        return super(Encoder, self).default(o)

class StructuredMessage(object):
    def __init__(self, message, **kwargs):
        self.message = message
        self.kwargs = kwargs

    def __str__(self):
        s = Encoder().encode(self.kwargs)
        return '%s >>> %s' % (self.message, s)

_ = StructuredMessage   # необязательно, для улучшения читаемости

def main():
    logging.basicConfig(level=logging.INFO, format='%(message)s')
    logging.info(_('message 1', set_value=set([1, 2, 3]), snowman='\u2603'))

if __name__ == '__main__':
    main()

При запуске приведённого выше скрипта он выведет:

message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}

Обратите внимание, что порядок элементов может отличаться в зависимости от используемой версии Python.

Настройка обработчиков с помощью `dictConfig()`¶Customizing handlers with dictConfig()

Иногда требуется настроить обработчики логирования особым образом, и при использовании dictConfig() это можно сделать без создания подклассов. Например, может потребоваться установить владельца файла журнала. В POSIX это легко сделать с помощью os.chown(), но файловые обработчики в стандартной библиотеке не предоставляют встроенной поддержки. Можно настроить создание обработчика с помощью обычной функции, такой как:

def owned_file_handler(filename, mode='a', encoding=None, owner=None):
    if owner:
        import os, pwd, grp
        # преобразовать имена пользователей и групп в uid и gid
        uid = pwd.getpwnam(owner[0]).pw_uid
        gid = grp.getgrnam(owner[1]).gr_gid
        owner = (uid, gid)
        if not os.path.exists(filename):
            open(filename, 'a').close()
        os.chown(filename, *owner)
    return logging.FileHandler(filename, mode, encoding)

Затем в конфигурации логирования, передаваемой в dictConfig(), можно указать, что обработчик должен быть создан вызовом этой функции:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'default': {
            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
        },
    },
    'handlers': {
        'file':{
            # Значения ниже извлекаются из этого словаря и
            # используются для создания обработчика, установки его уровня и
            # его форматтера.
            '()': owned_file_handler,
            'level':'DEBUG',
            'formatter': 'default',
            # Значения ниже передаются вызываемому объекту-создателю обработчика
            # в качестве именованных аргументов.
            'owner': ['pulse', 'pulse'],
            'filename': 'chowntest.log',
            'mode': 'w',
            'encoding': 'utf-8',
        },
    },
    'root': {
        'handlers': ['file'],
        'level': 'DEBUG',
    },
}

В этом примере для иллюстрации права владения устанавливаются с использованием пользователя и группы pulse. Собирая всё вместе в рабочий скрипт, chowntest.py:

import logging, logging.config, os, shutil

def owned_file_handler(filename, mode='a', encoding=None, owner=None):
    if owner:
        if not os.path.exists(filename):
            open(filename, 'a').close()
        shutil.chown(filename, *owner)
    return logging.FileHandler(filename, mode, encoding)

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'default': {
            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
        },
    },
    'handlers': {
        'file':{
            # Значения ниже извлекаются из этого словаря и
            # используются для создания обработчика, установки его уровня и
            # его форматтера.
            '()': owned_file_handler,
            'level':'DEBUG',
            'formatter': 'default',
            # Значения ниже передаются вызываемому объекту-создателю обработчика
            # в качестве именованных аргументов.
            'owner': ['pulse', 'pulse'],
            'filename': 'chowntest.log',
            'mode': 'w',
            'encoding': 'utf-8',
        },
    },
    'root': {
        'handlers': ['file'],
        'level': 'DEBUG',
    },
}

logging.config.dictConfig(LOGGING)
logger = logging.getLogger('mylogger')
logger.debug('A debug message')

Для запуска, вероятно, потребуется выполнить от имени root:

$ sudo python3.3 chowntest.py
$ cat chowntest.log
2013-11-05 09:34:51,128 DEBUG mylogger A debug message
$ ls -l chowntest.log
-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log

Обратите внимание, что в этом примере используется Python 3.3, потому что в нём появился shutil.chown(). Этот подход должен работать с любой версией Python, поддерживающей dictConfig() – а именно Python 2.7, 3.2 или новее. В версиях до 3.3 потребовалось бы реализовать фактическую смену владельца, например, с помощью os.chown().

На практике функция создания обработчика может находиться в служебном модуле где-нибудь в вашем проекте. Вместо строки в конфигурации:

'()': owned_file_handler,

можно использовать, например:

'()': 'ext://project.util.owned_file_handler',

где project.util можно заменить на фактическое имя пакета, в котором находится функция. В приведённом рабочем скрипте должно сработать использование 'ext://__main__.owned_file_handler'. Здесь фактический вызываемый объект разрешается с помощью dictConfig() из спецификации ext://.

Этот пример, надеюсь, также показывает, как можно реализовать другие типы изменений файлов – например, установку определённых битов разрешений POSIX – аналогичным образом, с помощью os.chmod().

Разумеется, этот подход можно распространить и на другие типы обработчиков, помимо FileHandler – например, на один из вращающихся файловых обработчиков или на совершенно другой тип обработчика.

Настройка фильтров с помощью `dictConfig()`¶Configuring filters with dictConfig()

Можно настраивать фильтры с помощью dictConfig(), хотя с первого взгляда может быть неочевидно, как это сделать (поэтому и дан этот рецепт). Поскольку Filter – единственный класс фильтра, включенный в стандартную библиотеку, и вряд ли он удовлетворит многие требования (он присутствует только как базовый класс), вам, как правило, потребуется определить свой собственный подкласс Filter с переопределенным методом filter(). Для этого укажите ключ () в словаре конфигурации для фильтра, указав вызываемый объект, который будет использоваться для создания фильтра (класс – наиболее очевидный вариант, но вы можете предоставить любой вызываемый объект, возвращающий экземпляр Filter). Вот полный пример:

import logging
import logging.config
import sys

class MyFilter(logging.Filter):
    def __init__(self, param=None):
        self.param = param

    def filter(self, record):
        if self.param is None:
            allow = True
        else:
            allow = self.param not in record.msg
        if allow:
            record.msg = 'changed: ' + record.msg
        return allow

LOGGING = {
    'version': 1,
    'filters': {
        'myfilter': {
            '()': MyFilter,
            'param': 'noshow',
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'filters': ['myfilter']
        }
    },
    'root': {
        'level': 'DEBUG',
        'handlers': ['console']
    },
}

if __name__ == '__main__':
    logging.config.dictConfig(LOGGING)
    logging.debug('hello')
    logging.debug('hello - noshow')

Этот пример показывает, как можно передавать конфигурационные данные вызываемому объекту, который создает экземпляр, в виде именованных параметров. При запуске приведенный выше скрипт выведет:

changed: hello

что показывает, что фильтр работает в соответствии с настройками.

Несколько дополнительных моментов, на которые стоит обратить внимание:

Если вы не можете сослаться на вызываемый объект напрямую в конфигурации (например, если он находится в другом модуле, и вы не можете импортировать его напрямую в том месте, где находится словарь конфигурации), вы можете использовать форму ext://..., как описано в разделе Доступ к внешним объектам. Например, в приведенном выше примере можно было использовать текст 'ext://__main__.MyFilter' вместо MyFilter.
Помимо фильтров, этот метод также можно использовать для настройки пользовательских обработчиков и форматтеров. Смотрите раздел Пользовательские объекты для получения дополнительной информации о том, как logging поддерживает использование пользовательских объектов в своей конфигурации, а также см. другой рецепт из этой книги рецептов Настройка обработчиков с помощью dictConfig() выше.

Настраиваемое форматирование исключений¶Customized exception formatting

Могут возникнуть ситуации, когда вы захотите настроить форматирование исключений – для примера, предположим, вы хотите ровно одну строку на каждое событие лога, даже если присутствует информация об исключении. Вы можете сделать это с помощью пользовательского класса форматтера, как показано в следующем примере:

import logging

class OneLineExceptionFormatter(logging.Formatter):
    def formatException(self, exc_info):
        """
        Форматировать исключение так, чтобы оно выводилось одной строкой.
        """
        result = super(OneLineExceptionFormatter, self).formatException(exc_info)
        return repr(result) # или форматировать одной строкой по своему усмотрению

    def format(self, record):
        s = super(OneLineExceptionFormatter, self).format(record)
        if record.exc_text:
            s = s.replace('\n', '') + '|'
        return s

def configure_logging():
    fh = logging.FileHandler('output.txt', 'w')
    f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',
                                  '%d/%m/%Y %H:%M:%S')
    fh.setFormatter(f)
    root = logging.getLogger()
    root.setLevel(logging.DEBUG)
    root.addHandler(fh)

def main():
    configure_logging()
    logging.info('Sample message')
    try:
        x = 1 / 0
    except ZeroDivisionError as e:
        logging.exception('ZeroDivisionError: %s', e)

if __name__ == '__main__':
    main()

При запуске это создает файл ровно с двумя строками:

28/01/2015 07:21:23|INFO|Sample message|
28/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'|

Хотя описанный выше подход упрощен, он показывает путь к тому, как можно форматировать информацию об исключениях по своему вкусу. Модуль traceback может быть полезен для более специализированных нужд.

Озвучивание сообщений лога¶Speaking logging messages

Могут быть ситуации, когда желательно выводить сообщения лога в звуковом, а не визуальном формате. Это легко сделать, если в вашей системе доступна функция преобразования текста в речь (TTS), даже если у нее нет привязки к Python. Большинство TTS-систем имеют программу командной строки, которую можно запустить, и ее можно вызвать из обработчика с помощью subprocess. Здесь предполагается, что программы командной строки TTS не будут ожидать взаимодействия с пользователем или занимать много времени для завершения, и что частота сообщений лога не будет настолько высокой, чтобы перегружать пользователя сообщениями, и что допустимо проговаривать сообщения по одному, а не одновременно. В приведенном ниже примере реализации ожидается, пока одно сообщение не будет произнесено, прежде чем обрабатывать следующее, и это может заставить другие обработчики ждать. Вот короткий пример, демонстрирующий подход, который предполагает, что доступен TTS-пакет espeak:

import logging
import subprocess
import sys

class TTSHandler(logging.Handler):
    def emit(self, record):
        msg = self.format(record)
        # Говорить медленно женским английским голосом.
        cmd = ['espeak', '-s150', '-ven+f3', msg]
        p = subprocess.Popen(cmd, stdout=subprocess.PIPE,
                             stderr=subprocess.STDOUT)
        # дождаться завершения программы
        p.communicate()

def configure_logging():
    h = TTSHandler()
    root = logging.getLogger()
    root.addHandler(h)
    # стандартный форматтер просто возвращает сообщение
    root.setLevel(logging.DEBUG)

def main():
    logging.info('Hello')
    logging.debug('Goodbye')

if __name__ == '__main__':
    configure_logging()
    sys.exit(main())

При запуске этот скрипт должен сказать «Hello», а затем «Goodbye» женским голосом.

Описанный выше подход, конечно, можно адаптировать для других TTS-систем и даже для других систем, которые могут обрабатывать сообщения через внешние программы, запускаемые из командной строки.

Буферизация сообщений лога и условный вывод¶Buffering logging messages and outputting them conditionally

Могут возникнуть ситуации, когда вы хотите записывать сообщения во временную область и выводить их только при наступлении определенного условия. Например, вы можете начать запись отладочных событий в функции, и если функция завершится без ошибок, вы не захотите засорять лог собранной отладочной информацией, но если возникнет ошибка, вы захотите вывести всю отладочную информацию вместе с ошибкой.

Вот пример, показывающий, как это можно сделать с помощью декоратора для ваших функций, где вы хотите, чтобы логирование вело себя таким образом. Он использует logging.handlers.MemoryHandler, который позволяет буферизовать зарегистрированные события до наступления некоторого условия, после чего буферизованные события flushed – передаются другому обработчику (обработчику target) для обработки. По умолчанию MemoryHandler сбрасывается, когда его буфер заполняется или встречается событие, уровень которого больше или равен указанному порогу. Вы можете использовать этот рецепт с более специализированным подклассом MemoryHandler, если хотите настроить поведение сброса.

Пример скрипта содержит простую функцию foo, которая просто перебирает все уровни логирования, записывая в sys.stderr информацию о том, какой уровень будет использоваться, а затем регистрирует сообщение на этом уровне. Вы можете передать параметр в foo, который, если равен true, будет регистрировать на уровнях ERROR и CRITICAL – в противном случае он регистрирует только на уровнях DEBUG, INFO и WARNING.

Скрипт просто декорирует foo декоратором, который выполняет условное логирование по необходимости. Декоратор принимает логгер в качестве параметра и подключает обработчик с буферизацией в памяти на время вызова декорируемой функции. Декоратор можно дополнительно настроить, указав целевой обработчик, уровень, при котором следует сбрасывать буфер, и ёмкость буфера. По умолчанию используются StreamHandler, который пишет в sys.stderr, logging.ERROR и 100 соответственно.

Вот скрипт:

import logging
from logging.handlers import MemoryHandler
import sys

logger = logging.getLogger(__name__)
logger.addHandler(logging.NullHandler())

def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):
    if target_handler is None:
        target_handler = logging.StreamHandler()
    if flush_level is None:
        flush_level = logging.ERROR
    if capacity is None:
        capacity = 100
    handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)

    def decorator(fn):
        def wrapper(*args, **kwargs):
            logger.addHandler(handler)
            try:
                return fn(*args, **kwargs)
            except Exception:
                logger.exception('call failed')
                raise
            finally:
                super(MemoryHandler, handler).flush()
                logger.removeHandler(handler)
        return wrapper

    return decorator

def write_line(s):
    sys.stderr.write('%s\n' % s)

def foo(fail=False):
    write_line('about to log at DEBUG ...')
    logger.debug('Actually logged at DEBUG')
    write_line('about to log at INFO ...')
    logger.info('Actually logged at INFO')
    write_line('about to log at WARNING ...')
    logger.warning('Actually logged at WARNING')
    if fail:
        write_line('about to log at ERROR ...')
        logger.error('Actually logged at ERROR')
        write_line('about to log at CRITICAL ...')
        logger.critical('Actually logged at CRITICAL')
    return fail

decorated_foo = log_if_errors(logger)(foo)

if __name__ == '__main__':
    logger.setLevel(logging.DEBUG)
    write_line('Calling undecorated foo with False')
    assert not foo(False)
    write_line('Calling undecorated foo with True')
    assert foo(True)
    write_line('Calling decorated foo with False')
    assert not decorated_foo(False)
    write_line('Calling decorated foo with True')
    assert decorated_foo(True)

При запуске этого скрипта отобразится следующий вывод:

Calling undecorated foo with False
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
Calling undecorated foo with True
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
about to log at ERROR ...
about to log at CRITICAL ...
Calling decorated foo with False
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
Calling decorated foo with True
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
about to log at ERROR ...
Actually logged at DEBUG
Actually logged at INFO
Actually logged at WARNING
Actually logged at ERROR
about to log at CRITICAL ...
Actually logged at CRITICAL

Как видно, фактический вывод журнала происходит только при регистрации события, уровень которого ERROR или выше, но в этом случае также регистрируются все предыдущие события с более низкими уровнями.

Конечно, можно использовать обычные средства декорирования:

@log_if_errors(logger)
def foo(fail=False):
    ...

Форматирование времени с использованием UTC (GMT) через конфигурацию¶Formatting times using UTC (GMT) via configuration

Иногда требуется форматировать время по UTC, что можно сделать с помощью класса такого как UTCFormatter, показанного ниже:

import logging
import time

class UTCFormatter(logging.Formatter):
    converter = time.gmtime

и затем можно использовать UTCFormatter в своём коде вместо Formatter. Если требуется сделать это через конфигурацию, можно воспользоваться API dictConfig(), как показано в следующем полном примере:

import logging
import logging.config
import time

class UTCFormatter(logging.Formatter):
    converter = time.gmtime

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'utc': {
            '()': UTCFormatter,
            'format': '%(asctime)s %(message)s',
        },
        'local': {
            'format': '%(asctime)s %(message)s',
        }
    },
    'handlers': {
        'console1': {
            'class': 'logging.StreamHandler',
            'formatter': 'utc',
        },
        'console2': {
            'class': 'logging.StreamHandler',
            'formatter': 'local',
        },
    },
    'root': {
        'handlers': ['console1', 'console2'],
   }
}

if __name__ == '__main__':
    logging.config.dictConfig(LOGGING)
    logging.warning('The local time is %s', time.asctime())

При запуске этого скрипта он должен вывести примерно следующее:

2015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 2015
2015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 2015

показывая, как время форматируется как в местном времени, так и в UTC, по одному для каждого обработчика.

Использование контекстного менеджера для выборочного журналирования¶Using a context manager for selective logging

Бывают ситуации, когда полезно временно изменить конфигурацию журналирования, а затем вернуть её обратно после выполнения каких-то действий. Для этого контекстный менеджер – самый очевидный способ сохранить и восстановить контекст журналирования. Вот простой пример такого контекстного менеджера, который позволяет по желанию изменить уровень журналирования и добавить обработчик журнала исключительно в области действия контекстного менеджера:

import logging
import sys

class LoggingContext(object):
    def __init__(self, logger, level=None, handler=None, close=True):
        self.logger = logger
        self.level = level
        self.handler = handler
        self.close = close

    def __enter__(self):
        if self.level is not None:
            self.old_level = self.logger.level
            self.logger.setLevel(self.level)
        if self.handler:
            self.logger.addHandler(self.handler)

    def __exit__(self, et, ev, tb):
        if self.level is not None:
            self.logger.setLevel(self.old_level)
        if self.handler:
            self.logger.removeHandler(self.handler)
        if self.handler and self.close:
            self.handler.close()
        # неявный возврат None => не подавлять исключения

Если указать значение уровня, уровень регистратора устанавливается на это значение в области действия блока with, охватываемого контекстным менеджером. Если указать обработчик, он добавляется к регистратору при входе в блок и удаляется при выходе из блока. Также можно попросить менеджер закрыть обработчик при выходе из блока – это можно сделать, если обработчик больше не нужен.

Чтобы проиллюстрировать, как это работает, можно добавить следующий блок кода к предыдущему:

if __name__ == '__main__':
    logger = logging.getLogger('foo')
    logger.addHandler(logging.StreamHandler())
    logger.setLevel(logging.INFO)
    logger.info('1. This should appear just once on stderr.')
    logger.debug('2. This should not appear.')
    with LoggingContext(logger, level=logging.DEBUG):
        logger.debug('3. This should appear once on stderr.')
    logger.debug('4. This should not appear.')
    h = logging.StreamHandler(sys.stdout)
    with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):
        logger.debug('5. This should appear twice - once on stderr and once on stdout.')
    logger.info('6. This should appear just once on stderr.')
    logger.debug('7. This should not appear.')

Изначально устанавливаем уровень регистратора равным INFO, поэтому сообщение №1 отображается, а сообщение №2 – нет. Затем временно меняем уровень на DEBUG в следующем блоке with, и сообщение №3 отображается. После выхода из блока уровень регистратора восстанавливается до INFO, поэтому сообщение №4 не отображается. В следующем блоке with снова устанавливаем уровень DEBUG, но также добавляем обработчик, записывающий в sys.stdout. Таким образом, сообщение №5 отображается дважды на консоли (один раз через stderr и один раз через stdout). После завершения оператора with состояние возвращается к исходному, поэтому сообщение №6 отображается (как сообщение №1), а сообщение №7 – нет (как сообщение №2).

Если запустить полученный скрипт, результат будет следующим:

$ python logctx.py
This should appear just once on stderr.
This should appear once on stderr.
This should appear twice - once on stderr and once on stdout.
This should appear twice - once on stderr and once on stdout.
This should appear just once on stderr.

Если запустить его снова, но перенаправить stderr в /dev/null, мы увидим следующее, что является единственным сообщением, записанным в stdout:

$ python logctx.py 2>/dev/null
5. This should appear twice - once on stderr and once on stdout.

Ещё раз, но перенаправляя stdout в /dev/null, получаем:

$ python logctx.py >/dev/null
This should appear just once on stderr.
This should appear once on stderr.
This should appear twice - once on stderr and once on stdout.
This should appear just once on stderr.

В этом случае сообщение №5, выведенное в stdout, не отображается, как и ожидалось.

Разумеется, описанный подход можно обобщить, например, для временного подключения фильтров журналирования. Обратите внимание, что приведённый выше код работает как в Python 2, так и в Python 3.