Хозяюшке на заметку: тэгируем логи и ошибки
В этой статье будет рассказано, что, возможно, не так с вашими диагностическими сообщениями, как их можно тэгировать, а главное - зачем это делать.
Диагностические сообщения - это текстовые сообщения об ошибках и логи вашей программы. Так что же с ними не так и как это можно улучшить? Но если ты нетерпелив, то можешь поверить на слово, что проблемы есть, пропустить всю воду и перейти сразу к сути статьи и выводам.
Что не так?
Сперва опишу некоторую проблематику, которую я начал осознавать со временем и с опытом.
Проблема №1
Рассмотрим обработку ошибок. Существует два вида обработки ошибок:
В некотором роде идеологически эти два варианта одинаковы, при возникновении ошибки мы имеем код ошибки (класс исключения) и текстовое сообщение, описывающее ошибку.
В случае с исключениями, мы ещё имеем стек возникновения исключения, цепочку зависимых исключений, какие-то дополнительные значения, прикрепленные к исключению, но это не имеет отношения к дальнейшему повествованию.
Практически во всех языках в стандартной библиотеке уже имеется ряд предопределённых кодов ошибок (классов исключений), такие как ArgumentError, SecurityError, IOError, RuntimeError и т.д. И предполагается, что разработчик для всех без исключения новых ошибок в своей системе будет объявлять новые классы исключений и коды ошибок. Но, как правило, писать столько кода очень затратно по времени и все используют узкий набор стандартных исключений или кодов + небольшое количество собственных . А что же произошло конкретно, описывается в сообщении об ошибке.
Что же здесь плохого? Плохо то, что с точки зрения кода мы можем анализировать только код ошибки, но не человекочитаемое сообщение об ошибке. Поэтому в данном случае остается только расширять список кодов ошибок (исключений) и это правильно. Но в любом случае в коде большого приложения остается очень много редко используемых веток исполнения, на которые не может быть внятной реакции извне. Пользователь тоже с этим ничего поделать не может, и в таких случаях обычно кидается RuntimeError и пользователю отображается “Что-то пошло не так”. Либо это бывает ошибка ArgumentError, которая может возникнуть практически в любой функции при валидации параметров.
Проблема №2
Ненадолго переключимся на логирование, здесь тоже есть проблема. Обычно в нагруженной системе мы получаем тонны логов, и иногда их как-то нужно анализировать, даже при помощи различных фильтров и инструментов. К примеру, нужно поискать некое сообщение в логах, как часто оно возникает. Но сообщения в логах обычно это человекочитаемые строки, которые часто подвергаются форматированию и локализации. И искать в логах точное соответствие строке порой бывает очень сложно, не спасают даже регулярки. Например: “Client #{client.id} not found in #{list}”. Если мы будем искать это сообщение по частям, то мы найдем множество записей с “Client” или “not found” и дальше уже глазками грепать пересечение. Также это отсутствие формализации сильно усложняет последующие автоматизированные анализы логов на наличие определенных ошибок, вывод статистики.
Проблема №3
Мы увидели какую-то ошибку или сообщение в логах, но как теперь найти то место в коде, которое её/его вызывает? Хорошо, если у исключения залогировался стектрейс со строками кода… Иначе мы беремся за инструмент полнотекстового поиска в нашей любимой IDE и начинаем искать сперва по нескольким словам, потом регуляркой, если сообщение было отформатировано. Через некоторое время конечно же находим нужное нам место. Но это было не очень просто, не так ли? А если строка была локализована… Ну вы поняли.
Проблема №4
Это поддержка. Пользователи начинают нам звонить и пытаться на ломаном языке сообщить, что же им выскочило на экране, либо делают скрины с выхлопом ошибки, а там что-то типа “Передан неправильный параметр”. Какой? Где? Стектрейса нет. Тут начинаются гадания на кофейной гуще и дальнейшие переписки, созвоны.
Что делать? Тэгировать!
Как-то очень давно я обратил внимание на синие экраны смерти Windows, также при работе с WinAPI я наткнулся на каталог кодов ошибок в Windows. Ребята явно заморочились на этот счет, сейчас он переваливает за 12000 записей. Там можно найти отдельный код на любой чих.
Но проблема в том, что нужно прямо брать и вести такой реестр порядковых кодов для своего проекта, чтобы случайно не пересечься с каким-то другим кодом. А если у тебя микросервисы, то желательно, чтобы между ними тоже не было пересечений. Поэтому я для себя быстро накатал незамысловатый скрипт на sh:
#!/bin/sh SHA256=$(uuidgen | sha256sum); echo -n "<${SHA256:0:8}>"
Расшифровываю: берем обычный GUID, считаем от него SHA256, берем первые 8 символов, обрамляем в угловые скобки “<”, “>” для пущей красоты.
Потом повесил вызов этого скрипта с эмуляцией вбития его с клавиатуры на хоткей, спасибо божественному KDE, что там всё для этого есть штатно (ну практически). И начал быстро растыкивать такие коды в тексты сообщений об ошибках и в логи.
Вот так примерно выглядят сообщения об ошибках:
raise SecurityError.new "<c920fbaf> Hello #{username}, " + "you’re not supposed to be here"
logger.warn "<dc8a357a> #{username} entered restricted area"
Выводы
Что же я получил с таким тэгированием:
- описанный метод универсален, и выгоду можно получить на любой платформе, будь то бэк, либо фронт, написанные на чём угодно
- мне не надо вести реестр кодов, я практически уверен, что очередной код будет уникален, и он не такой громоздкий как GUID
- видя код ошибки в выхлопе на экране, я могу быстро найти её в исходниках простейшим грепом без тайных знаний regexp
- благодаря строгому формату тэга, я могу незамысловатым скриптом собрать все ошибки в проекте с описанием в текстовый файл (он же реестр кодов ошибок) и отдать его, например, фронтендеру
- пользователи мне слали коды ошибок, и могли это делать хоть через SMS
- стало возможным вычленить из текста тэг и обработать программно специфичную ошибку особым образом
- в системе сбора и анализа логов я настраивал фильтры на особые ошибки, по которым необходимо было экстренно реагировать, получал сообщения в телегу
- в отличие от стектрейса с файлом и номером строки UID не изменится. Это означает, что даже если вы сделаете грандиозный рефакторинг, вы всегда найдете ошибку или сообщение по коду, сколько бы лет не прошло, и если она там ещё осталась.
- на сервере при формировании response я выделял UID ошибки в отдельное поле, чтобы клиенту было удобнее. Получалось примерно так:
{ "result": "ACCESS_DENIED", "uid": "c920fbaf", "message": "Hello John, you’re not supposed to be here" }
Конечно же, есть и некоторые неудобства, недостатки данного тэгирования:
- когда занимаешь копипастой, то частенько коды начинают задваиваться, тут надо быть внимательным и генерить для только что вставленного кода новые тэги
- коды могут просочиться в итоге на экран пользователю в сообщении об ошибке и на фронте надо озаботиться отделением текста от тэга, а полный текст ошибки убрать в секцию “Дополнительно”
Спасибо за внимание, надеюсь, что данный несложный приём ещё кому-нибудь хорошо зайдет.
В качестве дополнения
Под Linux я использую xvkbd для эмуляции ввода с клавиатуры.
#!/bin/sh GUID=`genuid.py` xvkbd -text $GUID
Что существует для эмуляции ввода с клавиатуры и автоматизации под Windows и Mac - мне неведомо, хотелось бы получить отклик в комментариях, и я дополню статью =)