Поваренная книга по ведению журналов

Автор

Винай Саджип <vinay_sajip at red-dove dot com>

Эта страница содержит ряд рецептов, связанных с протоколированием, которые были признаны полезными в прошлом. Ссылки на учебную и справочную информацию см. в разделе Другие ресурсы.

Использование протоколирования в нескольких модулях

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

import logging
import auxiliary_module

# create logger with 'spam_application'
logger = logging.getLogger('spam_application')
logger.setLevel(logging.DEBUG)
# create file handler which logs even debug messages
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
# create formatter and add it to the handlers
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)
# add the handlers to the logger
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

# create logger
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()

Ведение журнала из нескольких потоков

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

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()

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

   0 Thread-1 Hi from myfunc
   3 MainThread Hello from main
 505 Thread-1 Hi from myfunc
 755 MainThread Hello from main
1007 Thread-1 Hi from myfunc
1507 MainThread Hello from main
1508 Thread-1 Hi from myfunc
2010 Thread-1 Hi from myfunc
2258 MainThread Hello from main
2512 Thread-1 Hi from myfunc
3009 MainThread Hello from main
3013 Thread-1 Hi from myfunc
3515 Thread-1 Hi from myfunc
3761 MainThread Hello from main
4017 Thread-1 Hi from myfunc
4513 MainThread Hello from main
4518 Thread-1 Hi from myfunc

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

Множественные обработчики и форматеры

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

import logging

logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)
# create file handler which logs even debug messages
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
# create formatter and add it to the handlers
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(formatter)
fh.setFormatter(formatter)
# add the handlers to logger
logger.addHandler(ch)
logger.addHandler(fh)

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')

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

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

Ведение журнала в нескольких местах назначения

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

import logging

# set up logging to file - see previous section for more details
logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
                    datefmt='%m-%d %H:%M',
                    filename='/tmp/myapp.log',
                    filemode='w')
# define a Handler which writes INFO messages or higher to the sys.stderr
console = logging.StreamHandler()
console.setLevel(logging.INFO)
# set a format which is simpler for console use
formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
# tell the handler to use this format
console.setFormatter(formatter)
# add the handler to the root logger
logging.getLogger('').addHandler(console)

# Now, we can log to the root logger, or any other logger. First the root...
logging.info('Jackdaws love my big sphinx of quartz.')

# Now, define a couple of other loggers which might represent areas in your
# application:

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. Остальные сообщения отправляются в оба пункта назначения.

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

Обратите внимание, что указанный выше выбор имени файла журнала /tmp/myapp.log подразумевает использование стандартного места для временных файлов в POSIX-системах. В Windows вам может понадобиться выбрать другое имя каталога для журнала - просто убедитесь, что каталог существует и что у вас есть права на создание и обновление файлов в нем.

Пример сервера конфигурации

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

import logging
import logging.config
import time
import os

# read initial config file
logging.config.fileConfig('logging.conf')

# create and start listener on port 9999
t = logging.config.listen(9999)
t.start()

logger = logging.getLogger('simpleExample')

try:
    # loop through logging calls to see the difference
    # new configurations make, until Ctrl+C is pressed
    while True:
        logger.debug('debug message')
        logger.info('info message')
        logger.warning('warn message')
        logger.error('error message')
        logger.critical('critical message')
        time.sleep(5)
except KeyboardInterrupt:
    # cleanup
    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')

Работа с обработчиками, которые блокируют

Иногда необходимо заставить обработчики регистрации выполнять свою работу, не блокируя поток, из которого ведется регистрация. Это часто встречается в веб-приложениях, хотя, конечно, бывает и в других сценариях.

Частым виновником вялого поведения является SMTPHandler: отправка электронной почты может занимать много времени по ряду причин, не зависящих от разработчика (например, плохо работающая почтовая или сетевая инфраструктура). Но почти любой сетевой обработчик может блокировать: Даже операция SocketHandler может выполнять DNS-запрос под капотом, что слишком медленно (и этот запрос может находиться глубоко в коде библиотеки сокетов, ниже уровня Python, и вне вашего контроля).

Одним из решений является использование подхода, состоящего из двух частей. Для первой части прикрепите только QueueHandler к тем регистраторам, к которым обращаются критически важные по производительности потоки. Они просто пишут в свою очередь, которая может иметь достаточно большой размер или быть инициализирована без верхней границы для своего размера. Запись в очередь обычно принимается быстро, хотя вам, вероятно, придется перехватывать исключение queue.Full в качестве меры предосторожности в вашем коде. Если вы являетесь разработчиком библиотеки, в коде которой есть потоки, критичные к производительности, обязательно задокументируйте это (вместе с предложением подключать к логгерам только QueueHandlers) для пользы других разработчиков, которые будут использовать ваш код.

Второй частью решения является QueueListener, который был разработан как аналог QueueHandler. QueueListener очень прост: ему передается очередь и некоторые обработчики, и он запускает внутренний поток, который прослушивает свою очередь на предмет LogRecords, отправленных от QueueHandlers (или любого другого источника LogRecords, если на то пошло). Записи LogRecords удаляются из очереди и передаются обработчикам для обработки.

Преимущество отдельного класса QueueListener в том, что вы можете использовать один и тот же экземпляр для обслуживания нескольких QueueHandlers. Это более дружелюбно к ресурсам, чем, скажем, потоковые версии существующих классов обработчиков, которые будут потреблять по одному потоку на каждый обработчик без особой пользы.

Пример использования этих двух классов приведен ниже (импорт опущен):

que = queue.Queue(-1)  # no limit on size
queue_handler = QueueHandler(que)
handler = logging.StreamHandler()
listener = QueueListener(que, handler)
root = logging.getLogger()
root.addHandler(queue_handler)
formatter = logging.Formatter('%(threadName)s: %(message)s')
handler.setFormatter(formatter)
listener.start()
# The log output will display the thread which generated
# the event (the main thread) rather than the internal
# thread which monitors the internal queue. This is what
# you want to happen.
root.warning('Look out!')
listener.stop()

который при запуске будет производить:

MainThread: Look out!

Изменено в версии 3.5: До Python 3.5 QueueListener всегда передавал каждое сообщение, полученное из очереди, каждому обработчику, которым он был инициализирован. (Это происходило потому, что предполагалось, что фильтрация уровней выполняется на другой стороне, где заполняется очередь). Начиная с версии 3.5, это поведение можно изменить, передав аргумент ключевого слова respect_handler_level=True в конструктор слушателя. После этого слушатель сравнивает уровень каждого сообщения с уровнем обработчика и передает сообщение обработчику, только если это целесообразно.

Отправка и получение событий регистрации по сети

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

import logging, logging.handlers

rootLogger = logging.getLogger('')
rootLogger.setLevel(logging.DEBUG)
socketHandler = logging.handlers.SocketHandler('localhost',
                    logging.handlers.DEFAULT_TCP_LOGGING_PORT)
# don't bother with a formatter, since a socket handler sends the event as
# an unformatted pickle
rootLogger.addHandler(socketHandler)

# Now, we can log to the root logger, or any other logger. First the root...
logging.info('Jackdaws love my big sphinx of quartz.')

# Now, define a couple of other loggers which might represent areas in your
# application:

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):
    """Handler for a streaming logging request.

    This basically logs the record using whatever logging policy is
    configured locally.
    """

    def handle(self):
        """
        Handle multiple requests - each expected to be a 4-byte length,
        followed by the LogRecord in pickle format. Logs the record
        according to whatever policy is configured locally.
        """
        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 a name is specified, we use the named logger rather than the one
        # implied by the record.
        if self.server.logname is not None:
            name = self.server.logname
        else:
            name = record.name
        logger = logging.getLogger(name)
        # N.B. EVERY record gets logged. This is because Logger.handle
        # is normally called AFTER logger-level filtering. If you want
        # to do filtering, do it at the client end to save wasting
        # cycles and network bandwidth!
        logger.handle(record)

class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):
    """
    Simple TCP socket-based logging receiver suitable for testing.
    """

    allow_reuse_address = True

    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...
   59 root            INFO     Jackdaws love my big sphinx of quartz.
   59 myapp.area1     DEBUG    Quick zephyrs blow, vexing daft Jim.
   69 myapp.area1     INFO     How quickly daft jumping zebras vex.
   69 myapp.area2     WARNING  Jail zesty vixen who grabbed pay from quack.
   69 myapp.area2     ERROR    The five boxing wizards jump quickly.

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

Запуск слушателя сокетов регистрации в производстве

Чтобы запустить приемник логов в продакшене, вам может понадобиться инструмент управления процессами, такой как Supervisor. Here - это Gist, в котором содержатся базовые файлы для запуска вышеописанной функциональности с помощью Supervisor: вам нужно будет изменить части /path/to/ в Gist, чтобы отразить фактические пути, которые вы хотите использовать.

Добавление контекстной информации в вывод журнала

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

Использование LoggerAdapters для передачи контекстной информации

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

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

def debug(self, msg, /, *args, **kwargs):
    """
    Delegate a debug call to the underlying logger, after adding
    contextual information from this adapter instance.
    """
    msg, kwargs = self.process(msg, kwargs)
    self.logger.debug(msg, *args, **kwargs)

