Логирование в Питоне

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

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

Все про українське ІТ в Телеграмі — підписуйтеся на канал редакції DOU

👍ПодобаєтьсяСподобалось0
До обраногоВ обраному0
LinkedIn



4 коментарі

Підписатись на коментаріВідписатись від коментарів Коментарі можуть залишати тільки користувачі з підтвердженими акаунтами.

скомпилировал питон на scratchbox для arm платформыпробовал запустить скрипты, использующие import loggingоказывается, модуль logging не скомпилировался.за отсутствием времени быстро заменил весь logging на printвсе заработало...

Инстанс логгеры — действительно хорошая вещь, в специфических задачах могут очень помочь увидеть что, собственно, происходит... и почему не то, чего хотелось ожидать:) Но мне вот только [-2:] не очень нравится... Если объектов создается чуток больше восьми, то кто из них пишет в лог уже не уследишь. Главное об этом помнить.

Симпатично. У меня в коде обычно модули маленькие, поэтому я использую module-level logger.

import logginglog = logging.getLogger(name)

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

познавательно. спасибо.

Підписатись на коментарі