Сохранение времени в базе данных

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

Я не буду здесь рассматривать все возможные варианты корректной работы со временем. Покажу лишь насколько просто можно реализовать самый распространённый вариант — хранение в базе в UTC — на примере SQLAlchemy. Для этого достаточно определить новый тип колонки:

from sqlalchemy import types
from dateutil.tz import tzutc
from datetime import datetime

class UTCDateTime(types.TypeDecorator):

    impl = types.DateTime

    def process_bind_param(self, value, engine):
        if value is not None:
            return value.astimezone(tzutc()).replace(tzinfo=None)

    def process_result_value(self, value, engine):
        if value is not None:
            return datetime(value.year, value.month, value.day,
                            value.hour, value.minute, value.second,
                            value.microsecond, tzinfo=tzutc())

Теперь вы можете сохранять время с произвольной зоной, все преобразования будут сделаны автоматически. Но сохранить время без зоны не получится — метод astimezone() выбросит исключение ValueError, что позволит избежать случайных ошибок.

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

Как-то понадобилось мне сделать логгинг в базу для модуля 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()