22 сент. 2008 г.

Логгинг в базу или борьба с рекурсией

Как-то понадобилось мне сделать логгинг в базу для модуля logging. Сразу видна очевидная проблема: внутри такого обработчика идёт сохранения в базу некоторыми принятыми в проекте средствами, которые сами используют logging. В результате обработчик рекусивно будет вызывать себя и зацикливаться. Понятно, что можно отбросить привычные средства и сделать либо логгинг своими средствами без использования стандартного пакета logging, либо в базу писать низкоуровневым кодом, который logging не использует. Но это всё не интересно и ведёт за собой неудобства в использовании.
Первая мысль была выставлять флаг в обработчике перед записью в базу и снимать его после. Но это без ухищрений не будет работать в многопоточном приложении, а ведь есть ещё и обработчики сигналов. А нельзя ли определить, что обработчик был вызван из самого себя? Оказывается, можно — с помощью средств работы со стеком интерпретатора в модуле inspect. Достаточно убедиться, чтобы текущего метода не было в стеке вызовов. Сам фрейм не подходит для сравнения, так как он создаётся новый на каждый вызов, но можно сравнивать объекты кода. Первая версия на базе inspect.stack() оказалась достаточно медленной, а ведь запись в лог — это то, что используется постоянно. Дело в том, что эта функция подготавливает много лишней информации, которая нам не нужна. Зато проход по стеку "вручную" оказался достаточно быстрым, примерно на 2 порядка быстрее варианта с inspect.stack():
def isRecursive():
   '''Returns whether it's recursive call of caller function.'''
   frame = inspect.currentframe().f_back
   try:
       code = frame.f_code
       while True:
           frame = frame.f_back
           if frame is None:
               break
           if frame.f_code is code:
               return True
       return False
   finally:
       del frame
Сам обработчик достаточно прост (здесь storage — произвольное хранилище, в моём случае оно сделано на базе SQLAlchemy):
class DBServiceLogHandler(logging.Handler):

   def __init__(self, storage):
       logging.Handler.__init__(self)
       self._storage = storage

   def emit(self, record):
       # We can't check this in filter() method, since recursive call is from
       # emit, not filter.
       if isRecursive():
           return
       traceback = None
       if record.exc_info:
           # It's used by logging to cache
           if not record.exc_text:
               record.exc_text = self.formatException(record.exc_info)
           traceback = record.exc_text
       entry = LogEntry(name=record.name, level=record.levelno,
                        message=record.getMessage(), traceback=traceback)
       try:
           self._storage.store(entry)
       except self._storage.Error:
           logger.exception('Error logging to DB (%s):', record.getMessage())
       self._storage.clear()

2 комментария:

Alexander Lyabah комментирует...

Моя, небольшая, идея на тему логов в БД
http://www.lyabah.com/?p=180

возможно вам будет интересно

Unknown комментирует...

Мне, как правило, приходится работать с большими логами. Текстовые удобно читать из терминала, в базе - для быстрого доступа и фильтрации. Пока что я не вижу в моих задачах применения для логов в CSV.