Метод process() в LoggerAdapter - это место, где контекстная информация добавляется к выводу журнала. Ему передаются аргументы сообщения и ключевого слова вызова логирования, и он передает обратно (потенциально) измененные версии этих аргументов для использования в вызове базового регистратора. Реализация этого метода по умолчанию оставляет сообщение в покое, но вставляет «дополнительный» ключ в аргумент ключевого слова, значением которого является диктоподобный объект, переданный в конструктор. Конечно, если вы передали „лишний“ аргумент ключевого слова в вызове адаптера, он будет молча перезаписан.

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

class CustomAdapter(logging.LoggerAdapter):
    """
    This example adapter expects the passed in dict-like object to have a
    'connid' key, whose value in brackets is prepended to the log message.
    """
    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, добавляемое к сообщениям журнала.

Использование объектов, отличных от dicts, для передачи контекстной информации

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

Использование фильтров для передачи контекстной информации

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

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

import logging
from random import choice

class ContextFilter(logging.Filter):
    """
    This is a filter which injects contextual information into the log.

    Rather than use actual contextual information, we just use random
    data in this demo.
    """

    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

Использование contextvars

Начиная с Python 3.7, модуль contextvars предоставляет контекстно-локальное хранилище, которое работает как для обработки threading, так и для обработки asyncio. Таким образом, этот тип хранения может быть в целом предпочтительнее потоковых локалей. Следующий пример показывает, как в многопоточной среде журналы могут быть заполнены контекстной информацией, такой как, например, атрибуты запросов, обрабатываемых веб-приложениями.

Для иллюстрации представим, что у вас есть различные веб-приложения, каждое из которых независимо от другого, но выполняется в одном и том же процессе Python и использует общую для них библиотеку. Как каждое из этих приложений может иметь свой собственный журнал, в котором все сообщения журнала от библиотеки (и другого кода обработки запросов) будут направляться в файл журнала соответствующего приложения, включая в журнал дополнительную контекстную информацию, такую как IP-адрес клиента, метод HTTP-запроса и имя пользователя клиента?

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

# webapplib.py
import logging
import time

logger = logging.getLogger(__name__)

def useful():
    # Just a representative event logged from the library
    logger.debug('Hello from webapplib!')
    # Just sleep for a bit so other threads get to run
    time.sleep(0.01)

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

# main.py
import argparse
from contextvars import ContextVar
import logging
import os
from random import choice
import threading
import webapplib

logger = logging.getLogger(__name__)
root = logging.getLogger()
root.setLevel(logging.DEBUG)

class Request:
    """
    A simple dummy request class which just holds dummy HTTP request method,
    client IP address and client username
    """
    def __init__(self, method, ip, user):
        self.method = method
        self.ip = ip
        self.user = user

# A dummy set of requests which will be used in the simulation - we'll just pick
# from this list randomly. Note that all GET requests are from 192.168.2.XXX
# addresses, whereas POST requests are from 192.16.3.XXX addresses. Three users
# are represented in the sample requests.

REQUESTS = [
    Request('GET', '192.168.2.20', 'jim'),
    Request('POST', '192.168.3.20', 'fred'),
    Request('GET', '192.168.2.21', 'sheila'),
    Request('POST', '192.168.3.21', 'jim'),
    Request('GET', '192.168.2.22', 'fred'),
    Request('POST', '192.168.3.22', 'sheila'),
]

# Note that the format string includes references to request context information
# such as HTTP method, client IP and username

formatter = logging.Formatter('%(threadName)-11s %(appName)s %(name)-9s %(user)-6s %(ip)s %(method)-4s %(message)s')

# Create our context variables. These will be filled at the start of request
# processing, and used in the logging that happens during that processing

ctx_request = ContextVar('request')
ctx_appname = ContextVar('appname')

class InjectingFilter(logging.Filter):
    """
    A filter which injects context-specific information into logs and ensures
    that only information for a specific webapp is included in its log
    """
    def __init__(self, app):
        self.app = app

    def filter(self, record):
        request = ctx_request.get()
        record.method = request.method
        record.ip = request.ip
        record.user = request.user
        record.appName = appName = ctx_appname.get()
        return appName == self.app.name

class WebApp:
    """
    A dummy web application class which has its own handler and filter for a
    webapp-specific log.
    """
    def __init__(self, name):
        self.name = name
        handler = logging.FileHandler(name + '.log', 'w')
        f = InjectingFilter(self)
        handler.setFormatter(formatter)
        handler.addFilter(f)
        root.addHandler(handler)
        self.num_requests = 0

    def process_request(self, request):
        """
        This is the dummy method for processing a request. It's called on a
        different thread for every request. We store the context information into
        the context vars before doing anything else.
        """
        ctx_request.set(request)
        ctx_appname.set(self.name)
        self.num_requests += 1
        logger.debug('Request processing started')
        webapplib.useful()
        logger.debug('Request processing finished')

def main():
    fn = os.path.splitext(os.path.basename(__file__))[0]
    adhf = argparse.ArgumentDefaultsHelpFormatter
    ap = argparse.ArgumentParser(formatter_class=adhf, prog=fn,
                                 description='Simulate a couple of web '
                                             'applications handling some '
                                             'requests, showing how request '
                                             'context can be used to '
                                             'populate logs')
    aa = ap.add_argument
    aa('--count', '-c', default=100, help='How many requests to simulate')
    options = ap.parse_args()

    # Create the dummy webapps and put them in a list which we can use to select
    # from randomly
    app1 = WebApp('app1')
    app2 = WebApp('app2')
    apps = [app1, app2]
    threads = []
    # Add a common handler which will capture all events
    handler = logging.FileHandler('app.log', 'w')
    handler.setFormatter(formatter)
    root.addHandler(handler)

    # Generate calls to process requests
    for i in range(options.count):
        try:
            # Pick an app at random and a request for it to process
            app = choice(apps)
            request = choice(REQUESTS)
            # Process the request in its own thread
            t = threading.Thread(target=app.process_request, args=(request,))
            threads.append(t)
            t.start()
        except KeyboardInterrupt:
            break

    # Wait for the threads to terminate
    for t in threads:
        t.join()

    for app in apps:
        print('%s processed %s requests' % (app.name, app.num_requests))

if __name__ == '__main__':
    main()

Если вы выполните вышеописанное, то обнаружите, что примерно половина запросов попадает в app1.log, остальные - в app2.log, а все запросы записываются в журнал app.log. Каждый журнал, специфичный для webapp, будет содержать только записи журнала только для этого webapp, и информация о запросах будет отображаться в журнале последовательно (т.е. информация в каждом фиктивном запросе всегда будет отображаться вместе в строке журнала). Это иллюстрируется следующим выводом оболочки:

~/logging-contextual-webapp$ python main.py
app1 processed 51 requests
app2 processed 49 requests
~/logging-contextual-webapp$ wc -l *.log
  153 app1.log
  147 app2.log
  300 app.log
  600 total
~/logging-contextual-webapp$ head -3 app1.log
Thread-3 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
Thread-3 (process_request) app1 webapplib jim    192.168.3.21 POST Hello from webapplib!
Thread-5 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
~/logging-contextual-webapp$ head -3 app2.log
Thread-1 (process_request) app2 __main__  sheila 192.168.2.21 GET  Request processing started
Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET  Hello from webapplib!
Thread-2 (process_request) app2 __main__  jim    192.168.2.20 GET  Request processing started
~/logging-contextual-webapp$ head app.log
Thread-1 (process_request) app2 __main__  sheila 192.168.2.21 GET  Request processing started
Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET  Hello from webapplib!
Thread-2 (process_request) app2 __main__  jim    192.168.2.20 GET  Request processing started
Thread-3 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
Thread-2 (process_request) app2 webapplib jim    192.168.2.20 GET  Hello from webapplib!
Thread-3 (process_request) app1 webapplib jim    192.168.3.21 POST Hello from webapplib!
Thread-4 (process_request) app2 __main__  fred   192.168.2.22 GET  Request processing started
Thread-5 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
Thread-4 (process_request) app2 webapplib fred   192.168.2.22 GET  Hello from webapplib!
Thread-6 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
~/logging-contextual-webapp$ grep app1 app1.log | wc -l
153
~/logging-contextual-webapp$ grep app2 app2.log | wc -l
147
~/logging-contextual-webapp$ grep app1 app.log | wc -l
153
~/logging-contextual-webapp$ grep app2 app.log | wc -l
147

Внесение контекстной информации в обработчики

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

import copy
import logging

def filter(record: logging.LogRecord):
    record = copy.copy(record)
    record.user = 'jim'
    return record

if __name__ == '__main__':
    logger = logging.getLogger()
    logger.setLevel(logging.INFO)
    handler = logging.StreamHandler()
    formatter = logging.Formatter('%(message)s from %(user)-8s')
    handler.setFormatter(formatter)
    handler.addFilter(filter)
    logger.addHandler(handler)

    logger.info('A log message')

