Кулинарная книга для ведения журнала

Автор:

Винай Саджип <винай Саджип в интернет-магазине red-dove>

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

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

Множественные вызовы logging.getLogger('someLogger') возвращают ссылку на один и тот же объект logger. Это верно не только в рамках одного и того же модуля, но и для разных модулей, если это выполняется в одном и том же процессе интерпретатора 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.

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

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

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

Пользовательская обработка уровней

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

  • Отправлять сообщения о серьезности INFO и WARNING на адрес sys.stdout

  • Отправлять сообщения со степенью серьезности ERROR и выше на адрес sys.stderr

  • Отправлять сообщения с уровнем серьезности DEBUG и выше в файл app.log

Предположим, вы настроили ведение журнала с помощью следующего JSON-файла:

{
    "version": 1,
    "disable_existing_loggers": false,
    "formatters": {
        "simple": {
            "format": "%(levelname)-8s - %(message)s"
        }
    },
    "handlers": {
        "stdout": {
            "class": "logging.StreamHandler",
            "level": "INFO",
            "formatter": "simple",
            "stream": "ext://sys.stdout"
        },
        "stderr": {
            "class": "logging.StreamHandler",
            "level": "ERROR",
            "formatter": "simple",
            "stream": "ext://sys.stderr"
        },
        "file": {
            "class": "logging.FileHandler",
            "formatter": "simple",
            "filename": "app.log",
            "mode": "w"
        }
    },
    "root": {
        "level": "DEBUG",
        "handlers": [
            "stderr",
            "stdout",
            "file"
        ]
    }
}

Эта конфигурация выполняет почти то, что мы хотим, за исключением того, что sys.stdout будут отображаться сообщения со степенью серьезности ERROR и выше, а также сообщения INFO и WARNING. Чтобы предотвратить это, мы можем настроить фильтр, который исключает такие сообщения, и добавить его в соответствующий обработчик. Это можно настроить, добавив раздел filters параллельно разделам formatters и handlers:

{
    "filters": {
        "warnings_and_below": {
            "()" : "__main__.filter_maker",
            "level": "WARNING"
        }
    }
}

и изменяем раздел в обработчике stdout, чтобы добавить его:

{
    "stdout": {
        "class": "logging.StreamHandler",
        "level": "INFO",
        "formatter": "simple",
        "stream": "ext://sys.stdout",
        "filters": ["warnings_and_below"]
    }
}

Фильтр - это просто функция, поэтому мы можем определить filter_maker (заводскую функцию) следующим образом:

def filter_maker(level):
    level = getattr(logging, level)

    def filter(record):
        return record.levelno <= level

    return filter

Это преобразует переданный строковый аргумент в числовой уровень и возвращает функцию, которая возвращает True только в том случае, если уровень переданной записи находится на указанном уровне или ниже него. Обратите внимание, что в этом примере я определил filter_maker в тестовом скрипте main.py, который я запускаю из командной строки, поэтому его модуль будет __main__ - отсюда и __main__.filter_maker в конфигурации фильтра . Вам нужно будет изменить это, если вы определите это в другом модуле.

С добавлением фильтра мы можем запустить main.py, который в полном объеме является:

import json
import logging
import logging.config

CONFIG = '''
{
    "version": 1,
    "disable_existing_loggers": false,
    "formatters": {
        "simple": {
            "format": "%(levelname)-8s - %(message)s"
        }
    },
    "filters": {
        "warnings_and_below": {
            "()" : "__main__.filter_maker",
            "level": "WARNING"
        }
    },
    "handlers": {
        "stdout": {
            "class": "logging.StreamHandler",
            "level": "INFO",
            "formatter": "simple",
            "stream": "ext://sys.stdout",
            "filters": ["warnings_and_below"]
        },
        "stderr": {
            "class": "logging.StreamHandler",
            "level": "ERROR",
            "formatter": "simple",
            "stream": "ext://sys.stderr"
        },
        "file": {
            "class": "logging.FileHandler",
            "formatter": "simple",
            "filename": "app.log",
            "mode": "w"
        }
    },
    "root": {
        "level": "DEBUG",
        "handlers": [
            "stderr",
            "stdout",
            "file"
        ]
    }
}
'''

