Сложность систем стремительно повышается и если мы хотим релизится чаще раза в месяц, нам приходится писать автоматические тесты на все - качество кода (линтеры, статические анализаторы), части кода (юнит тесты), собранный код (интеграционные тесты), поведение в браузерах и мобильных (приемочные тесты), инфраструктуру (деплой тесты, Chaos Monkey тесты, service mesh тесты), продакшен (нагрузочные тесты и тесты на проникновение), тесты бэкапов, тесты баш-скриптов и даже тесты на сами тесты (мутационное тестирование).
Но мы забыли протестировать еще кое - что. Логи.
И нет, я говорю не о мониторинге, не о метриках. Я говорю именно о логах приложения.
Система управления логами может быть внутренняя (EL(F)K, LPG или LogHouse), или внешняя (Loggly, CloudWatch, StackDriver).
Любая система будет логически делиться на 3 подсистемы: агент сборки логов, хранилище логов и интерфейс для визуализации. В случае EL(F)K это Logstash(Fluentd) + ElasticSearch и Kibana, LPG это Promtail+ Loki + Grafana, Loghouse - Fluentd + Clickhouse + Loghouse UI.
С внешними системами такая же история. Агент+хранилище+интерфейс.
Что может пойти не так?
Во-первых, мы заинтересованны в том, чтобы агент сборки логов мог распарсить то, что мы залогировали. Значит нам стоит проверять логи на поддерживаемый формат и максимальный размер каждой записи. В старые добрые времена было принято писать логи обычной строкой и парсить потом regexp'ами. Сейчас, как правило, логи это объект, сериализованный в однострочный JSON. Важно, чтобы этого формата придерживался не только логер в вашем коде, но и логеры во внешних зависимостях, если их авторы не позаботились о возможности встроиться в единый логер приложения.
Во-вторых, хранилище логов должно уметь разобрать наш лог, сохранить и проиндексировать. Из этого следует сразу два важных момента: хранилище должно поддерживать все типы данных, которые мы хотим сохранить, и структура логов должна быть постоянной.
Последнее вызывает особенные проблемы в EL(F)K стеке - ElasticSearch без специальных танцев с бубном будет игнорировать логи, которые выбиваются из общей схемы. В итоге часть логов просто пропадет.
Кроме того, существует подход, который позволяет извлекать метрики из логов. Это особенно просто можно реализовать при работе с ClickHouse при помощи инструмента MaterializedView.
Это вторая причина, почему нам необходимо поддерживать постоянную структуру логов.
В-третьих, покрытие кода тестами. Общеизвестно, что 100% покрытия в сложных системах добиться сложно и что даже полное покрытие не гарантирует правильной работы приложения.
Но в контексте нашего разговора нам критически важно знать, что все попытки записи логов в коде были реализованы. Только тогда мы сможем убедиться, что все логи соответствуют нашим ожиданиям. Особенно обидно будет, если система записи отбросит лог, который был записан в месте, в которое не добрался тест. Скорее всего такие ситуации будут возникать редко, и нам будет особенно важно знать что же именно произошло.
Это значит, что нам стоит тестировать сколько событий попало в лог и какие именно это были события.
И особенно здорово получится, если все логи в вашей системе будут иметь похожую структуру. Если у вас много микросервисов, договоритесь с коллегами об общей структуре логов и тогда расследование инцидентов станет занимать гораздо меньше времени, чем раньше.
Что сохранять в лог?
Если вы пользуетесь готовыми модулями для логирования, они, как правило, уже имеют несколько полей по умолчанию:
name - имя приложения. Если логи пишутся в одну таблицу (коллекцию), потребуется имя, чтобы отличать одно приложение от другого.
hostname - хост, на котором запущено приложение. Особенно важно в микросервисной среде.
pid - process id на хосте. Если ваше приложение может быть запущенно в нескольких экземплярах на одном сервере, хотелось бы уметь их различать между собой.
level - уровень отображает типа лога - info, trace, error и тд.
time - время кода произведена запись. Не забудьте следить за тем, чтобы на всех машинах в вашем кластере было одинаковое время.
src - в зависимости от языка программирования может содержать место в исходнике, где инициирована запись лога. В случае с минифицированными или траспилированными скриптами нужно не забыть про sourcemap.
Кроме самого сообщения, стоит добавить некоторый идентификатор события, по которому логи проще будет разделять между собой. Например, если у вы делаете API, можно указать endpoint. Таких идентификаторов можно сделать несколько, если одни и те же методы могут вызывать разные end-point'ы.
Так же в случае с API стоит добавить идентификатор запроса. Здорово будет если вы сможете объединить логи от Sentry и все дальнейшие вызовы между вашими микросервисами.
Если вы логируете операции, выполняющиеся по расписанию, добавьте номер шага внутри задачи и общее количество шагов.
Если производится вставка или обновление в базе данных, всегда возвращайте идентификаторы измененных строк и сохраняйте их в лог.
Что проверять и какие инструменты мне нужны?
Давайте рассматривать вариант, когда логи представляют собой однострочный JSON. Думаю, большинство из нас генерирует логи именно в этом формате.
Тестирование логов - это часть обычного тестирования, которое запускается по хуку перед пушем в git или на CI после попадания в репозиторий.
Запускать тестирование логов имеет смысл либо после выполнения всех тестов, либо после каждого test-suit'а.
Проверить постоянство структуры JSON в файле с логами нам поможет инструмент Ajv-cli. Это консольная версия известного пакета Ajv для валидации JSON объектов по шаблонам JSON-Schema. Нам останется подготовить необходимый шаблон.
Проверить количество разных типов записей в файле с логами будет удобно при помощи утилиты Jl-Sql. Она позволяет из консоли запустить SQL-запрос по файлу, содержащему сериализованные JSON строки, так, как будто это таблица в базе данных.
Этот инструмент будет удобно использовать после выполнения всех тестов. Минус такого подхода - мы должны считать все логи вместе. Если в коде будет добавлен новый лог, тест придется править.
Возможно, удобнее будет проверять количество записей после каждого test-suit'а. Тогда придется написать тесты, например на JS, используя Jl-Sql-Api.
Так же можно проверить некоторые значения в самих записях. Например, можно проверять значения дат и времени, записываемых в лог. При тестировании операции, выполняющихся по расписанию, можно проверить что все шаги выполнены последовательно, ничего не пропущено, ничего не выполнено больше одного раза и значения поля с текущим шагом не превышают значения поля с общим количеством шагов.
Проверяйте идентификаторы строк после вставки в базу данных. Это может помочь обнаружить проблемы с данными намного раньше, чем это станет проблемой. Проверять это в обычных тестах нецелесообразно, а достать эти данные из логов довольно удобно.
Что еще мне стоит знать?
Логи и метрики - это не дополнение к вашему приложению, это неотъемлемая его часть. Не относитесь к ним по остаточному принципу. Архитектура этих подсистем не менее важна, чем архитектура самого приложения.
Больше на канале в телеграме: https://t.me/nosingularity
