Логирование в Django или детективная история одного ма-а-аленького, но очень гордого велосипеда
Жил-был некий проект... Да, на Джанго. Развивался потихоньку. И вот в один далеко не прекрасный момент один из пользователей сотворил что-то непотребное, но сознаваться в этом категорически отказался - "а оно само!". А потом и ещё раз, и снова с потерей "очень важных данных". Нет, с защитой от дурака там всё в порядке было, система терроризирует пользователя подтверждениями не хуже винды. Но бывают отдельные особо упорные личности... Начальство сказало - документируй все действия юзверя! И всё заверте........
1. Добавляем в лог дополнительную отладочную информацию: имя пользователя, в сессии которого произошло событие, URI, имя модуля, где произошло событие, имя функции и даже номер строки.
Если посмотрим в документацию по модулю logging, то увидим, что кроме, собственно, сообщения, в методы класса Logger можно передать ещё и необязательный аргумент extra, в который можно положить всё, что душе угодно, в виде словаря. А в формат строки лога включить ключи этого словаря и всё будет прекрасно!
Хм-м... Прекрасно?!
logger.debug('Какая-то сволочь удалила докУмент', extra={'username': name_of_svolotch, 'uri': uri})
Вот после такого вызова в формате можем использовать $(username)s и $(uri)s. Ну а имя функции, номер строки, имя модуля и сам логгер предоставляет. Полностью список атрибутов, доступных "из коробки", можно посмотреть вот тут: Документация по модулю logging
А что, если в формате что-то указано, а в LogRecord этого нет, потому как в extra положить забыли? Exception, а не запись в лог - вот что! И это первые грабли. Про "некрасиво" я уже и не говорю даже. Впрочем, с "некрасиво" ещё можно поработать. Дело в том, что Джанга в любую вьюху отдаёт request - экземпляр класса HttpRequest
Что же там такого интересного, в этом объекте? Если у нас включены приложения django.contrib.auth и django.contrib.sessions, то у нас есть request.user и request.session. Имя пользователя может быть как в session (словарь) и/или в user. Ещё в request нас интересует path. Это, фактически, URL без доменной части. В принципе, это то, что нам и нужно! Всё в одном объекте! Значит, делаем так:
logger.debug('Какая-то сволочь удалила докУмент', extra={'request': request})
Минуточку... А как мы в format string на request сошлёмся? Там ведь нельзя написать $(request.user.name)s, поскольку форматирование строки лога осуществляется совершенно примитивным образом. Заглянув в logging/__init__.py мы увидим что-то вроде s = self._fmt % record.__dict__ (взято из Formatter.format)
Что ж, взглянем на документацию по модулю logging повнимательнее. Принимает сообщение метод класса Logger, а куда же оно девается внутри? Внимательно посмотрим на конфигурацию логгера: там кроме самого логгера, возможно, есть один или несколько форматтеров и как минимум один handler. Formatter просто форматирует строку. Может быть, напишем свой форматтер? Да, идея годная. Но вот захотелось нам ещё в базу данных лог писать и/или использовать удалённое логирование по http, например. И request в этом случае всё равно остаётся объектом... То есть, в форматтере мы опишем способ извлечения нужных данных из request, но для передачи по http данные вообще никак не фоматируются! А работа с БД в модуле logging и вовсе не предусмотрена. Впрочем, про логирование в БД несколько позже, это отдельная печальная история.
А теперь вернёмся к вопросу, что же с сообщением делает экземпляр класса Logger. А он просто создаёт LogRecord, включая в этот объект и данные из аргумента extra и по очереди скармливает этот, по сути, словарь всем зарегистрированным handler'ам! Тут есть некоторая "вилка". Либо пишем свою реализацию класса Logger, которая будет уметь распаковать request нужным нам образом, либо сделать распаковку в handler'е. Забегая вперёд, сразу скажу, что закончилась эта опупея созданием своего Logger'а.
Но в тот момент я ещё не знал, что подменить Logger НАСТОЛЬКО просто! И решил таки понаписать своих handler'ов на все случаи.
Вот как-то так:
class NewFileHandler(RotatingFileHandler):
def __init__(self, *args, **kwargs):
super(NewFileHandler, self).__init__(*args, **kwargs)
self.setFormatter(Formatter(logMessageFormat))
def emit(self, record):
return super(NewFileHandler, self).emit(get_extended_record(record))
class NewHTTPHandler(HTTPHandler):
def emit(self, record):
return super(NewHTTPHandler, self).emit(get_extended_record(record))
def mapLogRecord(self, record):
d = {}
for k in record.__dict__:
val = record.__dict__[k]
if isinstance(val, unicode):
d[k] = val.encode(localenv.default_coding)
else:
d[k] = str(val)
return d
Видно, что получились они довольно компактными. Но тут случилась пара неприятностей. Во-первых, попытка из модуля подцепить эти хэндлеры из модуля core в settings.py потерпела сокрушительнейшее поражение, ибо... в core была волшебная строчка import project.settings. То есть я попытался сотворить страшное странное - я попытался осуществить циклический импорт! Но опытного костылеходного велосипедиста это, конечно же, не остановило. Для обхода такой ситуации был создан в составе проекта отдельный модуль log. Вторая неприятность. Формат лога формировался динамически, в зависимости от флагов DEBUG и PRODUCTION. Формировался где? Пра-а-авильно! В settings.py, что привело к созданию ещё и отдельного модуля localenv.py. Но вот если настройки локального окружения, различные для девелопмента и для продакшна вынести в отедельный модуль идея явно правильная, то запихиавть туда ещё и формат лога... Потому формат лога тоже был перенесён в log. Отсюда и переопределение __init__, в который добавилась вот эта загадочная строчка:
self.setFormatter(Formatter(logMessageFormat))
Костыль? Костыль! Однозначно! Формат должен быть определён всё-таки в settings! Но log уже импортируется в settings, а значит попытка импорта чего-либо из project.settings внутри log привдёт... Пра-а-авильно! Отсюда этот безобразный костыль.
В огстальном хэндлеры предельно примитивны. NewFileHandler вызывает функцию, формирующую нужные атрибуты в лог-записи и отправляет её своему родителю. NewHTTPHandler занимается ровно тем же. За небольшим исключением - ему не нужно форматировать запись. Ему нужно перекодировать все атрибуты в тот вид, в котором они могут быть переданы по протоколу http. Собственно, это метод mapLogRecord - в нём определяются и кодируются нужные атрибутв. Поскольку запись в нужном виде формируется в get_extended_record, то просто кодируем и отправляем.
Ну вот мы и добрались до самого "вкусного". Внимание! Людей, стардающих костылевелосипедобоязнью прошу реализацию функции get_extended_record не смотреть!!! X-D
Но для особо отчаянных - вот она! ;)
def get_extended_record(record):
if not hasattr(record, 'timestamp'):
# Если этот атрибут уже есть - запись уже обработана, возвращаем её.
# Иначе - допиливаем до нужного состояния, в том числе весь юникод кодируем в utf-8
if record.exc_info:
etype, evalue, tb = record.exc_info
exc_text = decode_exception_info(etype, evalue, tb).encode(localenv.default_coding)
else:
exc_text = ''
module_path = record.pathname
project_path = path.normpath(path.join(path.dirname(path.abspath(__file__)), '..'))
module_path = module_path.replace(project_path, "").replace(".py", ".") + record.funcName
extra_log_data = { # Добавляем некоторые дополнительные атрибуты
'worker': socket.gethostname(),
'module_path': module_path,
'logformat': logMessageFormat,
'dateformat': logDateFormat,
'timestamp': datetime.now().strftime(logDateFormat),
'exc_text': u'',
'exc_info': u'',
'exception': exc_text,
}
if hasattr(record, 'request'):
user_id = record.request.user.id
if user_id:
user_name = record.request.user.login
else:
user_name = "?"
user_ip = record.request.META.get('REMOTE_ADDR', '') or record.request.META.get('HTTP_X_FORWARDED_FOR', '')
extra_log_data.update({'user_id': user_id, 'user_name': user_name, 'user_ip': user_ip, })
# Обязательно выкусываем из записи request, т.к оттуда можно вытащить CSRF_TOKEN и ещё много интересного
del record.request
else: # Если забыли передать request - вставляем заглушку. Чтобы обязательно увидеть и добавить в extra
extra_log_data.update({'user_id': None, 'user_name': u"NoRequest", 'user_ip': u"?.?.?.?", })
record.__dict__.update(extra_log_data)
for k in record.__dict__:
if isinstance(record.__dict__[k], basestring):
record.__dict__[k] = localenv.try_unicode(record.__dict__[k])
В принципе, в каких-либо комментариях особо не нуждается, но всё же... Первый момент это исключения. Если в тексте exception'а присутствует кириллица, то вместо этого самого exception'а стабильно будем видеть UnicodeDecodeError. А в самом логе - строчки, состоящие из \x## или \u####. Потому из модуля traceback была вытащена реализация decode_exception_info и слегка "допилена" до использования локальной кодировки по-умолчанию. Да, знаю, кодировку можно и через стандартные средства модуля sys сменить, но выглядит сам процесс... жутковато. Нам мой взгляд. Второй момент: атрибут worker. Дело в том, что для пущей устойчивости несколько экземпляров проекта были развёрнуты на нескольких физических серверах, на каждом из которых был набор виртуалок. worker - ссылка на конкретный экземпляр рабочего процесса, которая позволяла идентифицировать в логе сообщение от конкретной виртуальной машины на конкретном физ. сервере. Третий момент это добавленные в состав атрибутов logformat и dateformat. Это тоже костыль. Удалённый логгер представлял собой примитивнейшее django-приложение, которое получало методом POST словарь, извлекало оттуда logformat и dateformat и заканчивалось всё это той самой строчкой s = logformat % dict, которая отадавлась логгеру, формат которого был задан, как %(msg)s. Атрибут timestamp некоторым образом дублирует asctime, но он тут используется как маркер того, что запись уже имеет нужный вид... Примитивно, да?
Я выше писал про логирование в базу данных... Внимательные уже заметили, что в тех фрагментах кода, что приведены выше, нет ни одного обращения к БД! Да, это не просто так. Те же грабли с циклическим импортом! Модуль log импортируется в project.settings. К чему приведёт попытка импортировать хоть одну модель внутри модуля log? Пра-а-авильно!!! Но тут цепочка (точнее, колечко) импортов получилась довольно длинной и процесс осознания "WTF?!?!" занял неприлично много времени. НЕ НАСТУПАЙТЕ НА ЭТИ ГРАБЛИ! ЭТО - БОЛЬНО!!! X-DDD В итоге, логирование в базу данных осуществляется удалённым логгером. То, что он получает по http, пишется и в файл, и в БД.
Сразу возникает вопрос, а зачем конкретному worker'у тоже писать лог в файл? Да тут просто всё - лень человеческая. По общему логу находим проблему и если она в конкретном worker'е - колупаем дальше только его лог! Когда будет реализован просмотр лога в базе данных, необходимость в такой изыбточности отпадёт, логирование в файл в самом проекте можно будет просто выключить, убрав из конфигурации лога ссылку на соотвествующий хэндлер.
Вроде, всё замечательно! Ну, относительно, конечно. Если не принимать во внимание плотность костылёфф и велосипедофф на строчку кода...
И было замечательно ровно до одного далеко не замечательного момента, когда понадобилось добавить логирование в ряд функций, куда request "не доходил", а пользователя таки нужно было идентифицировать... Первый порыв - сделать "проброс" request куда только можно. Оказалось, возможно это не везде. Второй порыв - выбросить к % собачьим отовсюду extra={'request': request}. Подумал-подумал и решил, что правильнее будет второе решение. К тому моменту я уже открыл для себя ещё одну полезную функцию из модуля logging: называется она просто и незатейливо setLoggerClass.
По каковому поводу все настройки логирования вновь были возвращены в project.settings, модуль log был выкинут из проекта, а в модуле core появился класс RequestLogger
Всех костыле-велосипедо-неустойчивых вновь прошу дальше не смотреть! )))
Вот он, потомок славного класса Logger!
class RequestLogger(Logger):
def findCaller(self): # Переопределим findCaller, чтобы он ещё и request из стека добывал
"""
Find the stack frame of the caller so that we can note the source
file name, line number and function name.
"""
f = currentframe()
# On some versions of IronPython, currentframe() returns None if
# IronPython isn't run with -X:Frames.
if f is not None:
f = f.f_back
rv = None
req = None
while f:
co = f.f_code
# Если ещё не нашли точку вызова и текущий фрейм стека уже не в модуле logging...
if rv is None and os.path.normcase(co.co_filename) != loggingsrcfile:
rv = (co.co_filename, f.f_lineno, co.co_name)
# А тут смотрим, нет ли в текущем фрейме request'а
if req is None and 'request' in f.f_locals and isinstance(f.f_locals['request'], HttpRequest):
req = f.f_locals['request']
if rv and req:
break # Нашли всё, что хотели - можно выходить!
else:
f = f.f_back # Ещё не всё нашли, берём следующий фрейм
else: # А если цикли пробежали до конца и чего-то не нашли... То чем богаты, тем и рады! ;)
rv = rv if rv else ("(unknown file)", 0, "(unknown function)")
return rv + (req,)
def _log(self, level, msg, args, exc_info=None, extra=None):
"""
Low-level logging routine which creates a LogRecord and then calls
all the handlers of this logger to handle the record.
"""
# IronPython doesn't track Python frames, so findCaller raises an
# exception on some versions of IronPython. We trap it here so that
# IronPython can use logging.
if extra is None:
extra = {}
if 'request' in extra: # Если кто-то заблотливый положил request в extra...
request = extra['request'] # ... Извлекаем request ...
del extra['request'] # ... и убираем его из extra, он там не нужен.
try: # Соответственно, вызываем немодифицированный (оригинальный) findCaller
fn, lno, func = super(RequestLogger, self).findCaller()
except ValueError:
fn, lno, func = ("(unknown file)", 0, "(unknown function)")
else:
fn, lno, func, request = self.findCaller()
module_path = fn
module_path = module_path.replace(project_path, "").replace(".py", "")
if exc_info:
if not isinstance(exc_info, tuple):
exc_info = sys.exc_info()
exc_text = decode_exception_info(*exc_info)
else:
exc_text = u""
worker = socket.gethostname()
user_id = request.user.id if request and hasattr(request.user, 'id') else None
user_name = request.user.login if user_id else u"?"
user_ip = request.META.get('REMOTE_ADDR', '') or \
request.META.get('HTTP_X_FORWARDED_FOR', '') if request else u"?.?.?.?"
req_extra = {
'timestamp': time.time(),
'user_id': user_id,
'user_name': user_name,
'user_ip': user_ip,
'level_name': _levelNames[level],
'worker': worker,
'module_path': module_path,
'func_name': func,
'line_no': lno,
'log_msg': msg % try_unicode(args) + exc_text
}
# Закидываем запись в БД
Log.objects.create(**req_extra)
extra.update(req_extra)
exc_info = None # Трэйсбэк уже лежит в log_msg, качественно декодированный, без кракозябр...
record = self.makeRecord(self.name, level, fn, lno, msg, args, exc_info, func, extra)
self.handle(record)
Собственно, тут видно, что пришлось переопределить всего 2 метода! findCaller и _log
С _log становится всё ясно, если посмотреть на класс Logger в модуле logging - вызов любого метода логирования упирается в этот метод! Кстати, замечу, здесь появилось и логирование в базу данных. Просто удивительно, как просто и органично это получилось в данной реализации! Одной строчкой!
Log.objects.create(**req_extra)
Да, и это _всё_)))
Попутно: все вызовы c extra={'request': request} можем оставить как есть, они уйдут потом, при очередном рефакторинге. В любом месте вызываем logger.info('Пользователь что-то натворил!') - и видим, кто, что и _где_ сделал! Вот тут, кстати, пара слов про findCaller. В оригинале этот метод выковыривает из стека место вызова логгера. Лёгким движением руки попутно из стека достаём request, если он не был передан явно! Реализация получилась совсем чуть-чуть длиннее оригинала и ненамного дольше работает. Зато логировать стало удобно! ОЧЕНЬ УДОБНО! ;-)))
Ах, да! Чуть не забыл! Обязательно надо сделать вот так:
# Собственно, переопределяем класс логера.
setLoggerClass(RequestLogger)
# Перехватываем логирование у джанги
django.core.handlers.base.logger.__class__ = RequestLogger
При этом, джанга почему-то игнорирует смену класса (не разбирался ещё, честно говоря), потому делается это в 2 строчки - во второй влезаем непосредственно внутрь ядра Джанги. Впрочем, это вполне безопасно, на мой взгляд.
И да, от HTTPHandler всё-таки придётся порождать новый класс... Но это можно сделать прямо перед настройками логирования в project.settigs. Он очень маленький:
# Если хотим отправить сообщение о событии во внешний логгер, то нужно подготовить данные...
class NewHTTPHandler(HTTPHandler):
def mapLogRecord(self, record):
return {'id': logID, 'event_data': json.dumps(record.__dict__)}
То есть тупо сериализуем всё содержимое LogRecord и закидываем удалённому логгеру. Кстати, там тоже может присутствовать строчка Log.objects.create(**record), где record десериализуется прямо из запроса!
Что же имеем в итоге?
1. Вызов логера предельно прост, не нужно никаких дополнительных параметров!
2. Логирование осуществляется как в файл, так и в базу данных
3. При кластеризации проекта имеем собственный лог для каждого узла и суммарный - через удалённый логгер.
4. Можно выключить (закомментировав одн строчку) логирование в базу данных приложения и оставить логирование в базу данных удалённого логгера. Более того, для девелопмента предпочтителен лог в базе данных проекта, для продакшна - в базе данных удалённого логгера. То есть, можно ввести соответсвующую настройку в localenv.py.
5. У нас есть удалённый логгер! В настоящее время он допиливается под сбор логов от нескольких разных приложений, при чём написанных не только на питоне.
Только не спрашивайте, чем меня не устроил django-sentry, который делает практически то же самое! Во-первых, у проекта отключена джанго-админка (_категорическое_ требование заказчика!), во-вторых, нет необходимости подключать сторонние компоненты, всё и так у меня в ядре проекта. В-третьих, я попутно создал удалённый логгер, пригодный для использования в целом комплексе софта. Он уже использутся для сбора логов ещё из пары проектов, один из которых написан на PHP. Это, кстати, и послужило причиной смены сериализатора с питоновского cPickle на JSON...
P/S/ Данный текст написан прежде всего для себя. Но если кто-то найдёт здесь что-то полезное для себя - буду только рад! :-)
1. Добавляем в лог дополнительную отладочную информацию: имя пользователя, в сессии которого произошло событие, URI, имя модуля, где произошло событие, имя функции и даже номер строки.
Если посмотрим в документацию по модулю logging, то увидим, что кроме, собственно, сообщения, в методы класса Logger можно передать ещё и необязательный аргумент extra, в который можно положить всё, что душе угодно, в виде словаря. А в формат строки лога включить ключи этого словаря и всё будет прекрасно!
Хм-м... Прекрасно?!
logger.debug('Какая-то сволочь удалила докУмент', extra={'username': name_of_svolotch, 'uri': uri})
Вот после такого вызова в формате можем использовать $(username)s и $(uri)s. Ну а имя функции, номер строки, имя модуля и сам логгер предоставляет. Полностью список атрибутов, доступных "из коробки", можно посмотреть вот тут: Документация по модулю logging
А что, если в формате что-то указано, а в LogRecord этого нет, потому как в extra положить забыли? Exception, а не запись в лог - вот что! И это первые грабли. Про "некрасиво" я уже и не говорю даже. Впрочем, с "некрасиво" ещё можно поработать. Дело в том, что Джанга в любую вьюху отдаёт request - экземпляр класса HttpRequest
Что же там такого интересного, в этом объекте? Если у нас включены приложения django.contrib.auth и django.contrib.sessions, то у нас есть request.user и request.session. Имя пользователя может быть как в session (словарь) и/или в user. Ещё в request нас интересует path. Это, фактически, URL без доменной части. В принципе, это то, что нам и нужно! Всё в одном объекте! Значит, делаем так:
logger.debug('Какая-то сволочь удалила докУмент', extra={'request': request})
Минуточку... А как мы в format string на request сошлёмся? Там ведь нельзя написать $(request.user.name)s, поскольку форматирование строки лога осуществляется совершенно примитивным образом. Заглянув в logging/__init__.py мы увидим что-то вроде s = self._fmt % record.__dict__ (взято из Formatter.format)
Что ж, взглянем на документацию по модулю logging повнимательнее. Принимает сообщение метод класса Logger, а куда же оно девается внутри? Внимательно посмотрим на конфигурацию логгера: там кроме самого логгера, возможно, есть один или несколько форматтеров и как минимум один handler. Formatter просто форматирует строку. Может быть, напишем свой форматтер? Да, идея годная. Но вот захотелось нам ещё в базу данных лог писать и/или использовать удалённое логирование по http, например. И request в этом случае всё равно остаётся объектом... То есть, в форматтере мы опишем способ извлечения нужных данных из request, но для передачи по http данные вообще никак не фоматируются! А работа с БД в модуле logging и вовсе не предусмотрена. Впрочем, про логирование в БД несколько позже, это отдельная печальная история.
А теперь вернёмся к вопросу, что же с сообщением делает экземпляр класса Logger. А он просто создаёт LogRecord, включая в этот объект и данные из аргумента extra и по очереди скармливает этот, по сути, словарь всем зарегистрированным handler'ам! Тут есть некоторая "вилка". Либо пишем свою реализацию класса Logger, которая будет уметь распаковать request нужным нам образом, либо сделать распаковку в handler'е. Забегая вперёд, сразу скажу, что закончилась эта опупея созданием своего Logger'а.
Но в тот момент я ещё не знал, что подменить Logger НАСТОЛЬКО просто! И решил таки понаписать своих handler'ов на все случаи.
Вот как-то так:
class NewFileHandler(RotatingFileHandler):
def __init__(self, *args, **kwargs):
super(NewFileHandler, self).__init__(*args, **kwargs)
self.setFormatter(Formatter(logMessageFormat))
def emit(self, record):
return super(NewFileHandler, self).emit(get_extended_record(record))
class NewHTTPHandler(HTTPHandler):
def emit(self, record):
return super(NewHTTPHandler, self).emit(get_extended_record(record))
def mapLogRecord(self, record):
d = {}
for k in record.__dict__:
val = record.__dict__[k]
if isinstance(val, unicode):
d[k] = val.encode(localenv.default_coding)
else:
d[k] = str(val)
return d
Видно, что получились они довольно компактными. Но тут случилась пара неприятностей. Во-первых, попытка из модуля подцепить эти хэндлеры из модуля core в settings.py потерпела сокрушительнейшее поражение, ибо... в core была волшебная строчка import project.settings. То есть я попытался сотворить страшное странное - я попытался осуществить циклический импорт! Но опытного костылеходного велосипедиста это, конечно же, не остановило. Для обхода такой ситуации был создан в составе проекта отдельный модуль log. Вторая неприятность. Формат лога формировался динамически, в зависимости от флагов DEBUG и PRODUCTION. Формировался где? Пра-а-авильно! В settings.py, что привело к созданию ещё и отдельного модуля localenv.py. Но вот если настройки локального окружения, различные для девелопмента и для продакшна вынести в отедельный модуль идея явно правильная, то запихиавть туда ещё и формат лога... Потому формат лога тоже был перенесён в log. Отсюда и переопределение __init__, в который добавилась вот эта загадочная строчка:
self.setFormatter(Formatter(logMessageFormat))
Костыль? Костыль! Однозначно! Формат должен быть определён всё-таки в settings! Но log уже импортируется в settings, а значит попытка импорта чего-либо из project.settings внутри log привдёт... Пра-а-авильно! Отсюда этот безобразный костыль.
В огстальном хэндлеры предельно примитивны. NewFileHandler вызывает функцию, формирующую нужные атрибуты в лог-записи и отправляет её своему родителю. NewHTTPHandler занимается ровно тем же. За небольшим исключением - ему не нужно форматировать запись. Ему нужно перекодировать все атрибуты в тот вид, в котором они могут быть переданы по протоколу http. Собственно, это метод mapLogRecord - в нём определяются и кодируются нужные атрибутв. Поскольку запись в нужном виде формируется в get_extended_record, то просто кодируем и отправляем.
Ну вот мы и добрались до самого "вкусного". Внимание! Людей, стардающих костылевелосипедобоязнью прошу реализацию функции get_extended_record не смотреть!!! X-D
Но для особо отчаянных - вот она! ;)
def get_extended_record(record):
if not hasattr(record, 'timestamp'):
# Если этот атрибут уже есть - запись уже обработана, возвращаем её.
# Иначе - допиливаем до нужного состояния, в том числе весь юникод кодируем в utf-8
if record.exc_info:
etype, evalue, tb = record.exc_info
exc_text = decode_exception_info(etype, evalue, tb).encode(localenv.default_coding)
else:
exc_text = ''
module_path = record.pathname
project_path = path.normpath(path.join(path.dirname(path.abspath(__file__)), '..'))
module_path = module_path.replace(project_path, "").replace(".py", ".") + record.funcName
extra_log_data = { # Добавляем некоторые дополнительные атрибуты
'worker': socket.gethostname(),
'module_path': module_path,
'logformat': logMessageFormat,
'dateformat': logDateFormat,
'timestamp': datetime.now().strftime(logDateFormat),
'exc_text': u'',
'exc_info': u'',
'exception': exc_text,
}
if hasattr(record, 'request'):
user_id = record.request.user.id
if user_id:
user_name = record.request.user.login
else:
user_name = "?"
user_ip = record.request.META.get('REMOTE_ADDR', '') or record.request.META.get('HTTP_X_FORWARDED_FOR', '')
extra_log_data.update({'user_id': user_id, 'user_name': user_name, 'user_ip': user_ip, })
# Обязательно выкусываем из записи request, т.к оттуда можно вытащить CSRF_TOKEN и ещё много интересного
del record.request
else: # Если забыли передать request - вставляем заглушку. Чтобы обязательно увидеть и добавить в extra
extra_log_data.update({'user_id': None, 'user_name': u"NoRequest", 'user_ip': u"?.?.?.?", })
record.__dict__.update(extra_log_data)
for k in record.__dict__:
if isinstance(record.__dict__[k], basestring):
record.__dict__[k] = localenv.try_unicode(record.__dict__[k])
В принципе, в каких-либо комментариях особо не нуждается, но всё же... Первый момент это исключения. Если в тексте exception'а присутствует кириллица, то вместо этого самого exception'а стабильно будем видеть UnicodeDecodeError. А в самом логе - строчки, состоящие из \x## или \u####. Потому из модуля traceback была вытащена реализация decode_exception_info и слегка "допилена" до использования локальной кодировки по-умолчанию. Да, знаю, кодировку можно и через стандартные средства модуля sys сменить, но выглядит сам процесс... жутковато. Нам мой взгляд. Второй момент: атрибут worker. Дело в том, что для пущей устойчивости несколько экземпляров проекта были развёрнуты на нескольких физических серверах, на каждом из которых был набор виртуалок. worker - ссылка на конкретный экземпляр рабочего процесса, которая позволяла идентифицировать в логе сообщение от конкретной виртуальной машины на конкретном физ. сервере. Третий момент это добавленные в состав атрибутов logformat и dateformat. Это тоже костыль. Удалённый логгер представлял собой примитивнейшее django-приложение, которое получало методом POST словарь, извлекало оттуда logformat и dateformat и заканчивалось всё это той самой строчкой s = logformat % dict, которая отадавлась логгеру, формат которого был задан, как %(msg)s. Атрибут timestamp некоторым образом дублирует asctime, но он тут используется как маркер того, что запись уже имеет нужный вид... Примитивно, да?
Я выше писал про логирование в базу данных... Внимательные уже заметили, что в тех фрагментах кода, что приведены выше, нет ни одного обращения к БД! Да, это не просто так. Те же грабли с циклическим импортом! Модуль log импортируется в project.settings. К чему приведёт попытка импортировать хоть одну модель внутри модуля log? Пра-а-авильно!!! Но тут цепочка (точнее, колечко) импортов получилась довольно длинной и процесс осознания "WTF?!?!" занял неприлично много времени. НЕ НАСТУПАЙТЕ НА ЭТИ ГРАБЛИ! ЭТО - БОЛЬНО!!! X-DDD В итоге, логирование в базу данных осуществляется удалённым логгером. То, что он получает по http, пишется и в файл, и в БД.
Сразу возникает вопрос, а зачем конкретному worker'у тоже писать лог в файл? Да тут просто всё - лень человеческая. По общему логу находим проблему и если она в конкретном worker'е - колупаем дальше только его лог! Когда будет реализован просмотр лога в базе данных, необходимость в такой изыбточности отпадёт, логирование в файл в самом проекте можно будет просто выключить, убрав из конфигурации лога ссылку на соотвествующий хэндлер.
Вроде, всё замечательно! Ну, относительно, конечно. Если не принимать во внимание плотность костылёфф и велосипедофф на строчку кода...
И было замечательно ровно до одного далеко не замечательного момента, когда понадобилось добавить логирование в ряд функций, куда request "не доходил", а пользователя таки нужно было идентифицировать... Первый порыв - сделать "проброс" request куда только можно. Оказалось, возможно это не везде. Второй порыв - выбросить к % собачьим отовсюду extra={'request': request}. Подумал-подумал и решил, что правильнее будет второе решение. К тому моменту я уже открыл для себя ещё одну полезную функцию из модуля logging: называется она просто и незатейливо setLoggerClass.
По каковому поводу все настройки логирования вновь были возвращены в project.settings, модуль log был выкинут из проекта, а в модуле core появился класс RequestLogger
Всех костыле-велосипедо-неустойчивых вновь прошу дальше не смотреть! )))
Вот он, потомок славного класса Logger!
class RequestLogger(Logger):
def findCaller(self): # Переопределим findCaller, чтобы он ещё и request из стека добывал
"""
Find the stack frame of the caller so that we can note the source
file name, line number and function name.
"""
f = currentframe()
# On some versions of IronPython, currentframe() returns None if
# IronPython isn't run with -X:Frames.
if f is not None:
f = f.f_back
rv = None
req = None
while f:
co = f.f_code
# Если ещё не нашли точку вызова и текущий фрейм стека уже не в модуле logging...
if rv is None and os.path.normcase(co.co_filename) != loggingsrcfile:
rv = (co.co_filename, f.f_lineno, co.co_name)
# А тут смотрим, нет ли в текущем фрейме request'а
if req is None and 'request' in f.f_locals and isinstance(f.f_locals['request'], HttpRequest):
req = f.f_locals['request']
if rv and req:
break # Нашли всё, что хотели - можно выходить!
else:
f = f.f_back # Ещё не всё нашли, берём следующий фрейм
else: # А если цикли пробежали до конца и чего-то не нашли... То чем богаты, тем и рады! ;)
rv = rv if rv else ("(unknown file)", 0, "(unknown function)")
return rv + (req,)
def _log(self, level, msg, args, exc_info=None, extra=None):
"""
Low-level logging routine which creates a LogRecord and then calls
all the handlers of this logger to handle the record.
"""
# IronPython doesn't track Python frames, so findCaller raises an
# exception on some versions of IronPython. We trap it here so that
# IronPython can use logging.
if extra is None:
extra = {}
if 'request' in extra: # Если кто-то заблотливый положил request в extra...
request = extra['request'] # ... Извлекаем request ...
del extra['request'] # ... и убираем его из extra, он там не нужен.
try: # Соответственно, вызываем немодифицированный (оригинальный) findCaller
fn, lno, func = super(RequestLogger, self).findCaller()
except ValueError:
fn, lno, func = ("(unknown file)", 0, "(unknown function)")
else:
fn, lno, func, request = self.findCaller()
module_path = fn
module_path = module_path.replace(project_path, "").replace(".py", "")
if exc_info:
if not isinstance(exc_info, tuple):
exc_info = sys.exc_info()
exc_text = decode_exception_info(*exc_info)
else:
exc_text = u""
worker = socket.gethostname()
user_id = request.user.id if request and hasattr(request.user, 'id') else None
user_name = request.user.login if user_id else u"?"
user_ip = request.META.get('REMOTE_ADDR', '') or \
request.META.get('HTTP_X_FORWARDED_FOR', '') if request else u"?.?.?.?"
req_extra = {
'timestamp': time.time(),
'user_id': user_id,
'user_name': user_name,
'user_ip': user_ip,
'level_name': _levelNames[level],
'worker': worker,
'module_path': module_path,
'func_name': func,
'line_no': lno,
'log_msg': msg % try_unicode(args) + exc_text
}
# Закидываем запись в БД
Log.objects.create(**req_extra)
extra.update(req_extra)
exc_info = None # Трэйсбэк уже лежит в log_msg, качественно декодированный, без кракозябр...
record = self.makeRecord(self.name, level, fn, lno, msg, args, exc_info, func, extra)
self.handle(record)
Собственно, тут видно, что пришлось переопределить всего 2 метода! findCaller и _log
С _log становится всё ясно, если посмотреть на класс Logger в модуле logging - вызов любого метода логирования упирается в этот метод! Кстати, замечу, здесь появилось и логирование в базу данных. Просто удивительно, как просто и органично это получилось в данной реализации! Одной строчкой!
Log.objects.create(**req_extra)
Да, и это _всё_)))
Попутно: все вызовы c extra={'request': request} можем оставить как есть, они уйдут потом, при очередном рефакторинге. В любом месте вызываем logger.info('Пользователь что-то натворил!') - и видим, кто, что и _где_ сделал! Вот тут, кстати, пара слов про findCaller. В оригинале этот метод выковыривает из стека место вызова логгера. Лёгким движением руки попутно из стека достаём request, если он не был передан явно! Реализация получилась совсем чуть-чуть длиннее оригинала и ненамного дольше работает. Зато логировать стало удобно! ОЧЕНЬ УДОБНО! ;-)))
Ах, да! Чуть не забыл! Обязательно надо сделать вот так:
# Собственно, переопределяем класс логера.
setLoggerClass(RequestLogger)
# Перехватываем логирование у джанги
django.core.handlers.base.logger.__class__ = RequestLogger
При этом, джанга почему-то игнорирует смену класса (не разбирался ещё, честно говоря), потому делается это в 2 строчки - во второй влезаем непосредственно внутрь ядра Джанги. Впрочем, это вполне безопасно, на мой взгляд.
И да, от HTTPHandler всё-таки придётся порождать новый класс... Но это можно сделать прямо перед настройками логирования в project.settigs. Он очень маленький:
# Если хотим отправить сообщение о событии во внешний логгер, то нужно подготовить данные...
class NewHTTPHandler(HTTPHandler):
def mapLogRecord(self, record):
return {'id': logID, 'event_data': json.dumps(record.__dict__)}
То есть тупо сериализуем всё содержимое LogRecord и закидываем удалённому логгеру. Кстати, там тоже может присутствовать строчка Log.objects.create(**record), где record десериализуется прямо из запроса!
Что же имеем в итоге?
1. Вызов логера предельно прост, не нужно никаких дополнительных параметров!
2. Логирование осуществляется как в файл, так и в базу данных
3. При кластеризации проекта имеем собственный лог для каждого узла и суммарный - через удалённый логгер.
4. Можно выключить (закомментировав одн строчку) логирование в базу данных приложения и оставить логирование в базу данных удалённого логгера. Более того, для девелопмента предпочтителен лог в базе данных проекта, для продакшна - в базе данных удалённого логгера. То есть, можно ввести соответсвующую настройку в localenv.py.
5. У нас есть удалённый логгер! В настоящее время он допиливается под сбор логов от нескольких разных приложений, при чём написанных не только на питоне.
Только не спрашивайте, чем меня не устроил django-sentry, который делает практически то же самое! Во-первых, у проекта отключена джанго-админка (_категорическое_ требование заказчика!), во-вторых, нет необходимости подключать сторонние компоненты, всё и так у меня в ядре проекта. В-третьих, я попутно создал удалённый логгер, пригодный для использования в целом комплексе софта. Он уже использутся для сбора логов ещё из пары проектов, один из которых написан на PHP. Это, кстати, и послужило причиной смены сериализатора с питоновского cPickle на JSON...
P/S/ Данный текст написан прежде всего для себя. Но если кто-то найдёт здесь что-то полезное для себя - буду только рад! :-)