В постах на Хабре тема структурного логирования упоминается часто, но вскользь. Поэтому, когда я наткнулся на эту подробную статью Brandur Leach из Stripe, я решил перевести её и поделиться с сообществом. 

В Badoo мы оценили пользу структурного логирования в частности для группировки ошибок. Хеш сообщения об ошибке часто содержит динамические данные — например, id пользователя, — которые мешают корректно группировать такие сообщения. Поэтому мы перешли на структурное логирование, где текст ошибки — это некий шаблон, а вся динамическая информация передается в контексте и не влияет на группировку.

В статье Brandur Leach предлагает идею, как открыть еще больше возможностей в структурном логировании. Есть и описание практической пользы от использования такого подхода — в Stripe даже сделали продуктовый функционал на основе данных, полученных из логов, — и детали реализации такого решения (без ухода в дебри конкретного стека технологий).

Приятного чтения!

Логирование — один из старейших и наиболее распространённых паттернов в программировании. Это ключ к пониманию самых разных проблем, начиная с простых сбоев в тестовом окружении и заканчивая запутанными проблемами в «бою». Логирование десятилетиями является стандартной практикой во всех стеках и типах инфраструктуры.

Хотя логи — мощный и гибкий инструмент, но из-за больших объёмов анализировать их «в лоб» часто неудобно. Релевантная информация разбросана по многим строкам, и даже самые мощные системы обработки логов не позволяют быстро найти нужные подробности без использования сложного синтаксиса запросов.

Мы в Stripe обнаружили, что можно немного изменить традиционный процесс логирования, добавив в текст дополнительные данные, и назвали этот способ каноническими строками логов (canonical log lines). Идея простая: помимо обычных текстовых сообщений, в лог записывается длинная строка, которая содержит ключевые характеристики запроса. Размещение всех этих данных в одной строке позволяет упростить запросы на поиск и агрегацию данных в логах и быстрее их исполнять.

Среди всех инструментов и методик, которые мы используем, чтобы получить представление о ситуации в продакшен-среде, канонические строки логов оказались настолько полезны для повышения эксплуатационной прозрачности (operational visibility) и реагирования на инциденты, что мы внедрили их почти в каждый наш сервис. Такие строки не только используются в нашем основном API, но и генерируются при каждой отправке веб-хука, при токенизации банковской карты в нашем PCI-хранилище секретов (PCI vault) и при загрузке страницы в Stripe Dashboard.

Структурное логирование

Логирование активно используется в API и веб-сервисах, а также во многих других сферах. В платёжном API один запрос может сгенерировать такую последовательность записей в логах:

[2019-03-18 22:48:32.990] Request started

[2019-03-18 22:48:32.991] User authenticated

[2019-03-18 22:48:32.992] Rate limiting ran

[2019-03-18 22:48:32.998] Charge created

[2019-03-18 22:48:32.999] Request finished

Структурное логирование дополняет эту практику, предоставляя разработчикам простой способ аннотирования строк дополнительными данными. Термин «структурное» имеет двоякий смысл: он может означать нативно структурированный формат данных вроде JSON, но зачастую он означает, что строки логов дополняются парами «ключ-значение» (иногда их называют logfmt). Дополнительная структура позволяет разработчикам легко обогащать строки нужной информацией, а не внедрять её в сами тексты сообщений.

Приведённый выше пример может выглядеть так:

[2019-03-18 22:48:32.990] Request started httpmethod=POST httppath=/v1/charges requestid=req123

[2019-03-18 22:48:32.991] User authenticated authtype=apikey keyid=mk123 userid=usr123

[2019-03-18 22:48:32.992] Rate limiting ran rateallowed=true ratequota=100 rateremaining=99

[2019-03-18 22:48:32.998] Charge created chargeid=ch123 permissionsused=accountwrite team=acquiring

[2019-03-18 22:48:32.999] Request finished alloccount=9123 databasequeries=34 duration=0.009 httpstatus=200

