Хозяюшке на заметку: тэгируем логи и ошибки

Оригинал: https://blog.rnds.pro/028-logs-and-errors-tagging

В этой статье будет рассказано, что, возможно, не так с вашими диагностическими сообщениями, как их можно тэгировать, а главное - зачем это делать.

Диагностические сообщения - это текстовые сообщения об ошибках и логи вашей программы. Так что же с ними не так и как это можно улучшить? Но если ты нетерпелив, то можешь поверить на слово, что проблемы есть, пропустить всю воду и перейти сразу к сути статьи и выводам.

Что не так?

Сперва опишу некоторую проблематику, которую я начал осознавать со временем и с опытом.

Проблема №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:

genuid.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 - мне неведомо, хотелось бы получить отклик в комментариях, и я дополню статью =)