def filter_maker(level):
    level = getattr(logging, level)

    def filter(record):
        return record.levelno <= level

    return filter

logging.config.dictConfig(json.loads(CONFIG))
logging.debug('A DEBUG message')
logging.info('An INFO message')
logging.warning('A WARNING message')
logging.error('An ERROR message')
logging.critical('A CRITICAL message')

И после запуска этого вот так:

python main.py 2>stderr.log >stdout.log

Мы видим, что результаты соответствуют ожиданиям:

$ more *.log
::::::::::::::
app.log
::::::::::::::
DEBUG    - A DEBUG message
INFO     - An INFO message
WARNING  - A WARNING message
ERROR    - An ERROR message
CRITICAL - A CRITICAL message
::::::::::::::
stderr.log
::::::::::::::
ERROR    - An ERROR message
CRITICAL - A CRITICAL message
::::::::::::::
stdout.log
::::::::::::::
INFO     - An INFO message
WARNING  - A WARNING message

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

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

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 очень прост: ему передается очередь и некоторые обработчики, и он запускает внутренний поток, который прослушивает свою очередь на наличие записей журнала, отправленных из 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!

Примечание

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

Изменено в версии 3.5: До Python 3.5 QueueListener всегда передавал каждое сообщение, полученное из очереди, каждому обработчику, с помощью которого оно было инициализировано. (Это было связано с тем, что предполагалось, что фильтрация по уровням выполняется на другой стороне, где очередь заполнена.) Начиная с версии 3.5, это поведение можно изменить, передав ключевое слово argument 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 is a Gist который предоставляет базовые файлы для запуска вышеуказанных функций с помощью Supervisor. Он состоит из следующих файлов:

Файл

Цель

prepare.sh

Скрипт на Bash для подготовки среды к тестированию

supervisor.conf

Файл конфигурации супервизора, содержащий записи для прослушивателя и многопроцессорного веб-приложения

ensure_app.sh

Сценарий Bash для обеспечения работы супервизора с вышеуказанной конфигурацией

log_listener.py

Программа-прослушиватель сокетов, которая получает лог-события и записывает их в файл

main.py

Простое веб-приложение, которое выполняет ведение журнала через сокет, подключенный к прослушивателю

webapp.json

Файл конфигурации в формате JSON для веб-приложения

client.py

Скрипт на Python для работы с веб-приложением

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

Чтобы протестировать эти файлы, выполните следующие действия в среде POSIX:

  1. Загрузите the Gist в виде ZIP-архива с помощью кнопки Download ZIP.

  2. Распакуйте вышеуказанные файлы из архива в новый каталог.

  3. В каталоге scratch запустите bash prepare.sh, чтобы все было готово. При этом создается подкаталог run, содержащий файлы, относящиеся к супервизору, и файлы журналов, и подкаталог venv, содержащий виртуальную среду, в которую установлены bottle, gunicorn и supervisor .

  4. Запустите bash ensure_app.sh, чтобы убедиться, что супервизор запущен с вышеуказанной конфигурацией.

  5. Запустите venv/bin/python client.py, чтобы запустить веб-приложение, что приведет к записи записей в журнал.

  6. Просмотрите файлы журнала в подкаталоге run. Вы должны увидеть самые последние строки журнала в файлах, соответствующих шаблону app.log*. Они не будут располагаться в каком-либо определенном порядке, поскольку обрабатывались одновременно разными рабочими процессами недетерминированным образом.

  7. Вы можете завершить работу прослушивателя и веб-приложения, выполнив команду venv/bin/supervisorctl -c supervisor.conf shutdown.

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

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

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

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

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

Когда вы создаете экземпляр LoggerAdapter, вы передаете ему экземпляр Logger и объект, подобный dict, который содержит вашу контекстную информацию. Когда вы вызываете один из методов ведения журнала в экземпляре 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 контекстная информация добавляется в выходные данные журнала. Ему передаются аргументы message и keyword вызова logging, и он передает обратно (потенциально) измененные версии этих аргументов для использования в вызове базового регистратора. Реализация этого метода по умолчанию оставляет сообщение в покое, но вставляет «дополнительный» ключ в аргумент ключевого слова, значением которого является объект, подобный dict, передаваемый конструктору. Конечно, если вы передали «дополнительный» аргумент ключевого слова в вызове адаптера, он будет автоматически перезаписан.