Наличие структуры данных также делает генерируемые логи машиночитаемыми (соглашение ключ-значение используется как компромисс, при котором данные могут читать и машины, и люди). Это делает их пригодными для использования в различных инструментах для работы с логами, многие из которых могут запрашивать записи с боевого окружения почти что в реальном времени. 

Допустим, нам нужно узнать, какие запросы к API были сделаны последними. Это можно сделать с помощью системы обработки логов вроде Splunk и её встроенного языка запросов:

“Request started” | head

Также можно узнать, были ли ограничены в скорости какие-то из недавних обращений к API:

“Rate limiting ran” allowed=false

Или собрать статистику по времени работы API за последний час:

“Request finished” earliest=-1h | stats count p50(duration) p95(duration) p99(duration)

На практике такие простые данные чаще всего получают из дашбордов, генерируемых системами сбора метрик вроде Graphite и StatsD, но у них есть ограничения. Метрики и интерпретирующие их панели разрабатываются заранее, и, когда возникает такая потребность, довольно тяжело создавать какие-то необычные запросы. Логирование превосходит подобные системы именно в гибкости.

Логи обычно содержат избыточные данные, что позволяет извлечь из них практически всё что угодно — даже информацию, о которой никто и не помышлял. Например, можно узнать, какой HTTP-путь самый востребованный:

“Request started” | stats count by http_path

А если API возвращает ошибки с кодом 500 (внутренняя ошибка сервера), можно узнать длительность сбойных запросов, чтобы достаточно точно оценить, не вызвано ли это тайм-аутами базы данных:

“Request finished” status=500 | stats count p50(duration) p95(duration) p99(duration)

Сложные системы обработки логов обычно предоставляют визуализацию, схожую с дашбордами систем сбора метрик. Поэтому вместо чтения сырых данных из лога можно сделать так, чтобы система отображала результаты наших запросов к данным в виде графиков. Интерпретировать графическую информацию проще, с ней куда легче разобраться в происходящем.

Канонические строки логов: одна строка на один запрос к одному сервису

Хотя в приведённых выше примерах логи обеспечивают гибкость в работе, мы всё равно оказываемся в трудной ситуации, когда нужно запросить информацию, разбросанную по разным строкам. Например, если мы заметили большое количество срабатываний механизмов ограничения (rate limiting) в API, может возникнуть вопрос: «Какие пользователи ограниченны больше всего?» Ответ на него поможет отличить корректные ограничения из-за слишком большого количества запросов от случайных, возникающих по причине бага в нашей системе.

Информация об ограничении запроса и о пользователе разбросана по нескольким строкам, поэтому её сложно собрать. Большинство систем обработки логов умеют это делать путем сопоставления трассировки с чем-нибудь вроде идентификатора запроса и запрашивания результата. Но это подразумевает сканирование большого объёма данных — задача выполняется медленно. Кроме того, требуется использовать сложный синтаксис, который тяжелее запомнить и дольше писать.

Канонические строки логов лишены этих недостатков. Идея проста: запросы (или другие исполняемые единицы работы) в дополнение к обычным текстовым данным генерируют одну дополнительную длинную строку, содержащую всю ключевую телеметрию. Например:

[2019-03-18 22:48:32.999] canonical-log-line alloc_count=9123 auth_type=api_key database_queries=34 duration=0.009 http_method=POST http_path=/v1/charges http_status=200 key_id=mk_123 permissions_used=account_write rate_allowed=true rate_quota=100 rate_remaining=99 request_id=req_123 team=acquiring user_id=usr_123

Пример показывает, какую информацию может содержать каноническая строка:

• тип HTTP-запроса, путь и статус ответа;

• данные о пользователе, связанная с аутентификацией информация (ключ API, пароль), идентификатор использованного API-ключа;

• был ли разрешён запрос механизмами ограничения (rate limiters), данные о состоянии этих механизмов вроде квоты и неизрасходованной части квоты;

