Руководство по ведению журналов

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

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

import logging
import auxiliary_module

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

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

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

import logging

# create logger
module_logger = logging.getLogger('spam_application.auxiliary')

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

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

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

Вывод выглядит следующим образом:

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

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

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

import logging
import threading
import time

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

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

if __name__ == '__main__':
    main()

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

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

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

Несколько обработчиков и форматеров

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

import logging

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

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

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

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

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

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

import logging

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

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

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

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

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

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

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

а в файле вы увидите что-то вроде

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

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

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

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

Настройка обработки уровней

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

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

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

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

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

который, при запуске, даст:

MainThread: Look out!

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

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

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

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

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)

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

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

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

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

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

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

Иногда вы хотите, чтобы файл журнала рос до определенного размера, затем открыть новый файл и вести в нем журнал. Возможно, вы хотите сохранить определенное количество этих файлов, а когда будет создано столько файлов, выполнить ротацию файлов, чтобы количество файлов и размер файлов оставались ограниченными. Для этой модели использования пакет ведения журнала предоставляет 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, единственным способом форматирования сообщений с переменным содержимым было использование метода %-форматирования. С тех пор Python получил два новых подхода к форматированию: string.Template (добавлено в Python 2.4) и str.format() (добавлено в Python 2.6).

Протоколирование (начиная с версии 3.2) обеспечивает улучшенную поддержку этих двух дополнительных стилей форматирования. Класс Formatter был расширен, чтобы принимать дополнительный необязательный ключевой параметр с именем style. По умолчанию он равен '%', но возможны и другие значения: '{' и '$', которые соответствуют другим двум стилям форматирования. Обратная совместимость поддерживается по умолчанию (как можно ожидать), но путем явного указания параметра 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(), который вызывается со словарем, содержащим атрибуты, которые должны быть добавлены в LogRecord. Обычно это вызывается, когда подходящий словарь был получен по сети (например, в формате pickle через SocketHandler или в формате JSON через HTTPHandler).

Это обычно означало, что если вам нужно что-то особенное сделать с LogRecord, вам нужно было сделать одно из следующего.

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

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

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

logger = logging.getLogger(__name__)

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

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

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

old_factory = logging.getLogRecordFactory()

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

logging.setLogRecordFactory(record_factory)

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

Наследование от QueueHandler и QueueListener — пример с ZeroMQ

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

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)

Наследование от QueueHandler и QueueListener — пример с pynng

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

# listener.py
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 happens 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()

# sender.py
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)
# Make sure the process ID is in the output
logging.basicConfig(level=logging.DEBUG,
                    handlers=[logging.StreamHandler(), handler],
                    format='%(levelname)-8s %(name)10s %(process)6s %(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)

$ python sender.py
DEBUG         myapp    613 Message no.     1
WARNING  myapp.lib2    613 Message no.     2
CRITICAL myapp.lib2    613 Message no.     3
WARNING  myapp.lib2    613 Message no.     4
CRITICAL myapp.lib1    613 Message no.     5
DEBUG         myapp    613 Message no.     6
CRITICAL myapp.lib1    613 Message no.     7
INFO     myapp.lib1    613 Message no.     8
(and so on)

$ python sender.py
INFO     myapp.lib2    657 Message no.     1
CRITICAL myapp.lib2    657 Message no.     2
CRITICAL      myapp    657 Message no.     3
CRITICAL myapp.lib1    657 Message no.     4
INFO     myapp.lib1    657 Message no.     5
WARNING  myapp.lib2    657 Message no.     6
CRITICAL      myapp    657 Message no.     7
DEBUG    myapp.lib1    657 Message no.     8
(and so on)

$ python listener.py
Press Ctrl-C to stop.
DEBUG         myapp    613 Message no.     1
WARNING  myapp.lib2    613 Message no.     2
INFO     myapp.lib2    657 Message no.     1
CRITICAL myapp.lib2    613 Message no.     3
CRITICAL myapp.lib2    657 Message no.     2
CRITICAL      myapp    657 Message no.     3
WARNING  myapp.lib2    613 Message no.     4
CRITICAL myapp.lib1    613 Message no.     5
CRITICAL myapp.lib1    657 Message no.     4
INFO     myapp.lib1    657 Message no.     5
DEBUG         myapp    613 Message no.     6
WARNING  myapp.lib2    657 Message no.     6
CRITICAL      myapp    657 Message no.     7
CRITICAL myapp.lib1    613 Message no.     7
INFO     myapp.lib1    613 Message no.     8
DEBUG    myapp.lib1    657 Message no.     8
(and so on)

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

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

Дополнительную информацию о данной конфигурации можно найти в соответствующем разделе документации 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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

if __name__ == '__main__':
    main()

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

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

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

Поскольку это поведение некорректно, некорректный код вставки BOM будет удален из Python 3.2.4 и более поздних версий. Однако он не будет заменён, и если вам нужно создать сообщения, совместимые с RFC 5424 и содержащие BOM, необязательную чисто 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, и ваш демон syslog может пожаловаться.

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

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

import json
import logging

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

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

_ = StructuredMessage   # optional, to improve readability

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

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

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

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

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

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

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)

>>> __ = 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)

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

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

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

import logging
import logging.config
import sys

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

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

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

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

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

changed: hello

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

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

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

Настройка форматирования исключений

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

import logging

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

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

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

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

if __name__ == '__main__':
    main()

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

28/01/2015 07:21:23|INFO|Sample message|
28/01/2015 07:21:23|ERROR|ZeroDivisionError: integer division or modulo by zero|'Traceback (most recent call last):\n  File "logtest7.py", line 30, in main\n    x = 1 / 0\nZeroDivisionError: integer division or modulo by zero'|

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

Произнесение сообщений логирования

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

import logging
import subprocess
import sys

class TTSHandler(logging.Handler):
    def emit(self, record):
        msg = self.format(record)
        # Speak slowly in a female English voice
        cmd = ['espeak', '-s150', '-ven+f3', msg]
        p = subprocess.Popen(cmd, stdout=subprocess.PIPE,
                             stderr=subprocess.STDOUT)
        # wait for the program to finish
        p.communicate()

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

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

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

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

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

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

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

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

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

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

Вот скрипт:

import logging
from logging.handlers import MemoryHandler
import sys

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

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

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

    return decorator

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

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

decorated_foo = log_if_errors(logger)(foo)

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

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

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

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

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

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

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

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

import logging
import logging.config
import time

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

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

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

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

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

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

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

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

import logging
import sys

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

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

    def __exit__(self, et, ev, tb):
        if self.level is not None:
            self.logger.setLevel(self.old_level)
        if self.handler:
            self.logger.removeHandler(self.handler)
        if self.handler and self.close:
            self.handler.close()
        # implicit return of None => don't swallow exceptions

Если вы укажете значение уровня, уровень журнала устанавливается на это значение в области блока 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.

Шаблон начального кода для приложения командной строки

Вот пример, который показывает, как вы можете:

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

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

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

Рабочий поток реализован с использованием класса QThread Qt, а не модуля 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()

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

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

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

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

class SysLogHandler5424(logging.handlers.SysLogHandler):

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

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

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

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

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

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

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

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

Иногда вам нужно взаимодействовать с 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

Избегаемые шаблоны

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

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