Преимущество использования «extra» заключается в том, что значения в объекте, подобном dict, объединяются в __dict__ экземпляра LogRecord, что позволяет вам использовать настраиваемые строки с вашими экземплярами Formatter, которые знают о ключах dict- похожий объект. Если вам нужен другой метод, например, если вы хотите добавить контекстную информацию в строку сообщения, вам просто нужно создать подкласс 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, для передачи контекстной информации

Вам не нужно передавать фактический dict в LoggerAdapter - вы могли бы передать экземпляр класса, который реализует __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', type=int, 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. Каждый журнал, относящийся к конкретному веб-приложению, будет содержать только записи журнала только для этого веб-приложения, и информация о запросе будет отображаться в журнале последовательно (т.е. информация в каждом фиктивном запросе всегда будет отображаться вместе в строке журнала). Это иллюстрируется следующим выводом командной строки:

~/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.

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

Иногда вы хотите, чтобы файл журнала увеличился до определенного размера, затем откройте новый файл и войдите в него. Возможно, вы захотите сохранить определенное количество этих файлов, и когда их будет создано достаточно много, чередуйте файлы таким образом, чтобы количество файлов и их размер оставались ограниченными. Для этого случая пакет ведения журнала предоставляет 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, потому что внутренне пакет протоколирования использует %-форматирование для объединения строки формата и переменных аргументов. Это невозможно изменить при сохранении обратной совместимости, поскольку все вызовы протоколирования, которые присутствуют в существующем коде, будут использовать строки в формате %.

Однако существует способ, с помощью которого вы можете использовать форматирование {}- и $- для создания ваших индивидуальных сообщений журнала. Напомним, что для сообщения вы можете использовать произвольный объект в качестве строки формата сообщения и что пакет ведения журнала вызовет 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 log(self, level, msg, /, *args, stacklevel=1, **kwargs):
        if self.isEnabledFor(level):
            msg, kwargs = self.process(msg, kwargs)
            self.logger.log(level, Message(msg, args), **kwargs,
                            stacklevel=stacklevel+1)

logger = StyleAdapter(logging.getLogger(__name__))

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

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

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

Настройка LogRecord

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

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

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

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

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 не дает желаемого результата.

Создание подкласса обработчика очередей и QueueListener - пример ZeroMQ

Подкласс QueueHandler

Вы можете использовать подкласс 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

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

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)

Создание подкласса обработчика очереди и QueueListener- пример pynng

Аналогично описанному выше разделу, мы можем реализовать прослушиватель и обработчик, используя pynng, который является привязкой Python к NNG, объявленной как духовный преемник ZeroMQ. Следующие фрагменты иллюстрируют, что вы можете протестировать их в среде, в которой установлен pynng. Просто для разнообразия сначала мы представим прослушиватель.

Подкласс QueueListener

import json
import logging
import logging.handlers

import pynng

DEFAULT_ADDR = "tcp://localhost:13232"

interrupted = False

class NNGSocketListener(logging.handlers.QueueListener):

    def __init__(self, uri, /, *handlers, **kwargs):
        # Have a timeout for interruptability, and open a
        # subscriber socket
        socket = pynng.Sub0(listen=uri, recv_timeout=500)
        # The b'' subscription matches all topics
        topics = kwargs.pop('topics', None) or b''
        socket.subscribe(topics)
        # We treat the socket as a queue
        super().__init__(socket, *handlers, **kwargs)

    def dequeue(self, block):
        data = None
        # Keep looping while not interrupted and no data received over the
        # socket
        while not interrupted:
            try:
                data = self.queue.recv(block=block)
                break
            except pynng.Timeout:
                pass
            except pynng.Closed:  # sometimes hit when you hit Ctrl-C
                break
        if data is None:
            return None
        # Get the logging event sent from a publisher
        event = json.loads(data.decode('utf-8'))
        return logging.makeLogRecord(event)

    def enqueue_sentinel(self):
        # Not used in this implementation, as the socket isn't really a
        # queue
        pass

logging.getLogger('pynng').propagate = False
listener = NNGSocketListener(DEFAULT_ADDR, logging.StreamHandler(), topics=b'')
listener.start()
print('Press Ctrl-C to stop.')
try:
    while True:
        pass