Ведение журнала в один файл из нескольких процессов

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

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

В качестве альтернативы вы можете использовать Queue и QueueHandler для отправки всех событий протоколирования в один из процессов вашего многопроцессного приложения. Следующий пример сценария демонстрирует, как это можно сделать; в примере отдельный процесс-слушатель прослушивает события, посылаемые другими процессами, и регистрирует их в соответствии со своей конфигурацией протоколирования. Хотя пример демонстрирует только один из вариантов (например, вы можете использовать поток слушателя, а не отдельный процесс слушателя - реализация будет аналогичной), он допускает совершенно разные конфигурации протоколирования для слушателя и других процессов в вашем приложении, и может быть использован в качестве основы для кода, отвечающего вашим специфическим требованиям:

# You'll need these imports in your own code
import logging
import logging.handlers
import multiprocessing

# Next two import lines for this demo only
from random import choice, random
import time

#
# Because you'll want to define the logging configurations for listener and workers, the
# listener and worker process functions take a configurer parameter which is a callable
# for configuring logging for that process. These functions are also passed the queue,
# which they use for communication.
#
# In practice, you can configure the listener however you want, but note that in this
# simple example, the listener does not apply level or filter logic to received records.
# In practice, you would probably want to do this logic in the worker processes, to avoid
# sending events which would be filtered out between processes.
#
# The size of the rotated files is made small so you can see the results easily.
def listener_configurer():
    root = logging.getLogger()
    h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)
    f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')
    h.setFormatter(f)
    root.addHandler(h)

# This is the listener process top-level loop: wait for logging events
# (LogRecords)on the queue and handle them, quit when you get a None for a
# LogRecord.
def listener_process(queue, configurer):
    configurer()
    while True:
        try:
            record = queue.get()
            if record is None:  # We send this as a sentinel to tell the listener to quit.
                break
            logger = logging.getLogger(record.name)
            logger.handle(record)  # No level or filter logic applied - just do it!
        except Exception:
            import sys, traceback
            print('Whoops! Problem:', file=sys.stderr)
            traceback.print_exc(file=sys.stderr)

# Arrays used for random selections in this demo

LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,
          logging.ERROR, logging.CRITICAL]

LOGGERS = ['a.b.c', 'd.e.f']

MESSAGES = [
    'Random message #1',
    'Random message #2',
    'Random message #3',
]

# The worker configuration is done at the start of the worker process run.
# Note that on Windows you can't rely on fork semantics, so each process
# will run the logging configuration code when it starts.
def worker_configurer(queue):
    h = logging.handlers.QueueHandler(queue)  # Just the one handler needed
    root = logging.getLogger()
    root.addHandler(h)
    # send all messages, for demo; no other level or filter logic applied.
    root.setLevel(logging.DEBUG)

# This is the worker process top-level loop, which just logs ten events with
# random intervening delays before terminating.
# The print messages are just so you know it's doing something!
def worker_process(queue, configurer):
    configurer(queue)
    name = multiprocessing.current_process().name
    print('Worker started: %s' % name)
    for i in range(10):
        time.sleep(random())
        logger = logging.getLogger(choice(LOGGERS))
        level = choice(LEVELS)
        message = choice(MESSAGES)
        logger.log(level, message)
    print('Worker finished: %s' % name)

# Here's where the demo gets orchestrated. Create the queue, create and start
# the listener, create ten workers and start them, wait for them to finish,
# then send a None to the queue to tell the listener to finish.
def main():
    queue = multiprocessing.Queue(-1)
    listener = multiprocessing.Process(target=listener_process,
                                       args=(queue, listener_configurer))
    listener.start()
    workers = []
    for i in range(10):
        worker = multiprocessing.Process(target=worker_process,
                                         args=(queue, worker_configurer))
        workers.append(worker)
        worker.start()
    for w in workers:
        w.join()
    queue.put_nowait(None)
    listener.join()

if __name__ == '__main__':
    main()

В варианте вышеприведенного сценария протоколирование ведется в основном процессе, в отдельном потоке:

import logging
import logging.config
import logging.handlers
from multiprocessing import Process, Queue
import random
import threading
import time

def logger_thread(q):
    while True:
        record = q.get()
        if record is None:
            break
        logger = logging.getLogger(record.name)
        logger.handle(record)


def worker_process(q):
    qh = logging.handlers.QueueHandler(q)
    root = logging.getLogger()
    root.setLevel(logging.DEBUG)
    root.addHandler(qh)
    levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
              logging.CRITICAL]
    loggers = ['foo', 'foo.bar', 'foo.bar.baz',
               'spam', 'spam.ham', 'spam.ham.eggs']
    for i in range(100):
        lvl = random.choice(levels)
        logger = logging.getLogger(random.choice(loggers))
        logger.log(lvl, 'Message no. %d', i)

if __name__ == '__main__':
    q = Queue()
    d = {
        'version': 1,
        'formatters': {
            'detailed': {
                'class': 'logging.Formatter',
                'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
            }
        },
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler',
                'level': 'INFO',
            },
            'file': {
                'class': 'logging.FileHandler',
                'filename': 'mplog.log',
                'mode': 'w',
                'formatter': 'detailed',
            },
            'foofile': {
                'class': 'logging.FileHandler',
                'filename': 'mplog-foo.log',
                'mode': 'w',
                'formatter': 'detailed',
            },
            'errors': {
                'class': 'logging.FileHandler',
                'filename': 'mplog-errors.log',
                'mode': 'w',
                'level': 'ERROR',
                'formatter': 'detailed',
            },
        },
        'loggers': {
            'foo': {
                'handlers': ['foofile']
            }
        },
        'root': {
            'level': 'DEBUG',
            'handlers': ['console', 'file', 'errors']
        },
    }
    workers = []
    for i in range(5):
        wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))
        workers.append(wp)
        wp.start()
    logging.config.dictConfig(d)
    lp = threading.Thread(target=logger_thread, args=(q,))
    lp.start()
    # At this point, the main process could do some useful work of its own
    # Once it's done that, it can wait for the workers to terminate...
    for wp in workers:
        wp.join()
    # And now tell the logging thread to finish up, too
    q.put(None)
    lp.join()

Этот вариант показывает, как можно, например, применить конфигурацию для определенных регистраторов - например, регистратор foo имеет специальный обработчик, который сохраняет все события в подсистеме foo в файл mplog-foo.log. Он будет использоваться механизмом протоколирования в главном процессе (даже если события протоколирования генерируются в рабочих процессах) для направления сообщений в соответствующие места назначения.

Использование concurrent.futures.ProcessPoolExecutor

Если вы хотите использовать concurrent.futures.ProcessPoolExecutor для запуска рабочих процессов, вам нужно создать очередь немного по-другому. Вместо

queue = multiprocessing.Queue(-1)

вы должны использовать

queue = multiprocessing.Manager().Queue(-1)  # also works with the examples above

и затем вы можете заменить создание рабочего из этого:

workers = []
for i in range(10):
    worker = multiprocessing.Process(target=worker_process,
                                     args=(queue, worker_configurer))
    workers.append(worker)
    worker.start()
for w in workers:
    w.join()

к этому (не забыв сначала импортировать concurrent.futures):

with concurrent.futures.ProcessPoolExecutor(max_workers=10) as executor:
    for i in range(10):
        executor.submit(worker_process, queue, worker_configurer)

Развертывание веб-приложений с помощью Gunicorn и uWSGI

При развертывании веб-приложений с помощью Gunicorn или uWSGI (или аналогичных) создается несколько рабочих процессов для обработки клиентских запросов. В таких средах избегайте создания обработчиков на основе файлов непосредственно в веб-приложении. Вместо этого используйте SocketHandler для регистрации из веб-приложения в слушателе в отдельном процессе. Это можно настроить с помощью инструмента управления процессами, такого как Supervisor - подробнее см. в Running a logging socket listener in production.

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

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

import glob
import logging
import logging.handlers

LOG_FILENAME = 'logging_rotatingfile_example.out'

# Set up a specific logger with our desired output level
my_logger = logging.getLogger('MyLogger')
my_logger.setLevel(logging.DEBUG)

# Add the log message handler to the logger
handler = logging.handlers.RotatingFileHandler(
              LOG_FILENAME, maxBytes=20, backupCount=5)

my_logger.addHandler(handler)

# Log some messages
for i in range(20):
    my_logger.debug('i = %d' % i)

# See what files are created
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 в соответствующее значение.

Использование альтернативных стилей форматирования

Когда ведение журнала было добавлено в стандартную библиотеку Python, единственным способом форматирования сообщений с переменным содержимым было использование метода %-formatting. С тех пор в Python появилось два новых подхода к форматированию: string.Template (добавлен в Python 2.4) и str.format() (добавлен в Python 2.6).

Логирование (начиная с версии 3.2) обеспечивает улучшенную поддержку этих двух дополнительных стилей форматирования. Класс Formatter был усовершенствован и теперь принимает дополнительный необязательный параметр ключевого слова style. По умолчанию он равен '%', но возможны и другие значения '{' и '$', которые соответствуют двум другим стилям форматирования. По умолчанию поддерживается обратная совместимость (как и следовало ожидать), но при явном указании параметра стиля вы получаете возможность указать строки форматирования, которые работают с str.format() или string.Template. Вот пример консольной сессии для демонстрации возможностей:

>>> import logging
>>> root = logging.getLogger()
>>> root.setLevel(logging.DEBUG)
>>> handler = logging.StreamHandler()
>>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}',
...                        style='{')
>>> handler.setFormatter(bf)
>>> root.addHandler(handler)
>>> logger = logging.getLogger('foo.bar')
>>> logger.debug('This is a DEBUG message')
2010-10-28 15:11:55,341 foo.bar DEBUG    This is a DEBUG message
>>> logger.critical('This is a CRITICAL message')
2010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message
>>> df = logging.Formatter('$asctime $name ${levelname} $message',
...                        style='$')
>>> handler.setFormatter(df)
>>> logger.debug('This is a DEBUG message')
2010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message
>>> logger.critical('This is a CRITICAL message')
2010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message
>>>

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

>>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')
2010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message
>>>

Вызовы логирования (logger.debug(), logger.info() и т.д.) принимают только позиционные параметры для самого сообщения логирования, а параметры ключевых слов используются только для определения опций обработки фактического вызова логирования (например, параметр ключевого слова exc_info для указания того, что информация об обратном ходе должна быть записана в журнал, или параметр ключевого слова extra для указания дополнительной контекстной информации, которая должна быть добавлена в журнал). Таким образом, вы не можете напрямую делать вызовы логирования, используя синтаксис str.format() или string.Template, потому что внутри пакет логирования использует %-форматирование для объединения строки формата и аргументов переменной. Это невозможно изменить, сохранив обратную совместимость, так как все вызовы логирования, которые есть в существующем коде, будут использовать строки %-формата.

Однако существует способ использования {}- и $- форматирования для построения индивидуальных сообщений журнала. Напомним, что для сообщения вы можете использовать произвольный объект в качестве строки формата сообщения, а пакет logging будет вызывать str() на этом объекте для получения фактической строки формата. Рассмотрим следующие два класса:

class BraceMessage:
    def __init__(self, fmt, /, *args, **kwargs):
        self.fmt = fmt
        self.args = args
        self.kwargs = kwargs

    def __str__(self):
        return self.fmt.format(*self.args, **self.kwargs)

class DollarMessage:
    def __init__(self, fmt, /, **kwargs):
        self.fmt = fmt
        self.kwargs = kwargs

    def __str__(self):
        from string import Template
        return Template(self.fmt).substitute(**self.kwargs)

Любой из них может использоваться вместо строки формата, чтобы позволить {}- или $-форматированию использоваться для создания фактической части «сообщения», которая появляется в форматированном выводе журнала вместо «%(message)s» или «{message}» или «$message». Немного громоздко использовать имена классов каждый раз, когда вы хотите записать что-то в журнал, но это вполне приемлемо, если вы используете псевдоним, например __ (двойное подчеркивание — не путать с _, одинарным подчеркиванием, используемым как синоним/псевдоним для gettext.gettext() или его собратьев).

Приведенные выше классы не включены в Python, хотя их достаточно легко скопировать и вставить в собственный код. Их можно использовать следующим образом (при условии, что они объявлены в модуле с именем wherever):

>>> from wherever import BraceMessage as __
>>> print(__('Message with {0} {name}', 2, name='placeholders'))
Message with 2 placeholders
>>> class Point: pass
...
>>> p = Point()
>>> p.x = 0.5
>>> p.y = 0.5
>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})',
...       point=p))
Message with coordinates: (0.50, 0.50)
>>> from wherever import DollarMessage as __
>>> print(__('Message with $num $what', num=2, what='placeholders'))
Message with 2 placeholders
>>>

Хотя в приведенных выше примерах используется print(), чтобы показать, как работает форматирование, вы, конечно же, будете использовать logger.debug() или аналогичное, чтобы действительно вести журнал, используя этот подход.

Следует отметить, что при таком подходе вы не понесете значительных потерь в производительности: фактическое форматирование происходит не тогда, когда вы делаете вызов логирования, а когда (и если) зарегистрированное сообщение действительно собирается быть выведенным в журнал обработчиком. Единственная необычная вещь, которая может вас смутить, - это то, что круглые скобки обводят строку форматирования и аргументы, а не только строку форматирования. Это потому, что обозначение __ - просто синтаксический сахар для вызова конструктора одного из классов XXXMessage.

Если вы предпочитаете, вы можете использовать LoggerAdapter для достижения эффекта, аналогичного вышеописанному, как в следующем примере:

import logging

class Message:
    def __init__(self, fmt, args):
        self.fmt = fmt
        self.args = args

    def __str__(self):
        return self.fmt.format(*self.args)

class StyleAdapter(logging.LoggerAdapter):
    def __init__(self, logger, extra=None):
        super().__init__(logger, extra or {})

    def log(self, level, msg, /, *args, **kwargs):
        if self.isEnabledFor(level):
            msg, kwargs = self.process(msg, kwargs)
            self.logger._log(level, Message(msg, args), (), **kwargs)

logger = StyleAdapter(logging.getLogger(__name__))

def main():
    logger.debug('Hello, {}', 'world!')

if __name__ == '__main__':
    logging.basicConfig(level=logging.DEBUG)
    main()

При запуске с Python 3.2 или более поздней версией вышеприведенный скрипт должен выдать в журнал сообщение Hello, world!.

Настройка LogRecord

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

  • Logger.makeRecord(), который вызывается в обычном процессе регистрации события. Это вызывает LogRecord непосредственно для создания экземпляра.

  • makeLogRecord(), который вызывается со словарем, содержащим атрибуты, которые необходимо добавить к записи LogRecord. Обычно эта функция вызывается, когда по сети получен подходящий словарь (например, в форме pickle через SocketHandler или в форме JSON через HTTPHandler).

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

  • Создайте свой собственный подкласс Logger, который переопределяет Logger.makeRecord(), и установите его с помощью setLoggerClass() перед инстанцированием всех регистраторов, о которых вы заботитесь.

  • Добавьте Filter к регистратору или обработчику, который выполняет необходимые специальные манипуляции, когда вызывается его метод filter().

Первый подход был бы немного громоздким в сценарии, когда (скажем) несколько различных библиотек хотят делать разные вещи. Каждая из них попыталась бы установить свой собственный подкласс Logger, и победила бы та, которая сделала это последней.

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

logger = logging.getLogger(__name__)

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

В Python 3.2 и более поздних версиях создание LogRecord осуществляется через фабрику, которую вы можете указать. Фабрика - это просто вызываемый объект, который можно задать с помощью setLogRecordFactory() и опросить с помощью getLogRecordFactory(). Фабрика вызывается с той же сигнатурой, что и конструктор LogRecord, поскольку LogRecord является настройкой фабрики по умолчанию.

Такой подход позволяет пользовательской фабрике контролировать все аспекты создания LogRecord. Например, вы можете вернуть подкласс или просто добавить некоторые дополнительные атрибуты к записи после ее создания, используя схему, подобную этой:

old_factory = logging.getLogRecordFactory()

def record_factory(*args, **kwargs):
    record = old_factory(*args, **kwargs)
    record.custom_attribute = 0xdecafbad
    return record

logging.setLogRecordFactory(record_factory)

Этот паттерн позволяет различным библиотекам объединять фабрики в цепочки, и до тех пор, пока они не перезаписывают атрибуты друг друга или непреднамеренно не переписывают атрибуты, предоставляемые в стандартном виде, никаких сюрпризов быть не должно. Однако следует помнить, что каждое звено в цепочке добавляет накладные расходы времени выполнения ко всем операциям протоколирования, и эту технику следует использовать только тогда, когда использование Filter не дает желаемого результата.

Подклассификация QueueHandler - пример ZeroMQ

Вы можете использовать подкласс QueueHandler для отправки сообщений в другие виды очередей, например, в сокет ZeroMQ „publish“. В примере ниже сокет создается отдельно и передается в обработчик (как его «очередь»):

import zmq   # using pyzmq, the Python binding for ZeroMQ
import json  # for serializing records portably

ctx = zmq.Context()
sock = zmq.Socket(ctx, zmq.PUB)  # or zmq.PUSH, or other suitable value
sock.bind('tcp://*:5556')        # or wherever

class ZeroMQSocketHandler(QueueHandler):
    def enqueue(self, record):
        self.queue.send_json(record.__dict__)


handler = ZeroMQSocketHandler(sock)

Конечно, существуют и другие способы организации, например, передача данных, необходимых обработчику для создания сокета:

class ZeroMQSocketHandler(QueueHandler):
    def __init__(self, uri, socktype=zmq.PUB, ctx=None):
        self.ctx = ctx or zmq.Context()
        socket = zmq.Socket(self.ctx, socktype)
        socket.bind(uri)
        super().__init__(socket)

    def enqueue(self, record):
        self.queue.send_json(record.__dict__)

    def close(self):
        self.queue.close()

Подклассификация QueueListener - пример ZeroMQ

