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

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

Поэтому появилось довольно много библиотек для решения этой проблемы. Я не буду даже пытаться их перечислять, остановлюсь на стандартном пакете logging. Он весьма мощен, допускает гибкую настройку, иерархические категории, вывод логов в любой мыслимый источник, указание желаемого форматирования сообщений. И, главное, logging — это стандарт, включенный в любую поставку Питона. Архитектурно он вырос из знаменитого log4j (Apache Group), который имеет множество клонов на других языках программирования.

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

Перейду к опыту применения. Первый же вопрос, который возникает — как отличать записи из разных мест. Поясню на примере.

# module sample_mod
import logging
def a():
    logging.debug("I'm here")
    ...
def b():
    logging.debug("I'm here")
    ... 

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

# module sample_mod
def a():
    logging.debug("sample_mod:a - I'm here")
    ... 

тоже не хочется. К счастью, сразу же на ум приходят иерархически организованные логеры. В нашем случае они создаются через вызов функции getLogger. Поскольку я пишу с интенсивным использованием ООП, дальнейшие примеры будут строиться на классах, а не функциях. Попытаемся создать класс A, в котором заведем для логера: один для класса целиком, второй для отдельной инстанции.

# module sample_mod
class A(object):
    cls_logger = logging.getLogger('sample_mod.A')
    def __init__(self):
        self.inst_logger = logging.getLogger('sample_mod.A.0x%008x'%id(self))
        ...                              

    def f(self):
        self.cls_logger.debug("class logger message")                             

    def g(self):
        self.inst_logger.debug("instance logger message") 

Отлично. Теперь мы можем писать что-то вроде:

>>> a = A()
>>> a.f()
DEBUG:sample_mod.A:class logger message
>>> a.g()
DEBUG:sample_mod.A.0x009fb650:class logger message 

Вроде бы все хорошо, но есть пара “но”. Первое очевидно — нужно явно указывать имя логера, хотя оно собирается из имени модуля, имени класса (и адреса инстанции для второго случая). Все это можно спросить у Питона, но вот незадача — если в конструкторе все уже есть и мы можем просто написать

self.inst_logger = logging.getLogger('%s.%s.0x%008x'%(self.__class__.__module__, self.__class__.__name__,id(self)))

то при создании логера для класса спросить __class__ просто не у кого.

Есть еще одна проблема: поскольку не предусмотрено удаление логеров, то для каждого нового объекта делается новый, а старые продолжают жить. Мало того, что неограниченно растет память, так еще и создание занимает ощутимое количество времени. Я подсмотрел, как это делают в SQLAlchemy:

def _get_instance_name(instance):
    return instance.__class__.__module__ + "." + instance.__class__.__name__ + ".0x.." + hex(id(instance))[-2:] 

def instance_logger(instance):
    return logging.getLogger(_get_instance_name(instance))            

def class_logger(cls):
    return logging.getLogger(cls.__module__ + "." + cls.__name__) 

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

class A(object):
    def __init__(self):
        self.inst_logger = instance_logger(self)
        ...                              

A.cls_logger = class_logger(A) 

Все почти хорошо. Только мне очень не нравится модифицирование класса после создания при добавлении cls_logger. Не потому, что считаю подобные действия абсолютным злом — наоборот, очень часто пользуюсь. Причина другая — легко не заметить этот код. Да и привык я описывать переменные класса в его начале. Мысль завертелась вокруг инструментирования кода. В который раз посетовав на отсутствие декораторов класса (не ждать же Python 2.6), начал строить все на метаклассах. Но с ними тоже все не хорошо. Во-первых, пришлось бы явно указывать метакласс или навязывать свой базовый. Во-вторых и главных: как только в предках появляется два разных метакласса, Питону становится нехорошо и он впадает в ступор. И, конечно же, в моем проекте это вылезло почти сразу. Я уже начал огорченно менять иерархию наследования, добавляя ненужные костыли, как вспомнил о дескрипторах. Решение оказалось очень простым:

class class_logger(object):
    '''Class logger descriptor'''
    def __init__(self):
        self._logger = None                      

    def __get__(self, instance, owner):
        if self._logger is None:
            self._logger = logging.getLogger(owner.__module__ + "." + owner.__name__)
        return self._logger                      

class instance_logger(object):
    '''Instance logger descriptor'''
    def __init__(self):
        self._logger = None                      

    def __get__(self, instance, owner):
        if self._logger is None:
            self._logger = logging.getLogger(_get_instance_name(instance))
        return self._logger 

а пример использования весьма лаконичным:

class A(object):
    cls_logger = class_logger()
    inst_logger = instance_logger()                      

    def __init__(self):
        ... 

Преимущества очевидны: логер (как для класса, так и для объекта) описывается одной строкой, никаких дополнительных трюков не требуется, конструктор класса не содержит никакого дополнительного кода. К тому же все прекрасно видно, а параметрами для class_logger и instance_logger можно передавать какие-нибудь настроечные параметры. На этом стоит поставить точку и привести получившийся код целиком (он до смешного короток):

# module logutils
import sys
import new
import logging             

#copy public content of logging package
for name in dir(logging):
    if not name.startswith('_'):
        globals()[name] = getattr(logging, name)             

def _get_instance_name(instance):
    return instance.__class__.__module__ + "." + instance.__class__.__name__ + ".0x.." + hex(id(instance))[-2:]  

class class_logger(object):
    '''Class logger descriptor'''
    def __init__(self):
        self._logger = None             

    def __get__(self, instance, owner):
        if self._logger is None:
            self._logger = logging.getLogger(owner.__module__ + "." + owner.__name__)
        return self._logger             

class instance_logger(object):
    '''Instance logger descriptor'''
    def __init__(self):
        self._logger = None             

    def __get__(self, instance, owner):
        if self._logger is None:
            self._logger = logging.getLogger(_get_instance_name(instance))
        return self._logger