except KeyboardInterrupt:
    interrupted = True
finally:
    listener.stop()

Подкласс QueueHandler

import json
import logging
import logging.handlers
import time
import random

import pynng

DEFAULT_ADDR = "tcp://localhost:13232"

class NNGSocketHandler(logging.handlers.QueueHandler):

    def __init__(self, uri):
        socket = pynng.Pub0(dial=uri, send_timeout=500)
        super().__init__(socket)

    def enqueue(self, record):
        # Send the record as UTF-8 encoded JSON
        d = dict(record.__dict__)
        data = json.dumps(d)
        self.queue.send(data.encode('utf-8'))

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

logging.getLogger('pynng').propagate = False
handler = NNGSocketHandler(DEFAULT_ADDR)
logging.basicConfig(level=logging.DEBUG,
                    handlers=[logging.StreamHandler(), handler],
                    format='%(levelname)-8s %(name)10s %(message)s')
levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
          logging.CRITICAL)
logger_names = ('myapp', 'myapp.lib1', 'myapp.lib2')
msgno = 1
while True:
    # Just randomly select some loggers and levels and log away
    level = random.choice(levels)
    logger = logging.getLogger(random.choice(logger_names))
    logger.log(level, 'Message no. %5d' % msgno)
    msgno += 1
    delay = random.random() * 2 + 0.5
    time.sleep(delay)

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

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

Ниже приведен пример словаря конфигурации ведения журнала - он взят из documentation on the Django project. Этот словарь передается в dictConfig(), чтобы ввести конфигурацию в действие.:

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

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

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

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

import gzip
import logging
import logging.handlers
import os
import shutil

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

def rotator(source, dest):
    with open(source, 'rb') as f_in:
        with gzip.open(dest, 'wb') as f_out:
            shutil.copyfileobj(f_in, f_out)
    os.remove(source)


rh = logging.handlers.RotatingFileHandler('rotated.log', maxBytes=128, backupCount=5)
rh.rotator = rotator
rh.namer = namer

root = logging.getLogger()
root.setLevel(logging.INFO)
root.addHandler(rh)
f = logging.Formatter('%(asctime)s %(message)s')
rh.setFormatter(f)
for i in range(1000):
    root.info(f'Message no. {i + 1}')

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

$ ls rotated.log*
rotated.log       rotated.log.2.gz  rotated.log.4.gz
rotated.log.1.gz  rotated.log.3.gz  rotated.log.5.gz
$ zcat rotated.log.1.gz
2023-01-20 02:28:17,767 Message no. 996
2023-01-20 02:28:17,767 Message no. 997
2023-01-20 02:28:17,767 Message no. 998

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

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

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

Вставка спецификации в сообщения, отправляемые системному обработчику

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

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

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

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

    'ASCII section\ufeffUnicode section'
    

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

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

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

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

Внедрение структурированного ведения журнала

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

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

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(), что обработчик ведения журнала будет создан путем вызова этой функции:

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, потому что внутренне пакет протоколирования использует %-форматирование для объединения строки формата и переменных аргументов. Это невозможно изменить при сохранении обратной совместимости, поскольку все вызовы протоколирования, которые присутствуют в существующем коде, будут использовать строки в формате %.

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

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

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

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

Обратитесь к справочной документации по setLogRecordFactory() и 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.

  • Помимо фильтров, этот метод также можно использовать для настройки пользовательских обработчиков и форматировщиков. Смотрите Определяемые пользователем объекты для получения дополнительной информации о том, как ведение журнала поддерживает использование пользовательских объектов в своей конфигурации, и смотрите другой рецепт из кулинарной книги Настройка обработчиков с помощью 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 не будут взаимодействовать с пользователями и их выполнение не займет много времени, и что частота регистрируемых сообщений будет не настолько высокой, чтобы перегружать пользователя сообщениями, и что допустимо, чтобы сообщения передавались по одному, а не по очереди. в то же время приведенный ниже пример реализации ожидает, пока будет произнесено одно сообщение, прежде чем будет обработано следующее, и это может привести к тому, что другие обработчики будут вынуждены ждать. Вот краткий пример, демонстрирующий подход, который предполагает, что доступен пакет espeak TTS:

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, будет регистрироваться на уровнях ОШИБОК и КРИТИЧЕСКИХ значений - в противном случае он будет регистрироваться только на уровнях ОТЛАДКИ, ИНФОРМАЦИИ и ПРЕДУПРЕЖДЕНИЯ.