Вы также можете подклассифицировать QueueListener для получения сообщений из других видов очередей, например, из ZeroMQ „subscribe“ socket. Вот пример:

class ZeroMQSocketListener(QueueListener):
    def __init__(self, uri, /, *handlers, **kwargs):
        self.ctx = kwargs.get('ctx') or zmq.Context()
        socket = zmq.Socket(self.ctx, zmq.SUB)
        socket.setsockopt_string(zmq.SUBSCRIBE, '')  # subscribe to everything
        socket.connect(uri)
        super().__init__(socket, *handlers, **kwargs)

    def dequeue(self):
        msg = self.queue.recv_json()
        return logging.makeLogRecord(msg)

См.также

Модуль logging

Ссылка на API для модуля протоколирования.

Модуль logging.config

API конфигурации для модуля протоколирования.

Модуль logging.handlers

Полезные обработчики, включенные в модуль протоколирования.

A basic logging tutorial

A more advanced logging tutorial

Пример конфигурации на основе словаря

Ниже приведен пример словаря конфигурации протоколирования - он взят из documentation on the Django project. Этот словарь передается в 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']
        }
    }
}

Ниже приведен пример словаря конфигурации протоколирования - он взят из relevant section. Этот словарь передается в для введения конфигурации в действие:

Использование ротатора и именователя для настройки обработки вращения журнала

Пример того, как можно определить namer и rotator, приведен в следующем фрагменте, который показывает сжатие файла журнала на основе zlib:

def namer(name):
    return name + ".gz"

def rotator(source, dest):
    with open(source, "rb") as sf:
        data = sf.read()
        compressed = zlib.compress(data, 9)
        with open(dest, "wb") as df:
            df.write(compressed)
    os.remove(source)

rh = logging.handlers.RotatingFileHandler(...)
rh.rotator = rotator
rh.namer = namer

Это не «настоящие» файлы .gz, поскольку они представляют собой просто сжатые данные, без «контейнера», как в настоящем gzip-файле. Этот фрагмент приведен для примера.

Более сложный пример мультипроцессинга

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

В примере главный процесс порождает процесс слушателя и несколько рабочих процессов. Каждый из главных процессов, слушатель и рабочие имеют три отдельные конфигурации (рабочие имеют одну и ту же конфигурацию). Мы можем видеть, как происходит логирование в главном процессе, как рабочие регистрируются в QueueHandler и как слушатель реализует QueueListener и более сложную конфигурацию логирования, а также организует отправку событий, полученных через очередь, в обработчики, указанные в конфигурации. Обратите внимание, что эти конфигурации являются чисто иллюстративными, но вы должны быть в состоянии адаптировать этот пример к своему собственному сценарию.

Вот сценарий - документация и комментарии, надеюсь, объяснят, как он работает:

import logging
import logging.config
import logging.handlers
from multiprocessing import Process, Queue, Event, current_process
import os
import random
import time

class MyHandler:
    """
    A simple handler for logging events. It runs in the listener process and
    dispatches events to loggers based on the name in the received record,
    which then get dispatched, by the logging system, to the handlers
    configured for those loggers.
    """

    def handle(self, record):
        if record.name == "root":
            logger = logging.getLogger()
        else:
            logger = logging.getLogger(record.name)

        if logger.isEnabledFor(record.levelno):
            # The process name is transformed just to show that it's the listener
            # doing the logging to files and console
            record.processName = '%s (for %s)' % (current_process().name, record.processName)
            logger.handle(record)

def listener_process(q, stop_event, config):
    """
    This could be done in the main process, but is just done in a separate
    process for illustrative purposes.

    This initialises logging according to the specified configuration,
    starts the listener and waits for the main process to signal completion
    via the event. The listener is then stopped, and the process exits.
    """
    logging.config.dictConfig(config)
    listener = logging.handlers.QueueListener(q, MyHandler())
    listener.start()
    if os.name == 'posix':
        # On POSIX, the setup logger will have been configured in the
        # parent process, but should have been disabled following the
        # dictConfig call.
        # On Windows, since fork isn't used, the setup logger won't
        # exist in the child, so it would be created and the message
        # would appear - hence the "if posix" clause.
        logger = logging.getLogger('setup')
        logger.critical('Should not appear, because of disabled logger ...')
    stop_event.wait()
    listener.stop()

def worker_process(config):
    """
    A number of these are spawned for the purpose of illustration. In
    practice, they could be a heterogeneous bunch of processes rather than
    ones which are identical to each other.

    This initialises logging according to the specified configuration,
    and logs a hundred messages with random levels to randomly selected
    loggers.

    A small sleep is added to allow other processes a chance to run. This
    is not strictly needed, but it mixes the output from the different
    processes a bit more than if it's left out.
    """
    logging.config.dictConfig(config)
    levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
              logging.CRITICAL]
    loggers = ['foo', 'foo.bar', 'foo.bar.baz',
               'spam', 'spam.ham', 'spam.ham.eggs']
    if os.name == 'posix':
        # On POSIX, the setup logger will have been configured in the
        # parent process, but should have been disabled following the
        # dictConfig call.
        # On Windows, since fork isn't used, the setup logger won't
        # exist in the child, so it would be created and the message
        # would appear - hence the "if posix" clause.
        logger = logging.getLogger('setup')
        logger.critical('Should not appear, because of disabled logger ...')
    for i in range(100):
        lvl = random.choice(levels)
        logger = logging.getLogger(random.choice(loggers))
        logger.log(lvl, 'Message no. %d', i)
        time.sleep(0.01)

def main():
    q = Queue()
    # The main process gets a simple configuration which prints to the console.
    config_initial = {
        'version': 1,
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler',
                'level': 'INFO'
            }
        },
        'root': {
            'handlers': ['console'],
            'level': 'DEBUG'
        }
    }
    # The worker process configuration is just a QueueHandler attached to the
    # root logger, which allows all messages to be sent to the queue.
    # We disable existing loggers to disable the "setup" logger used in the
    # parent process. This is needed on POSIX because the logger will
    # be there in the child following a fork().
    config_worker = {
        'version': 1,
        'disable_existing_loggers': True,
        'handlers': {
            'queue': {
                'class': 'logging.handlers.QueueHandler',
                'queue': q
            }
        },
        'root': {
            'handlers': ['queue'],
            'level': 'DEBUG'
        }
    }
    # The listener process configuration shows that the full flexibility of
    # logging configuration is available to dispatch events to handlers however
    # you want.
    # We disable existing loggers to disable the "setup" logger used in the
    # parent process. This is needed on POSIX because the logger will
    # be there in the child following a fork().
    config_listener = {
        'version': 1,
        'disable_existing_loggers': True,
        'formatters': {
            'detailed': {
                'class': 'logging.Formatter',
                'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
            },
            'simple': {
                'class': 'logging.Formatter',
                'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
            }
        },
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler',
                'formatter': 'simple',
                'level': 'INFO'
            },
            'file': {
                'class': 'logging.FileHandler',
                'filename': 'mplog.log',
                'mode': 'w',
                'formatter': 'detailed'
            },
            'foofile': {
                'class': 'logging.FileHandler',
                'filename': 'mplog-foo.log',
                'mode': 'w',
                'formatter': 'detailed'
            },
            'errors': {
                'class': 'logging.FileHandler',
                'filename': 'mplog-errors.log',
                'mode': 'w',
                'formatter': 'detailed',
                'level': 'ERROR'
            }
        },
        'loggers': {
            'foo': {
                'handlers': ['foofile']
            }
        },
        'root': {
            'handlers': ['console', 'file', 'errors'],
            'level': 'DEBUG'
        }
    }
    # Log some initial events, just to show that logging in the parent works
    # normally.
    logging.config.dictConfig(config_initial)
    logger = logging.getLogger('setup')
    logger.info('About to create workers ...')
    workers = []
    for i in range(5):
        wp = Process(target=worker_process, name='worker %d' % (i + 1),
                     args=(config_worker,))
        workers.append(wp)
        wp.start()
        logger.info('Started worker: %s', wp.name)
    logger.info('About to create listener ...')
    stop_event = Event()
    lp = Process(target=listener_process, name='listener',
                 args=(q, stop_event, config_listener))
    lp.start()
    logger.info('Started listener')
    # We now hang around for the workers to finish their work.
    for wp in workers:
        wp.join()
    # Workers all done, listening can now stop.
    # Logging in the parent still works normally.
    logger.info('Telling listener to stop ...')
    stop_event.set()
    lp.join()
    logger.info('All done.')

if __name__ == '__main__':
    main()

Вставка BOM в сообщения, отправленные на SysLogHandler

