Есть достаточно большой проект. много модулей, коммандлайн скрипты, демоны, django UI. Хочется сделать гибкое логирование всего и вся с возможностью конфигурирования не лазая в код. Может у кого-нибудь уже это решено и этот кто-нибудь поделится правильным концептом?
Пока общее направление мыслей такое: использовать logging с иерархией логгеров/хэндлеров/форматтеров, описаных в конфиге, загружаемом приложениями с помощью fileConfig(). Но хотелось бы реальный пример такого подхода для (желательно) аналогичного проекта.
Андрей Светлов
Ноя. 10, 2010 10:57:04
примерно так и делали.
Единственно замечание - имена логеров.
Похоже, порядок есть только при одной схеме: имена должны совпадать с полным путем к классу объекта.
Т.е. если есть класс A в модуле pack.subpack.mod, имя модуля должно быть ‘pack.subpack.mod.A’. Это легко автоматизировать написав свой дескриптор.
Можно использовать в качестве имен просто полные пути к модулям, если классов в них немного.
При произвольном именовании начинается форменный бедлам.
shupg
Ноя. 10, 2010 11:33:30
Я бы посоветовал пользовать метаклассы для прикрутки логирования к функциям.
class MetaLogging(type):
def __call__(cls, *args, **kargs):
for attr in dir(cls):
value = getattr(cls, attr)
if isinstance(value, MethodType):
if attr.startswith('__'):
setattr(cls, attr, trace(value))
elif attr.startswith('_'):
setattr(cls, attr, debug(value))
else:
setattr(cls, attr, info(value))
return super(MetaLogging, cls).__call__(*args, **kargs)
где info, debug и trace - декораторы логирования
Андрей Светлов
Ноя. 10, 2010 11:35:24
Ээээ. А что ваши trace-debug-info будут делать? Т.е. какая с них польза?
shupg
Ноя. 10, 2010 12:07:07
Для автоматической прикрутки декораторов.
простой пример функции:
def debug(func):
def _logFunctionCall(*args,**kwargs):
log.debug("%s(%s, %s)" % (func.func_name, args, kwargs))
return func(*args, **kwargs)
return _logFunctionCall
Андрей Светлов
Ноя. 10, 2010 12:20:26
Ага. Положим, декораторы я писать умею.
Следующий вопрос: а что мне делать с этой простыней - кто кого вызвал и с какими параметрами?
Вы для чего вообще логи используете?
shupg
Ноя. 10, 2010 16:55:15
Мы используем логи для истории. Истории того, как там все было, какой поток чего когда вызывал и все такое. Мне кажется это полезно, вот на каком уровне такое логировать - это вопрос.
Если уж на то пошло: а Вы зачем логи пишите?
Андрей Светлов
Ноя. 10, 2010 17:40:38
Вопрос хороший. И непростой.
Логировать все вызовы подряд не приходилось. Да и зачем? Если уж очень нужно - есть settrace, которая может записать все вызовы.
На тех проектах, где я участвовал - хватало стандартного профайлера, чтобы увидеть кто ест время.
Длинная простыня логов, по моему скромному мнению, в этом не поможет.
В логи нужно писать то, что потом будут читать люди. Скорее, им будет интересно, что код сначала не смог, к примеру, получить данные из тернета по ошибке, которая прилагается - а затем поток успешно помер. Или еще что-нибудь странное.
И эти записи лежат _внутри_ функций-методов, лог пишется тогда, когда это именно нужно.
Даже в режиме дебага не стоит писать все подряд. Есть, наверное, гении - но я не могу внятно прочитать простыню вызовов и найти в ней поломку - когда простыня на несколько мегабайтов (это я еще скромно сказал - видел разные логи).
Итак, простая схема, выработанная практикой.
Источник логов совпадает с полным путем к коду, который пишет в лог.
Сначала - не логируем ничего. Ну кроме самых напрашивающихся кандидатов - типа к БД подключится не получилось, ошибка прилагается.
Дальше - по нужде. Возник вопрос, как себя повела система при крахе или нестандартном поведении - добавляем логи. Разносим их по уровням - debug или таки error.
Кажется, в любом большом проекте так делают. Только, наверное, не описывают процесс - я ни разу не видел, приходилось доходить самому.
Логи - для того чтобы их читали люди. А человеки - не монстры. Поэтому логи должны быть по возможности лаконичными. Баланс вырабатывается для каждого проекта заново. Но логировать все подряд - априорно моветон.
ЗЫ. Обращение на ВЫ - это просто потому, что мы не знакомы. Мне кажется, что так будет вежливей.
Ed
Ноя. 10, 2010 20:44:37
У нас пока получилась такая схема:
Был написан простенький project.logging.getLogger(name), который при вызове из __main__ читает конфигурацию из /etc/project/logging.conf, ~/.project/logging.conf и /etc/project/%(name)s-logging.conf при наличии оных. Ну и возвращает логгер для запрашиваемого имени, естественно. Есть также configure_logging, которому конфиг файл можно передать, если нужно.
В каждом модуле пишем LOG = getLogger(__name__) и потом эту глобальную переменную юзаем где нужно. Мне наличие глобальной переменной не очень нравится, но альтернативы, которые я вижу, еще хуже. В классах в __init__ можно делать self.logger = getLogger(self.__module__), либо юзать глобальный LOG, так же, как и в других местах. Была идея нарисовать mixin Loggable для классов и декоратор loggable для функций, которые должны были добавлять logger в namespace объекта или функции соответственно, но подумавши не стал этого делать. explicit is better than implicit.
Что скажете?
PS: Андрей, можно про дескриптор поподробнее?
Андрей Светлов
Ноя. 11, 2010 11:43:23
про дескриптор была древняя статья
http://www.developers.org.ua/archives/asvetlov/2007/09/22/python-logging/Глобальные логеры - это нормально. Они такие по определению - потому что все равно регистрируются в глобальной структуре внутри logging.
Использующий логирование код не должен этот логер настраивать. Получил и пиши в него - и все.
Настройка - отдельное дело. Осуществляется на старте приложения, а не на импорте библиотеки. Так правильно - и заодно избавляет от неприятных ситуаций.
Например, когда для одного пользователя библиотеки нужна одна конфигурация, а для другого - иная. Это могут быть две разные программы, юниттесты и т.д.
С ненастроенными логерами такой проблемы нет.
Настройка делается по именам логеров, так что импортировать библиотечный код не нужно.