Скрипт просто настраивает оформление 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

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

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

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

Отправка сообщений журнала на электронную почту с буферизацией

Чтобы проиллюстрировать, как вы можете отправлять лог-сообщения по электронной почте, чтобы на каждое электронное письмо отправлялось определенное количество сообщений, вы можете создать подкласс BufferingHandler. В следующем примере, который вы можете адаптировать в соответствии с вашими конкретными потребностями, представлен простой тестовый инструментарий, который позволяет вам запускать скрипт с аргументами командной строки, указывающими, что вам обычно требуется для отправки данных по SMTP. (Запустите загруженный скрипт с аргументом -h, чтобы просмотреть обязательные и необязательные аргументы.)

import logging
import logging.handlers
import smtplib

class BufferingSMTPHandler(logging.handlers.BufferingHandler):
    def __init__(self, mailhost, port, username, password, fromaddr, toaddrs,
                 subject, capacity):
        logging.handlers.BufferingHandler.__init__(self, capacity)
        self.mailhost = mailhost
        self.mailport = port
        self.username = username
        self.password = password
        self.fromaddr = fromaddr
        if isinstance(toaddrs, str):
            toaddrs = [toaddrs]
        self.toaddrs = toaddrs
        self.subject = subject
        self.setFormatter(logging.Formatter("%(asctime)s %(levelname)-5s %(message)s"))

    def flush(self):
        if len(self.buffer) > 0:
            try:
                smtp = smtplib.SMTP(self.mailhost, self.mailport)
                smtp.starttls()
                smtp.login(self.username, self.password)
                msg = "From: %s\r\nTo: %s\r\nSubject: %s\r\n\r\n" % (self.fromaddr, ','.join(self.toaddrs), self.subject)
                for record in self.buffer:
                    s = self.format(record)
                    msg = msg + s + "\r\n"
                smtp.sendmail(self.fromaddr, self.toaddrs, msg)
                smtp.quit()
            except Exception:
                if logging.raiseExceptions:
                    raise
            self.buffer = []

if __name__ == '__main__':
    import argparse

    ap = argparse.ArgumentParser()
    aa = ap.add_argument
    aa('host', metavar='HOST', help='SMTP server')
    aa('--port', '-p', type=int, default=587, help='SMTP port')
    aa('user', metavar='USER', help='SMTP username')
    aa('password', metavar='PASSWORD', help='SMTP password')
    aa('to', metavar='TO', help='Addressee for emails')
    aa('sender', metavar='SENDER', help='Sender email address')
    aa('--subject', '-s',
       default='Test Logging email from Python logging module (buffering)',
       help='Subject of email')
    options = ap.parse_args()
    logger = logging.getLogger()
    logger.setLevel(logging.DEBUG)
    h = BufferingSMTPHandler(options.host, options.port, options.user,
                             options.password, options.sender,
                             options.to, options.subject, 10)
    logger.addHandler(h)
    for i in range(102):
        logger.info("Info index = %d", i)
    h.flush()
    h.close()

Если вы запустите этот скрипт и ваш SMTP-сервер настроен правильно, вы увидите, что он отправляет одиннадцать электронных писем указанному вами адресату. В первых десяти электронных письмах будет по десять лог-сообщений, а в одиннадцатом - два сообщения. Это составляет 102 сообщения, как указано в скрипте.

Форматирование времени с использованием UTC (GMT) с помощью настройки

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

import logging
import time

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

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

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 - это популярный кроссплатформенный фреймворк пользовательского интерфейса с привязками на Python, использующий библиотеки PySide2 или PyQt5.

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

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

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

import datetime
import logging
import random
import sys
import time

# Deal with minor differences between different Qt packages
try:
    from PySide6 import QtCore, QtGui, QtWidgets
    Signal = QtCore.Signal
    Slot = QtCore.Slot