• общая длительность запроса и время, потраченное на запросы к базе данных;

• количество запросов к базе данных и количество объектов, размещённых в памяти виртуальной машины.

Мы называем строку лога канонической, потому что это определяющая строка для конкретного запроса — по аналогии с тем, как каноническая ссылка IETF описывает определяющий URL.

Канонические ссылки эргономичны. Компактно «упаковав» всю важную информацию, мы делаем её доступной для запросов, которые легко могут писать люди даже в состоянии стресса, вызванного сбоем в боевом окружении. Поскольку системе логирования для ответа на запрос не нужно собирать несколько строк, канонические строки просты в извлечении и агрегировании, а значит, их можно быстро использовать. Широкий диапазон записанной информации даёт почти безграничную гибкость при составлении запросов. Это особенно ценно при расследовании инцидентов, когда уже понятно, что есть проблема, но ещё неясна её природа.

Разобраться с описанной выше проблемой ограничения запросов можно очень легко:

canonical-log-line rate_allowed=false | stats count by user_id

Если запросы одного или нескольких пользователей были ограничены механизмами ограничения, то, возможно, речь идёт о корректном срабатывании защиты от слишком большого количества запросов. А если с ограничениями столкнулось много пользователей, то, вероятно, мы имеем дело с ошибкой.

Возьмём более сложный пример. Можно для конкретного пользователя визуализировать изменение времени работы эндпойнта charges, отфильтровав ошибки 4хх, вызванные некорректными запросами пользователя. Такие ошибки, как правило, быстро устраняются и не сообщают нам ничего полезного об обычной производительности эндпойнта. Запрос может выглядеть так:

canonical-log-line user=usr_123 http_method=POST http_path=/v1/charges http_status!=4* | timechart p50(duration) p95(duration) p99(duration)

Реализация в middleware и за его пределами

Логирование настолько распространено, а идея с каноническими строками настолько проста, что реализовать их несложно на любом технологическом стеке.

В основном API Stripe это реализовано в виде middleware с этапом генерирования строки после обработки запроса. Модули, исполняемые в течение жизненного цикла запроса, дополняют его среду информацией для канонических строк, которая будет извлечена middleware по завершении обработки.

Вот сильно упрощённый пример:

class CanonicalLineLogger
  def call(env)
    # Call into the core application and inner middleware
    status, headers, body = @app.call(env)

    # Emit the canonical line using response status and other
    # information embedded in the request environment
    log_canonical_line(status, env)

    # Return results upstream
    [status, headers, body]
  end
end

Наша реализация годами оттачивалась, чтобы канонические строки генерировались для каждого запроса даже при возникновении внутренних сбоев и неожиданном поведении. Строка логируется в блоке ensure (это аналог finally в языке Ruby — примечание переводчика) на случай возникновения исключения, брошенного где-то ниже. Логирующее выражение оборачивается в собственный блок begin/rescue (аналог try/catch), чтобы никакие проблемы при формировании канонической строки не влияли на сам запрос и чтобы об этих проблемах сразу уведомляли ответственного. Этот инструмент настолько важен для нас, что любые проблемы с ним должны максимально быстро устраняться (иначе реагирование на инциденты будет похоже на полёт вслепую).

История хранения

Проблема логов связана с обилием данных в них. Их длительное хранение где-то, кроме холодного хранилища, — дорогое удовольствие, особенно при низкой вероятности обращения к логам. И, помимо пользы при эксплуатации, краткость канонических строк делает их удобными для архивирования исторических данных.

В Stripe канонические строки логов так часто используются разработчиками для анализа боевой среды, что у нас уже сформировалась мышечная память на наименования определённых полей. Долгое время мы старались сделать так, чтобы правила наименования не менялись, потому что это было бы неудобно для команды, ведь всем пришлось бы переучиваться. В конце концов мы придали соглашению официальный статус, описав его формат с помощью Google Protocol Buffers.

