Всем привет! На связи Роман Савельев, фронтенд-разработчик в команде Звука. В этой статье я хочу поделиться опытом и рассказать, как мы с командой прошли путь от хаоса до выстроенной инфраструктуры и унифицировали работу с логами в собственных веб-сервисах. Я расскажу, с какими проблемами мы столкнулись, как их решали и какие вывели в best practices. 

Кстати, в best practices даны ответы на вопросы «зачем», «как» и «что» логировать.

Логирование в контексте наблюдаемости

Если рассматривать логирование в контексте наблюдаемости (или observability), то логи можно определить как идемпотентные записи о дискретных событиях, которые произошли в определенный момент времени. 

Правильно выстроенный процесс логирования дает возможность получить полное представление о функционировании сервиса — это ответ на вопрос «Зачем логировать?».

Как процесс устроен в Звуке

Веб-приложение Звук состоит из нескольких  сервисов, каждый из которых разрабатывается и поддерживается отдельными командами. Большинство этих сервисов созданы с использованием фреймворка Next.JS, что означает наличие как серверной (SSR), так и клиентской части. По мере роста числа сервисов становится необходимым обеспечить их мониторинг. Это требует унификации и стандартизации работы с логами и другими сигналами наблюдаемости.

В наших сервисах мы используем логирование для мониторинга их технического состояния. Мы логируем:

• необработанные исключения (у нас для этого подключен Sentry); 

• ошибки при серверном рендеринге и выполнении js кода на клиенте; 

• ошибки в HTTP-запросах; 

• информационные сообщения в важных компонентах приложения (инициализация, авторизация, оформление подписки и т.п.); 

• в целях отладки в локальной и стейдж-среде.

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

Почему изменили подход к логированию

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

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

— Для сервисов должна быть выстроена единая инфраструктура по сбору и работе с логами.

— Для каждого сервиса клиентские и серверные логи должны храниться в едином источнике (и по ним должен быть организован быстрый поиск). 

— Логи должны иметь стандартизированный набор уровней.

— Логи должны иметь общую структуру (в частности, иметь стандартизированный трейс для логов уровня ERROR).

Общая инфраструктура для сбора и работы с логами

Первое, что мы сделали — упростили схему логирования наших веб-сервисов для удобства работы с большим объемом логов. 

Алгоритм, который мы реализовали: 

• Логи веб-сервисов записываются в формате JSON и сохраняются в локальных файлах внутри контейнеров Kubernetes. Логи ротируются для оптимизации хранения и доставки.

• Поды Filebeat обрабатывают логи и отправляют их в очередь Kafka без дополнительного парсинга, так как они уже логируются в совместимом формате с Elasticsearch.

• Логи из Kafka индексируются в Elasticsearch, где создается отдельный индекс для каждого сервиса. Логи хранятся в Elasticsearch 14 дней и затем перезаписываются.

• За последние 3 месяца логи также сохраняются в хранилище S3 для возможного использования в будущем, для анализа или запросов от партнеров.

• Для поиска по логам используется Kibana, а общая статистика и дашборды строятся в Grafana в рамках мониторинга веб-сервиса.

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

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

В итоге мы обеспечиваем индексацию клиентских и серверных логов в едином источнике.

Логирование в веб-сервисах 

Мы создали единый модуль логирования для упрощения работы с логами в различных сервисах. Модуль доступен через приватный менеджер пакетов npm и удовлетворяет следующие требования:

• Обеспечивает верхнеуровневое API-логирование и минимальный оверхед по использованию ресурсов. 

• Структура логов совместима с Elasticsearch, с возможностью настройки timestamp и разделителя столбцов.

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

• Поддерживает как серверное, так и клиентское логирование.

В качестве основы для реализации модуля мы рассмотрели собственное решение, а также библиотеки Pino, Winston и Loglevel. В итоге мы выбрали Pino, так как он удовлетворяет всем нашим требованиям и имеет минимальный оверхед, подтвержденный бенчмарками. Для вывода логов в совместимом с Elasticsearch формате мы используем модули @elastic/ecs-pino-format, а для красивого вывода логов в режиме разработки — pino-pretty. Наш собственный бенчмарк (MacBook Air m1) также подтвердил преимущества Pino по сравнению с нашей и другими реализациями:

1. Базовая реализация модуля заняла несколько строк кода (далее — пример кода):

   import pino, { Logger, LoggerOptions as PinoLoggerOptions } from "pino";
   import ecsFormat from "@elastic/ecs-pino-format";
   
   interface LoggerOptions extends PinoLoggerOptions {
    /** Использовать ли форматирование логов через pino-pretty */
    isPrettyEnabled?: boolean;
    /** Использовать ли форматирование логов через ecs-pino-format (не используется в клиентской части) */
    isEcsEnabled?: boolean;
   }
   
   const loggerFactory = (options?: LoggerOptions): Logger => {
    const { level, isPrettyEnabled, isEcsEnabled, ...restOptions } = options || {};
   
    // Читабельные логи
    const prettyTransport: pino.LoggerOptions["transport"] = { target: "pino-pretty" };
    const prettyOptions = isPrettyEnabled ? { transport: prettyTransport } : {};
    // Ecs форматированные логи
    const ecsOptions = isEcsEnabled ? ecsFormat.({ convertErr: false }) : {};
   
    return pino({
      level: level || "trace",
      ...prettyOptions,
      ...ecsOptions,
      ...restOptions,
    });
   };
   
   export { loggerFactory };