RFC 5424 требует, чтобы сообщение Unicode отправлялось демону syslog в виде набора байтов, которые имеют следующую структуру: необязательный компонент pure-ASCII, затем UTF-8 Byte Order Mark (BOM), затем Unicode, закодированный с помощью UTF-8. (См. relevant section of the specification).

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

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

  1. Прикрепите экземпляр Formatter к вашему экземпляру SysLogHandler со строкой формата, например:

    'ASCII section\ufeffUnicode section'
    

    Кодовая точка Unicode U+FEFF при кодировании с использованием UTF-8 будет закодирована как UTF-8 BOM – байт-строка b'\xef\xbb\xbf'.

  2. Замените секцию ASCII на любые другие, какие вам нравятся, но убедитесь, что данные, которые появляются в ней после замены, всегда ASCII (таким образом, они останутся неизменными после кодирования UTF-8).

  3. Замените раздел Unicode любыми удобными для вас заполнителями; если данные, которые появятся там после замены, содержат символы вне диапазона ASCII, это не страшно - они будут закодированы с помощью UTF-8.

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

Реализация структурированного протоколирования

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

import json
import logging

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

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

_ = StructuredMessage   # optional, to improve readability

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

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

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

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

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

import json
import logging


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

class StructuredMessage:
    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   # optional, to improve readability

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

if __name__ == '__main__':
    main()

При выполнении приведенного выше сценария выводится:

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

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

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

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

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)

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

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'default': {
            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
        },
    },
    'handlers': {
        'file':{
            # The values below are popped from this dictionary and
            # used to create the handler, set the handler's level and
            # its formatter.
            '()': owned_file_handler,
            'level':'DEBUG',
            'formatter': 'default',
            # The values below are passed to the handler creator callable
            # as keyword arguments.
            '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':{
            # The values below are popped from this dictionary and
            # used to create the handler, set the handler's level and
            # its formatter.
            '()': owned_file_handler,
            'level':'DEBUG',
            'formatter': 'default',
            # The values below are passed to the handler creator callable
            # as keyword arguments.
            '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 - например, на один из вращающихся обработчиков файлов или вообще на другой тип обработчика.

Использование определенных стилей форматирования во всем приложении

В Python 3.2 у Formatter появился параметр ключевого слова style, который, хотя по умолчанию используется % для обратной совместимости, позволяет указать { или $ для поддержки подходов форматирования, поддерживаемых str.format() и string.Template. Обратите внимание, что это регулирует форматирование сообщений протоколирования для окончательного вывода в журналы и полностью ортогонально тому, как строится отдельное сообщение протоколирования.

Вызовы логирования (debug(), info() и т.д.) принимают только позиционные параметры для самого сообщения логирования, а параметры ключевых слов используются только для определения опций обработки вызова логирования (например, параметр ключевого слова exc_info для указания того, что информация об обратном ходе должна быть записана в журнал, или параметр ключевого слова extra для указания дополнительной контекстной информации, которая должна быть добавлена в журнал). Таким образом, вы не можете напрямую делать вызовы логирования, используя синтаксис str.format() или string.Template, потому что внутри пакет логирования использует %-форматирование для объединения строки формата и аргументов переменной. Это невозможно изменить, сохранив обратную совместимость, так как все вызовы логирования, которые есть в существующем коде, будут использовать строки %-формата.

Были предложения связать стили формата с конкретными логгерами, но этот подход также сталкивается с проблемами обратной совместимости, поскольку любой существующий код может использовать данное имя логгера и использовать %-форматирование.

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

Использование фабрик LogRecord

В Python 3.2, наряду с упомянутыми выше изменениями Formatter, пакет logging получил возможность позволять пользователям устанавливать собственные подклассы LogRecord, используя функцию setLogRecordFactory(). Вы можете использовать ее для создания собственного подкласса LogRecord, который делает правильную вещь, переопределяя метод getMessage(). Реализация этого метода в базовом классе является тем местом, где происходит форматирование msg % args, и где вы можете подставить свое альтернативное форматирование; однако вы должны быть осторожны, чтобы поддерживать все стили форматирования и разрешить %-форматирование по умолчанию, чтобы обеспечить совместимость с другим кодом. Также следует позаботиться о вызове str(self.msg), как это делает базовая реализация.

В Python 3.2, наряду с упомянутыми выше изменениями setLogRecordFactory(), пакет logging получил возможность позволять пользователям устанавливать собственные подклассы LogRecord, используя функцию . Вы можете использовать ее для создания собственного подкласса , который делает правильную вещь, переопределяя метод . Реализация этого метода в базовом классе является тем местом, где происходит форматирование , и где вы можете подставить свое альтернативное форматирование; однако вы должны быть осторожны, чтобы поддерживать все стили форматирования и разрешить %-форматирование по умолчанию, чтобы обеспечить совместимость с другим кодом. Также следует позаботиться о вызове , как это делает базовая реализация.

Использование пользовательских объектов сообщений

Существует еще один, возможно, более простой способ использования {}- и $- форматирования для построения индивидуальных сообщений журнала. Возможно, вы помните (из Использование произвольных объектов в качестве сообщений), что при ведении журнала вы можете использовать произвольный объект в качестве строки формата сообщения, и что пакет ведения журнала будет вызывать str() на этом объекте для получения фактической строки формата. Рассмотрим следующие два класса:

class BraceMessage:
    def __init__(self, fmt, /, *args, **kwargs):
        self.fmt = fmt
        self.args = args
        self.kwargs = kwargs

    def __str__(self):
        return self.fmt.format(*self.args, **self.kwargs)

class DollarMessage:
    def __init__(self, fmt, /, **kwargs):
        self.fmt = fmt
        self.kwargs = kwargs

    def __str__(self):
        from string import Template
        return Template(self.fmt).substitute(**self.kwargs)

Любой из них можно использовать вместо строки формата, чтобы позволить {}- или $-форматированию использоваться для создания фактической части «сообщения», которая появляется в форматированном журнале вместо «%(message)s» или «{message}» или «$message». Если вам кажется немного громоздким использовать имена классов каждый раз, когда вы хотите записать что-то в журнал, вы можете сделать это более удобным, если будете использовать псевдоним, такой как M или _ для сообщения (или, возможно, __, если вы используете _ для локализации).

Примеры такого подхода приведены ниже. Во-первых, форматирование с помощью str.format():

>>> __ = BraceMessage
>>> print(__('Message with {0} {1}', 2, 'placeholders'))
Message with 2 placeholders
>>> class Point: pass
...
>>> p = Point()
>>> p.x = 0.5
>>> p.y = 0.5
>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))
Message with coordinates: (0.50, 0.50)

Во-вторых, форматирование с помощью string.Template:

>>> __ = DollarMessage
>>> print(__('Message with $num $what', num=2, what='placeholders'))
Message with 2 placeholders
>>>

Следует отметить, что при таком подходе вы не понесете значительных потерь в производительности: фактическое форматирование происходит не тогда, когда вы делаете вызов логирования, а когда (и если) зарегистрированное сообщение действительно собирается быть выведенным в журнал обработчиком. Единственная необычная вещь, которая может вас смутить, - это то, что круглые скобки обводят строку форматирования и аргументы, а не только строку форматирования. Это потому, что обозначение __ - просто синтаксический сахар для вызова конструктора одного из классов XXXMessage, показанных выше.

Настройка фильтров с помощью 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() выше.

Индивидуальное форматирование исключений

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

import logging

class OneLineExceptionFormatter(logging.Formatter):
    def formatException(self, exc_info):
        """
        Format an exception so that it prints on a single line.
        """
        result = super().formatException(exc_info)
        return repr(result)  # or format into one line however you want to

    def format(self, record):
        s = super().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 может быть полезен для более специализированных нужд.

Высказывание сообщений журнала

Бывают ситуации, когда желательно, чтобы сообщения журнала выводились не в видимом, а в слышимом формате. Это легко сделать, если в вашей системе есть функция преобразования текста в речь (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)
        # Speak slowly in a female English voice
        cmd = ['espeak', '-s150', '-ven+f3', msg]
        p = subprocess.Popen(cmd, stdout=subprocess.PIPE,
                             stderr=subprocess.STDOUT)
        # wait for the program to finish
        p.communicate()

def configure_logging():
    h = TTSHandler()
    root = logging.getLogger()
    root.addHandler(h)
    # the default formatter just returns the message
    root.setLevel(logging.DEBUG)

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

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

При запуске этот скрипт должен произнести «Привет», а затем «До свидания» женским голосом.

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

Буферизация сообщений журнала и их условный вывод

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

Вот пример, который показывает, как это можно сделать, используя декоратор для ваших функций, в которых вы хотите, чтобы логирование вело себя подобным образом. Он использует 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) через конфигурацию

Иногда вы хотите отформатировать время по 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, по одному для каждого обработчика.

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

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

import logging
import sys

class LoggingContext:
    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()
        # implicit return of None => don't swallow exceptions

Если вы указали значение level, то уровень регистратора устанавливается на это значение в области видимости блока 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
1. This should appear just once on stderr.
3. This should appear once on stderr.
5. This should appear twice - once on stderr and once on stdout.
5. This should appear twice - once on stderr and once on stdout.
6. 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
1. This should appear just once on stderr.
3. This should appear once on stderr.
5. This should appear twice - once on stderr and once on stdout.
6. This should appear just once on stderr.

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

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

Стартовый шаблон приложения CLI

Вот пример, который показывает, как это можно сделать:

  • Использовать уровень ведения журнала на основе аргументов командной строки

  • Диспетчеризация нескольких подкоманд в отдельных файлах, все они регистрируются на одном уровне последовательным образом

  • Используйте простую, минимальную конфигурацию

Предположим, у нас есть приложение командной строки, задачей которого является остановка, запуск или перезапуск некоторых служб. Для наглядности это можно организовать в виде файла app.py, который является основным сценарием приложения, с отдельными командами, реализованными в start.py, stop.py и restart.py. Предположим далее, что мы хотим контролировать многословность приложения через аргумент командной строки, по умолчанию имеющий значение logging.INFO. Вот один из вариантов того, как можно записать app.py:

import argparse
import importlib
import logging
import os
import sys

def main(args=None):
    scriptname = os.path.basename(__file__)
    parser = argparse.ArgumentParser(scriptname)
    levels = ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')
    parser.add_argument('--log-level', default='INFO', choices=levels)
    subparsers = parser.add_subparsers(dest='command',
                                       help='Available commands:')
    start_cmd = subparsers.add_parser('start', help='Start a service')
    start_cmd.add_argument('name', metavar='NAME',
                           help='Name of service to start')
    stop_cmd = subparsers.add_parser('stop',
                                     help='Stop one or more services')
    stop_cmd.add_argument('names', metavar='NAME', nargs='+',
                          help='Name of service to stop')
    restart_cmd = subparsers.add_parser('restart',
                                        help='Restart one or more services')
    restart_cmd.add_argument('names', metavar='NAME', nargs='+',
                             help='Name of service to restart')
    options = parser.parse_args()
    # the code to dispatch commands could all be in this file. For the purposes
    # of illustration only, we implement each command in a separate module.
    try:
        mod = importlib.import_module(options.command)
        cmd = getattr(mod, 'command')
    except (ImportError, AttributeError):
        print('Unable to find the code for command \'%s\'' % options.command)
        return 1
    # Could get fancy here and load configuration from file or dictionary
    logging.basicConfig(level=options.log_level,
                        format='%(levelname)s %(name)s %(message)s')
    cmd(options)

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

А команды start, stop и restart могут быть реализованы в отдельных модулях, как, например, для запуска:

# start.py
import logging

logger = logging.getLogger(__name__)

def command(options):
    logger.debug('About to start %s', options.name)
    # actually do the command processing here ...
    logger.info('Started the \'%s\' service.', options.name)

и, таким образом, для остановки:

# stop.py
import logging

logger = logging.getLogger(__name__)

def command(options):
    n = len(options.names)
    if n == 1:
        plural = ''
        services = '\'%s\'' % options.names[0]
    else:
        plural = 's'
        services = ', '.join('\'%s\'' % name for name in options.names)
        i = services.rfind(', ')
        services = services[:i] + ' and ' + services[i + 2:]
    logger.debug('About to stop %s', services)
    # actually do the command processing here ...
    logger.info('Stopped the %s service%s.', services, plural)

и аналогично для перезапуска:

# restart.py
import logging

logger = logging.getLogger(__name__)

def command(options):
    n = len(options.names)
    if n == 1:
        plural = ''
        services = '\'%s\'' % options.names[0]
    else:
        plural = 's'
        services = ', '.join('\'%s\'' % name for name in options.names)
        i = services.rfind(', ')
        services = services[:i] + ' and ' + services[i + 2:]
    logger.debug('About to restart %s', services)
    # actually do the command processing here ...
    logger.info('Restarted the %s service%s.', services, plural)

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

$ python app.py start foo
INFO start Started the 'foo' service.

$ python app.py stop foo bar
INFO stop Stopped the 'foo' and 'bar' services.

$ python app.py restart foo bar baz
INFO restart Restarted the 'foo', 'bar' and 'baz' services.

Первое слово - это уровень регистрации, а второе слово - это имя модуля или пакета, в котором было зарегистрировано событие.

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

$ python app.py --log-level DEBUG start foo
DEBUG start About to start foo
INFO start Started the 'foo' service.

$ python app.py --log-level DEBUG stop foo bar
DEBUG stop About to stop 'foo' and 'bar'
INFO stop Stopped the 'foo' and 'bar' services.

$ python app.py --log-level DEBUG restart foo bar baz
DEBUG restart About to restart 'foo', 'bar' and 'baz'
INFO restart Restarted the 'foo', 'bar' and 'baz' services.

А если мы хотим меньше:

$ python app.py --log-level WARNING start foo
$ python app.py --log-level WARNING stop foo bar
$ python app.py --log-level WARNING restart foo bar baz

В этом случае команды ничего не выводят на консоль, поскольку ничего на уровне WARNING и выше не регистрируется ими.

Графический интерфейс Qt для ведения журнала

Время от времени возникает вопрос о том, как войти в систему в приложении с графическим интерфейсом. Фреймворк Qt является популярным кроссплатформенным UI-фреймворком с привязкой к Python с использованием библиотек PySide2 или PyQt5.

Следующий пример показывает, как вести журнал в графическом интерфейсе Qt. Здесь представлен простой класс QtHandler, который принимает callable, который должен быть слотом в главном потоке, выполняющем обновление GUI. Также создается рабочий поток, чтобы показать, как можно вести журнал в GUI как из самого пользовательского интерфейса (с помощью кнопки для ручной регистрации), так и из рабочего потока, выполняющего работу в фоновом режиме (здесь просто регистрируются сообщения на случайных уровнях со случайными короткими задержками между ними).

Рабочий поток реализован с использованием класса Qt QThread, а не модуля threading, поскольку существуют обстоятельства, когда необходимо использовать QThread, который обеспечивает лучшую интеграцию с другими компонентами Qt.

Код должен работать с последними версиями PySide2 или PyQt5. Вы должны быть в состоянии адаптировать подход к более ранним версиям Qt. Пожалуйста, обратитесь к комментариям в фрагменте кода для получения более подробной информации.

import datetime
import logging
import random
import sys
import time

# Deal with minor differences between PySide2 and PyQt5
try:
    from PySide2 import QtCore, QtGui, QtWidgets
    Signal = QtCore.Signal
    Slot = QtCore.Slot
except ImportError:
    from PyQt5 import QtCore, QtGui, QtWidgets
    Signal = QtCore.pyqtSignal
    Slot = QtCore.pyqtSlot


logger = logging.getLogger(__name__)


#
# Signals need to be contained in a QObject or subclass in order to be correctly
# initialized.
#
class Signaller(QtCore.QObject):
    signal = Signal(str, logging.LogRecord)

#
# Output to a Qt GUI is only supposed to happen on the main thread. So, this
# handler is designed to take a slot function which is set up to run in the main
# thread. In this example, the function takes a string argument which is a
# formatted log message, and the log record which generated it. The formatted
# string is just a convenience - you could format a string for output any way
# you like in the slot function itself.
#
# You specify the slot function to do whatever GUI updates you want. The handler
# doesn't know or care about specific UI elements.
#
class QtHandler(logging.Handler):
    def __init__(self, slotfunc, *args, **kwargs):
        super().__init__(*args, **kwargs)
        self.signaller = Signaller()
        self.signaller.signal.connect(slotfunc)

    def emit(self, record):
        s = self.format(record)
        self.signaller.signal.emit(s, record)

#
# This example uses QThreads, which means that the threads at the Python level
# are named something like "Dummy-1". The function below gets the Qt name of the
# current thread.
#
def ctname():
    return QtCore.QThread.currentThread().objectName()


#
# Used to generate random levels for logging.
#
LEVELS = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
          logging.CRITICAL)