Наряду с генерированием канонических строк в системе логирования API сериализует данные в соответствии с соглашением и асинхронно отправляет их в топик Kafka. Потребитель считывает топик, собирает несколько строк в пакет и сохраняет его в S3. Периодические процессы загружают эти пакеты в архивы Presto и Redshift, что позволяет легко анализировать долгосрочные тренды, просматривая данные за несколько месяцев.

На практике это позволяет измерять почти всё, что мы захотим. Например, вот график внедрения основных версий Go, построенный на основании данных из запросов, сгенерированных нашими официальными API-библиотеками:

Более того, поскольку в наших инструментах обработки данных используется SQL, агрегировать и анализировать данные могут как инженеры, так и неинженеры. 

Вот исходный код запроса из предыдущего примера:

SELECT
    DATE_TRUNC('week', created) AS week,
    REGEXP_SUBSTR(language_version, '\\d*\\.\\d*') AS major_minor,
    COUNT(DISTINCT user)
FROM events.canonical_log_lines
WHERE created > CURRENT_DATE - interval '2 months'
    AND language = 'go'
GROUP BY 1, 2
ORDER BY 1, 3 DESC

Улучшение продукта

Мы уже описали схему наших канонических строк в Google Protocol Buffers для использования в аналитике, поэтому пошли дальше и начали применять эти данные для развития элементов Stripe как продукта. Год назад мы представили наш Developer Dashboard, дающий доступ к высокоуровневым метрикам API-интеграций наших пользователей.

Графики для этого дашборда также сгенерированы на основе канонических строк. Бэкенд MapReduce создаёт из архивов, хранящихся в S3, визуализации для дашбордов конкретных пользователей. Как и в случае с нашими инструментами аналитики, схема прописана в Google Protocol Buffer, что гарантирует соблюдение контракта.

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

Набросок конвейера для канонического логирования

Канонические строки логов применимы практически на любом стеке. Давайте вкратце рассмотрим некоторые технологии, которые можно использовать для создания полного конвейера логирования.

В большинстве систем логи сохраняются на локальных дисках, а затем локальные агенты отправляют их в центральную систему для поиска и анализа. Документация по логированию в Kubernetes предлагает использовать Elasticsearch, а GCP — Google Stackdriver Logging. В стеках на основе AWS принято использовать CloudWatch. Во всех трёх случаях необходим агент вроде Fluentd для обработки передачи логов с серверов. Все эти решения распространены, но далеко не повсеместно: для обработки логов есть десятки продуктов, поэтому важно разобраться в предложениях и выбрать решение, которое оптимально для вас.

Отправка данных в хранилище требует специального решения, но не какого-то необычного или особенно сложного. Серверы должны отправлять канонические данные в потоковую структуру, причём делать это асинхронно, чтобы не замедлять действия пользователей. Kafka сегодня является предпочтительным решением, но этот инструмент не слишком дёшев и непрост в использовании. Прекрасной альтернативой для небольших систем будет что-то вроде потоков на основе Redis. Группа потребителей читает поток и кладёт его содержимое в хранилище вроде Redshift или BigQuery. Как и в случае с обработчиками логов, существует большое разнообразие решений для создания хранилища.

Гибкая и быстрая наблюдаемость

Напомним основные свойства канонических строк логов и причины, по которым они оказались нам полезны.

• Создаётся по одной канонической строке на один запрос к одному сервису. Строка содержит ключевую телеметрию запроса.

• Получение данных из канонических строк не такое быстрое, как у метрик, но строки чрезвычайно гибкие и простые в использовании.

• Мы асинхронно отправляем их в топик Kafka для записи в хранилище, что очень полезно для проведения аналитики.

• Обеспечиваемое каноническими строками стабильное соглашение делает их очень полезными для улучшения пользовательских продуктов. Мы используем их для создания графиков в Stripe Developer Dashboard.

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