except ImportError:
    try:
        from PyQt6 import QtCore, QtGui, QtWidgets
        Signal = QtCore.pyqtSignal
        Slot = QtCore.pyqtSlot
    except ImportError:
        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)
            try:
                if random.random() < 0.1:
                    raise ValueError('Exception raised: %d' % i)
                else:
                    level = random.choice(LEVELS)
                    logger.log(level, 'Message after delay of %3.1f: %d', delay, i, extra=extra)
            except ValueError as e:
                logger.exception('Failed: %s', e, 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')
        if hasattr(f, 'Monospace'):
            f.setStyleHint(f.Monospace)
        else:
            f.setStyleHint(f.StyleHint.Monospace)  # for Qt6
        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()
    if hasattr(app, 'exec'):
        rc = app.exec()
    else:
        rc = app.exec_()
    sys.exit(rc)

if __name__=='__main__':
    main()

Запись в системный журнал с поддержкой RFC5424

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

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

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)

Как обращаться с регистратором как с выходным потоком

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

import logging

class LoggerWriter:
    def __init__(self, logger, level):
        self.logger = logger
        self.level = level

    def write(self, message):
        if message != '\n':  # avoid printing bare newlines, if you like
            self.logger.log(self.level, message)

    def flush(self):
        # doesn't actually do anything, but might be expected of a file-like
        # object - so optional depending on your situation
        pass

    def close(self):
        # doesn't actually do anything, but might be expected of a file-like
        # object - so optional depending on your situation. You might want
        # to set a flag so that later calls to write raise an exception
        pass

def main():
    logging.basicConfig(level=logging.DEBUG)
    logger = logging.getLogger('demo')
    info_fp = LoggerWriter(logger, logging.INFO)
    debug_fp = LoggerWriter(logger, logging.DEBUG)
    print('An INFO message', file=info_fp)
    print('A DEBUG message', file=debug_fp)

if __name__ == "__main__":
    main()

Когда этот скрипт запускается, он выводит

INFO:demo:An INFO message
DEBUG:demo:A DEBUG message

Вы также можете использовать LoggerWriter для перенаправления sys.stdout и sys.stderr, выполнив что-то вроде этого:

import sys

sys.stdout = LoggerWriter(logger, logging.INFO)
sys.stderr = LoggerWriter(logger, logging.WARNING)

Вы должны сделать это после настройки ведения журнала в соответствии с вашими потребностями. В приведенном выше примере это выполняется вызовом basicConfig() (используя значение sys.stderr до того, как оно будет перезаписано экземпляром LoggerWriter). Тогда вы получили бы такой результат:

>>> print('Foo')
INFO:demo:Foo
>>> print('Bar', file=sys.stderr)
WARNING:demo:Bar
>>>

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

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

sys.stderr = LoggerWriter(logger, logging.WARNING)
1 / 0

затем запуск скрипта приводит к

WARNING:demo:Traceback (most recent call last):

WARNING:demo:  File "/home/runner/cookbook-loggerwriter/test.py", line 53, in <module>

WARNING:demo:
WARNING:demo:main()
WARNING:demo:  File "/home/runner/cookbook-loggerwriter/test.py", line 49, in main

WARNING:demo:
WARNING:demo:1 / 0
WARNING:demo:ZeroDivisionError
WARNING:demo::
WARNING:demo:division by zero

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

class BufferingLoggerWriter(LoggerWriter):
    def __init__(self, logger, level):
        super().__init__(logger, level)
        self.buffer = ''

    def write(self, message):
        if '\n' not in message:
            self.buffer += message
        else:
            parts = message.split('\n')
            if self.buffer:
                s = self.buffer + parts.pop(0)
                self.logger.log(self.level, s)
            self.buffer = parts.pop()
            for part in parts:
                self.logger.log(self.level, part)

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

WARNING:demo:Traceback (most recent call last):
WARNING:demo:  File "/home/runner/cookbook-loggerwriter/main.py", line 55, in <module>
WARNING:demo:    main()
WARNING:demo:  File "/home/runner/cookbook-loggerwriter/main.py", line 52, in main
WARNING:demo:    1/0
WARNING:demo:ZeroDivisionError: division by zero

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

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

Многократное открытие одного и того же файла журнала

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

См.также

Модуль logging

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

Модуль logging.config

API настройки для модуля ведения журнала.

Модуль logging.handlers

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

Basic Tutorial

Advanced Tutorial

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