#
# This worker class represents work that is done in a thread separate to the
# main thread. The way the thread is kicked off to do work is via a button press
# that connects to a slot in the worker.
#
# Because the default threadName value in the LogRecord isn't much use, we add
# a qThreadName which contains the QThread name as computed above, and pass that
# value in an "extra" dictionary which is used to update the LogRecord with the
# QThread name.
#
# This example worker just outputs messages sequentially, interspersed with
# random delays of the order of a few seconds.
#
class Worker(QtCore.QObject):
    @Slot()
    def start(self):
        extra = {'qThreadName': ctname() }
        logger.debug('Started work', extra=extra)
        i = 1
        # Let the thread run until interrupted. This allows reasonably clean
        # thread termination.
        while not QtCore.QThread.currentThread().isInterruptionRequested():
            delay = 0.5 + random.random() * 2
            time.sleep(delay)
            level = random.choice(LEVELS)
            logger.log(level, 'Message after delay of %3.1f: %d', delay, i, extra=extra)
            i += 1

#
# Implement a simple UI for this cookbook example. This contains:
#
# * A read-only text edit window which holds formatted log messages
# * A button to start work and log stuff in a separate thread
# * A button to log something from the main thread
# * A button to clear the log window
#
class Window(QtWidgets.QWidget):

    COLORS = {
        logging.DEBUG: 'black',
        logging.INFO: 'blue',
        logging.WARNING: 'orange',
        logging.ERROR: 'red',
        logging.CRITICAL: 'purple',
    }

    def __init__(self, app):
        super().__init__()
        self.app = app
        self.textedit = te = QtWidgets.QPlainTextEdit(self)
        # Set whatever the default monospace font is for the platform
        f = QtGui.QFont('nosuchfont')
        f.setStyleHint(f.Monospace)
        te.setFont(f)
        te.setReadOnly(True)
        PB = QtWidgets.QPushButton
        self.work_button = PB('Start background work', self)
        self.log_button = PB('Log a message at a random level', self)
        self.clear_button = PB('Clear log window', self)
        self.handler = h = QtHandler(self.update_status)
        # Remember to use qThreadName rather than threadName in the format string.
        fs = '%(asctime)s %(qThreadName)-12s %(levelname)-8s %(message)s'
        formatter = logging.Formatter(fs)
        h.setFormatter(formatter)
        logger.addHandler(h)
        # Set up to terminate the QThread when we exit
        app.aboutToQuit.connect(self.force_quit)

        # Lay out all the widgets
        layout = QtWidgets.QVBoxLayout(self)
        layout.addWidget(te)
        layout.addWidget(self.work_button)
        layout.addWidget(self.log_button)
        layout.addWidget(self.clear_button)
        self.setFixedSize(900, 400)

        # Connect the non-worker slots and signals
        self.log_button.clicked.connect(self.manual_update)
        self.clear_button.clicked.connect(self.clear_display)

        # Start a new worker thread and connect the slots for the worker
        self.start_thread()
        self.work_button.clicked.connect(self.worker.start)
        # Once started, the button should be disabled
        self.work_button.clicked.connect(lambda : self.work_button.setEnabled(False))

    def start_thread(self):
        self.worker = Worker()
        self.worker_thread = QtCore.QThread()
        self.worker.setObjectName('Worker')
        self.worker_thread.setObjectName('WorkerThread')  # for qThreadName
        self.worker.moveToThread(self.worker_thread)
        # This will start an event loop in the worker thread
        self.worker_thread.start()

    def kill_thread(self):
        # Just tell the worker to stop, then tell it to quit and wait for that
        # to happen
        self.worker_thread.requestInterruption()
        if self.worker_thread.isRunning():
            self.worker_thread.quit()
            self.worker_thread.wait()
        else:
            print('worker has already exited.')

    def force_quit(self):
        # For use when the window is closed
        if self.worker_thread.isRunning():
            self.kill_thread()

    # The functions below update the UI and run in the main thread because
    # that's where the slots are set up

    @Slot(str, logging.LogRecord)
    def update_status(self, status, record):
        color = self.COLORS.get(record.levelno, 'black')
        s = '<pre><font color="%s">%s</font></pre>' % (color, status)
        self.textedit.appendHtml(s)

    @Slot()
    def manual_update(self):
        # This function uses the formatted message passed in, but also uses
        # information from the record to format the message in an appropriate
        # color according to its severity (level).
        level = random.choice(LEVELS)
        extra = {'qThreadName': ctname() }
        logger.log(level, 'Manually logged!', extra=extra)

    @Slot()
    def clear_display(self):
        self.textedit.clear()