2. Модуль конфигурируется в каждом сервисе и затем подключается в другие файлы для создания единых экземпляров логгера в клиентской и в серверной частях приложения: 

   import { loggerFactory } from '@zvuk-web/logger';
   
   import { IS_DEV_MODE } from 'config/constants/common';
   import { LOG_LEVEL } from 'config/env/common';
   
   export default loggerFactory({
    level: LOG_LEVEL,
    isPrettyEnabled: IS_DEV_MODE,
    isEcsEnabled: !IS_DEV_MODE,
   });

   В данном примере отсутствует код для отправки клиентских логов, однако это можно легко реализовать, передав соответствующий колбэк в параметр browser.write. При этом у Pino есть очевидный минус: он не логирует модуль, в котором выполняется запись лога, по умолчанию. Для исправления этой проблемы важно использовать метод pino.child (logger, {file: ‘moduleA’}) в корне каждого файла, чтобы путь к исходному файлу был частью лога.

Мы используем модуль логирования в каждом сервисе таким образом: 

— обработанные ошибки регистрируем через этот модуль, добавляя соответствующие данные в зависимости от контекста (здесь мы рассчитываем поймать ошибку, так как  потенциально знаем ее причину);

— для необработанных исключений мы используем Sentry, чтобы сохранить трейс запроса, дополнительные данные и иногда воспроизведение сессии;

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

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

Пример кода инициализации Sentry в одном из сервисов:

import { init } from '@sentry/nextjs';
import parentLogger from 'src/core/logger';

const logger = parentLogger.child({ module: ‘sentry.client.config.ts’ });

init({
 // Общий конфиг sentry
 ...,
 // Перехватываем исключение перед отправкой в sentry
 beforeSend: (event, hint) => {
   const exception = hint.originalException || hint.syntheticException;

   if (exception) {
     logger.error(exception, '[UNHANDLED_EXCEPTION] Sentry beforeSend');
   }

   return event;
 },
});

С учетом всего вышесказанного получилась следующая структура:

Важно покрыть логированием участки кода, которые могут вызывать ошибки. Например, большинство клиентских ошибок мы обрабатываем в реакт ErrorBoundary. Ошибки при серверном рендеринге мы также логируем, оборачивая соответствующие блоки кода в try/catch — и в случае необработанных исключений отправляем их в Sentry через метод beforeSend. Помимо этого, мы логируем события инициализации приложения, плеера, авторизации и других критически важных модулей приложения с уровнем INFO.

Не стоит логировать чувствительные и персональные данные. Для этого полезно использовать функцию redaction в Pino, чтобы явно указать, какие данные необходимо скрыть в логах. Также не рекомендуется логировать в продакшн-режиме отладочные логи (debug и trace), чтобы не загромождать место хранения логов лишней информацией. Управление уровнем логирования через переменные окружения может помочь в этом.

Как мы работаем с логами

Мы используем модуль логирования для дебага в Dev-режиме с помощью модуля pino-pretty, который выводит логи в удобном формате с понятным стеком трейса. Логи также используются для исследования инцидентов и решения проблем клиентов при обращениях в техническую поддержку. Для этого удобно логировать некий идентификатор (например, хэш лога), который отображается пользователям во всплывающем сообщении об ошибке и позволяет быстро установить причину проблемы.

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

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

Кейс Звука по работе с логами

Один из последних кейсов, когда пришлось изучать логи, выглядел так:

У нас сработал алерт на процент валидных входящих запросов (меньше 95%). Проблему было видно сразу на 3 дашбордах — rps по кодам ответа, процент валидных входящих запросов и количестве серверных ошибок:

Аналогично возрастание фона ошибок можно увидеть в Kibana. Там же быстро находим детализацию по исследуемой проблеме:

Ошибка была идентифицирована вне нашего приложения, вероятно, на уровне проксирования запросов в Kubernetes. После совместного анализа с инженерами SRE было выяснено, что проблема связана с высвобождением памяти в Kong Ingress (у нас это легаси). Решением стало переведение соответствующего узла на Istio Ingress, что позволило быстро устранить ошибку.

В данном примере ошибка не зависела от наших веб-сервисов. Однако, когда ошибки или аномалии в показателях возникают из-за работы сервиса, полезно получать дополнительные инсайты, анализируя трейсы и профайлы. Современные инструменты для помощи  — ELK/LGTM стек, SigNoz, New Relic и другие. Они помогают анализировать узкие места производительности, проблемы безопасности и находить инсайты. Мы также планируем внедрить подобный подход и рассматриваем логирование как часть единой платформы наблюдаемости веб-сервисов.

Подведем итоги

• Рассматривайте логирование как часть наблюдаемости и мониторинга веб-сервисов.

• Выстраивайте общую инфраструктуру для сбора логов с настройкой ротации.

• Храните клиентские и серверные логи сервиса в едином месте.

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

• Не стоит использовать Sentry в качестве инструмента логирования; его назначение — отлавливать и работать с исключениями.

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

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

Спасибо, что прочитали! Если у вас есть вопросы — будем рады ответить на них в комментариях.