def main():
    QtCore.QThread.currentThread().setObjectName('MainThread')
    logging.getLogger().setLevel(logging.DEBUG)
    app = QtWidgets.QApplication(sys.argv)
    example = Window(app)
    example.show()
    sys.exit(app.exec_())

if __name__=='__main__':
    main()

Ведение журнала в syslog с поддержкой RFC5424

Хотя RFC 5424 датируется 2009 годом, большинство серверов syslog по умолчанию настроены на использование более старого протокола RFC 3164, который появился в 2001 году. Когда logging был добавлен в Python в 2003 году, он поддерживал более ранний (и единственный существующий на тот момент) протокол. С момента выхода RFC5424, поскольку он не был широко распространен в серверах syslog, функциональность SysLogHandler не обновлялась.

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

import datetime
import logging.handlers
import re
import socket
import time

class SysLogHandler5424(logging.handlers.SysLogHandler):

    tz_offset = re.compile(r'([+-]\d{2})(\d{2})$')
    escaped = re.compile(r'([\]"\\])')

    def __init__(self, *args, **kwargs):
        self.msgid = kwargs.pop('msgid', None)
        self.appname = kwargs.pop('appname', None)
        super().__init__(*args, **kwargs)

    def format(self, record):
        version = 1
        asctime = datetime.datetime.fromtimestamp(record.created).isoformat()
        m = self.tz_offset.match(time.strftime('%z'))
        has_offset = False
        if m and time.timezone:
            hrs, mins = m.groups()
            if int(hrs) or int(mins):
                has_offset = True
        if not has_offset:
            asctime += 'Z'
        else:
            asctime += f'{hrs}:{mins}'
        try:
            hostname = socket.gethostname()
        except Exception:
            hostname = '-'
        appname = self.appname or '-'
        procid = record.process
        msgid = '-'
        msg = super().format(record)
        sdata = '-'
        if hasattr(record, 'structured_data'):
            sd = record.structured_data
            # This should be a dict where the keys are SD-ID and the value is a
            # dict mapping PARAM-NAME to PARAM-VALUE (refer to the RFC for what these
            # mean)
            # There's no error checking here - it's purely for illustration, and you
            # can adapt this code for use in production environments
            parts = []

            def replacer(m):
                g = m.groups()
                return '\\' + g[0]

            for sdid, dv in sd.items():
                part = f'[{sdid}'
                for k, v in dv.items():
                    s = str(v)
                    s = self.escaped.sub(replacer, s)
                    part += f' {k}="{s}"'
                part += ']'
                parts.append(part)
            sdata = ''.join(parts)
        return f'{version} {asctime} {hostname} {appname} {procid} {msgid} {sdata} {msg}'

Для полного понимания приведенного выше кода вам потребуется знакомство с RFC 5424, и, возможно, у вас несколько иные потребности (например, в передаче структурных данных в журнал). Тем не менее, приведенный выше код должен быть адаптирован к вашим конкретным потребностям. С помощью приведенного выше обработчика вы передадите структурированные данные, используя что-то вроде этого:

sd = {
    'foo@12345': {'bar': 'baz', 'baz': 'bozz', 'fizz': r'buzz'},
    'foo@54321': {'rab': 'baz', 'zab': 'bozz', 'zzif': r'buzz'}
}
extra = {'structured_data': sd}
i = 1
logger.debug('Message %d', i, extra=extra)

Шаблоны, которых следует избегать

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

Открытие одного и того же файла журнала несколько раз

В Windows, как правило, вы не сможете открыть один и тот же файл несколько раз, так как это приведет к ошибке «файл используется другим процессом». Однако на платформах POSIX вы не получите никаких ошибок, если откроете один и тот же файл несколько раз. Это может быть сделано случайно, например:

  • Добавление обработчика файла более одного раза, который ссылается на один и тот же файл (например, в результате ошибки copy/paste/forget-to-change).

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

  • Форкинг процесса, после которого родительский и дочерний процессы имеют ссылку на один и тот же файл. Это может происходить, например, с помощью модуля multiprocessing.

Открытие файла несколько раз может кажется работать большую часть времени, но на практике может привести к ряду проблем:

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

  • Попытка удалить файл (например, во время ротации файлов) тихо проваливается, потому что на него указывает другая ссылка. Это может привести к путанице и напрасной трате времени на отладку - записи журнала оказываются в неожиданных местах или вообще теряются. Или файл, который должен был быть перемещен, остается на месте и неожиданно увеличивается в размерах, несмотря на то, что ротация на основе размера якобы выполняется.

Для обхода таких проблем используйте приемы, описанные в Ведение журнала в один файл из нескольких процессов.

Использование регистраторов в качестве атрибутов в классе или передача их в качестве параметров

Хотя могут быть необычные случаи, когда вам понадобится это сделать, в общем случае в этом нет смысла, поскольку регистраторы являются синглтонами. Код всегда может получить доступ к данному экземпляру логгера по имени, используя logging.getLogger(name), поэтому передавать экземпляры и хранить их как атрибуты экземпляра бессмысленно. Обратите внимание, что в других языках, таких как Java и C#, логгеры часто являются статическими атрибутами класса. Однако эта схема не имеет смысла в Python, где модуль (а не класс) является единицей декомпозиции программного обеспечения.

Добавление обработчиков, отличных от NullHandler, к регистратору в библиотеке

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

Создание большого количества регистраторов

Логгеры - это синглтоны, которые никогда не освобождаются во время выполнения скрипта, поэтому создание большого количества логгеров будет использовать память, которую потом нельзя будет освободить. Вместо того чтобы создавать логгер на каждый обработанный файл или выполненное сетевое соединение, используйте existing mechanisms для передачи контекстной информации в ваши логи и ограничьте создаваемые логгеры теми, которые описывают области в вашем приложении (обычно модули, но иногда немного более тонкие, чем это).

Другие ресурсы

См.также

Модуль logging

Ссылка на API для модуля протоколирования.

Модуль logging.config

API конфигурации для модуля протоколирования.

Модуль logging.handlers

Полезные обработчики, включенные в модуль протоколирования.

Basic Tutorial

Advanced Tutorial

Вернуться на верх