Всем привет! Меня зовут Алексей Леонтьев, я старший разработчик и системный архитектор в компании KTS.

Сейчас я занимаюсь Smartbot Pro. Это low-code платформа для создания чат-ботов, которые могут работать одновременно в нескольких каналах. Например, в Telegram, ВКонтакте и других соцсетях. Боты могут взаимодействовать с платёжными шлюзами, сохранять данные в Google-таблицы и отправлять почту. Проект этот достаточно сложный, там несколько десятков разных сервисов, несколько баз данных и очередей. 

Над этой платформой я работаю уже более пяти лет. За это время накопилось много опыта, которым хотелось поделиться в этой статье, подготовленной по мотивам моего доклада в «Школе мониторинга» Slurm. Здесь я поделюсь своим мнением, как построить мониторинг так, чтобы им было удобно пользоваться.

Содержание

• Формулировка целей

• Метрики

• Performance Monitoring

• Sentry Performance Monitoring

• Healthchecks

• Алерты

• Мониторинг пользователей и trace_id

• Sentry

• Логи

• Заключение

Формулировка целей

Прежде всего стоит определиться с тем, чего мы хотим добиться, настраивая мониторинг для проекта. Инциденты могут иметь разный охват: может лежать весь сервис, а может просто упасть какой-то  один запрос у одного конкретного пользователя. Хотелось бы иметь возможность решать проблемы в обоих случаях. Так что здесь и далее будем говорить о мониторинге в обоих указанных «масштабах».

На уровне проекта мониторинг нужен, чтобы:

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

2. минимизировать время на локализацию проблемы, если какой-то инцидент все же произошел 

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

Как достичь этих целей

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

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

1. Окружение (production или dev-среда)

2. Название компонента

3. Хостнейм сервера

Хост нужен потому, что даже при использовании Kubernetes-кластера мы не застрахованы от каких-то проблем с железом или с сетью. 

Контекст на уровне пользователя подразумевает:

1. ID пользователя 

2. ID проекта

3. trace_id

С помощью ID пользователя и ID проекта можно оценить, какое количество наших клиентов аффектит та или иная проблема. Про trace_id расскажу чуть позже.

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

Метрики

Дашборды метрик целесообразно поделить по целевой аудитории пользователей, которые ими будет пользоваться:

1. Продуктовые метрики – для бизнеса, например:
   

   1. Число клиентов и проектов

   2. Статистика по фичам

   3. LTV и CR

2. Технические метрики:
   

   1. Метрики приложения — для разработчиков и админов:

      1. RPS

      2. Число задач в очереди

      3. ..и время на их обработку

   2. «Железные» метрики — для DevOps:
      

      1. CPU Utilization

      2. RAM

      3. Disk Space

В большинстве систем агрегации метрики разделяются на несколько типов: 

• Counter — позволяют считать частоту и количество событий

• Timer — позволяют оценить время обработки задач

• Gauge — просто произвольные значения, например, число записей в таблице или температура за окном

Counter- и Timer-метрики достаточно просто собирать и обрабатывать. Например, нам пришёл запрос от пользователя или мы получили задачу из очереди. В этот же момент мы ее посчитали и запустили таймер, чтобы узнать, сколько времени она работает. 

Проблема сбора Gauge-метрик

Бывают метрики, значение которых может аффектиться со стороны каких-то сервисов, которые разрабатываем не мы. Например, количество записей в таблице может быть изменено извне: другим сервисом, админом или при накатке бекапа или миграции. Также бывают подобные ситуации и с нетехническими метриками. В качестве примера можно привести мониторинг количества пользователей в сервисах конкурентов в маркетплейсе. Так как мы не можем поймать сам момент установки того или иного сервиса в каталоге, мы должны периодически обновлять эту информацию.

Первое, что приходит в голову при слове «периодически» — это cron. Но я бы не рекомендовал использовать cron для сбора аналитики Gauge-метрик. Дело в том, что по мере роста продукта объём данных и количество собираемых метрик будет расти, а значит, время на обработку аналитических запросов будет увеличиваться. Каждый раз подгонять время на работу итерации обсчёта метрик довольно неудобно, а если этого не делать, то итерации могут начать перекрываться.

Также я не рекомендую запускать несколько аналитических задач одновременно и в одном процессе. Причина та же: по мере увеличения количества данных в базе запросы будут обрабатываться дольше, и рано или поздно мы захотим разобраться, что именно создаёт нагрузку на нашу базу. Гораздо проще это понять, если разные задачи будут запускаться в разное время. В случае возникновения проблем проще будет ориентироваться по логам, если они будут разнесены по разным сервисам.

Решение проблемы. Циклосервисы 

У себя мы эту проблему решили просто. Под каждую задачу создаётся отдельный сервис, где буквально в цикле while True выполняется какая-то итерация с определенными интервалами времени.

class BaseLoopService(BaseService):
    ITERATIONS_INTERVAL: float = 10

    async def execute(self, *args, **kwargs):
        while True:
            await self.iteration()
            await asyncio.sleep(self.ITERATIONS_INTERVAL)

    async def iteration(self):
        raise NotImplementedError

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

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

class BaseLoopService(BaseService):
    ITERATIONS_INTERVAL: float = 10
    ITERATION_TIMEOUT: float = 60 * 60

    async def execute(self, *args, **kwargs):
        while not self.stop_event.is_set():
            service_name = self.__class__.__name__

            try:
                self._logger.info(f'{service_name} iteration started')

                await wait_for(
                    self.iteration(),
                    timeout=self.ITERATION_TIMEOUT,
                    timeout_exc=IterationTimeoutExceeded(service_name),
                )

                self._logger.info(f'{service_name} iteration finished')
            except Exception:
                self._logger.exception(f'{service_name} iteration failed')

            await asyncio.wait((
                asyncio.sleep(self.ITERATIONS_INTERVAL),
                self.stop_event.wait(),
            ), return_when=asyncio.FIRST_COMPLETED)

    async def iteration(self):
        raise NotImplementedError

С тем, как собирать такие метрики, мы разобрались. Давайте поговорим о том, куда их слать. 

Куда слать Gauge-метрики

Так как в первую очередь мы говорим про Kubernetes, первое, что приходит в голову — это Prometheus. Но тут есть нюансы.

Пример. Допустим, у нас есть метрика smartbot_projects (количество проектов в нашем сервисе), и мы хотим получить количество проектов с разбивкой по сплитам. 

Пишем запрос на PromQL:

sum by (split) (smartbot_projects{env="prod"})

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

Из-за того, что задача запущена внутри пода в k8s, к метрике добавляются дополнительные метки: название пода, контейнера и хост, на котором все запущено. Так как по дефолту используется стратегия выкатки Rolling Update, то в один момент времени может быть запущено несколько копий одного и того же пода.

Можно усложнить запрос, добавив внутри агрегацию по перечисленным ранее техническим меткам: 

sum by (split) (max without (pod, instance, node_name)
                            (smartbot_projects{env="prod"}))

Мы используем здесь max without, но вместо max можно использовать любую другую функцию. Например, min или avg, так как значение этих метрик одинаковое у обоих копий сервиса. 

Можно отправлять данные в какой-то другой сервис, например Graphite. Тогда запрос на получение метрик мог бы выглядеть так:

aliasByNode(smartbot.projects.by_split.*.by_category.*.count, 3, 5)

Единственное, что у нас здесь есть — имя метрики. Это не очень удобно, потому что если мы захотим добавить какие-то новые атрибуты для разбивки метрики, мы потеряем старые данные. Конечно, можно было бы предагрегировать данные на стороне нашего бэкенда по каждому атрибуту отдельно, но на деле лучше использовать Graphite 1.1+, где есть теги, аналогичные меткам в Prometheus: 

groupByTags(
    seriesByTag(
        "name=smartbot.projects",
        "env=prod"
    ),
    "sum", "split"
)

Здесь мы сначала фильтруем метрики по env=prod, а потом применяем какую-то агрегацию. В данном случае это то же самое, сумма по сплитам.

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

Performance Monitoring

Говоря про метрики, нельзя не упомянуть про Performance Monitoring. Он помогает понять, что именно тормозит в нашем сервисе в продакшене. Причём, конечно, целесообразно начинать реализовывать Performance Monitoring до того, как какие-то проблемы уже возникли, чтобы видеть изменения нагрузки в динамике и иметь возможность предпринять какие-то действия заранее. В отличие от локального профилирования кода каким-нибудь cProfile’ом, Performance Monitoring, будучи запущенным в продакшене, позволяет понять реальную нагрузку на фактических данных, на реальном «железе» и с реальными сетевыми задержками в окружении, в котором запущен сервис. 

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

class ProjectsAccessor(BaseCollectionAccessor):
    async def get(self, _id: ObjectId):
        return await self.collection.find_one({
            '_id': _id,
        })

    async def list_all(self):
        return await self.collection.find({}).to_list()

    ...

Удобно каким-то образом обернуть каждый такой метод, считая количество и частоту запросов, а также время на их выполнение. У нас в Smartbot мы используем самописный метакласс, который проходит по всем методам классов аксессоров, и добавляет по каждому методу 2 метрики: MethodCalls и MethodCallSeconds.

class CallStatsMeta(type):
    def __init__(cls, class_name, bases, class_dict):
        package = cls.__module__

        def wrapper_factory(method_name, method):
            @wraps(method)
            async def wrapper(*args, **kwargs):
                with MethodCallSeconds.labels(
                    package=package,
                    classname=class_name,
                    method=method_name,
                ).time():
                    MethodCalls.labels(
                        package=package,
                        classname=class_name,
                        method=method_name,
                    ).inc(1)
                    return await method(*args, **kwargs)

            return wrapper

        for k, v in class_dict.items():
            if not callable(v) or not asyncio.iscoroutinefunction(v):
                continue

            wrapper = wrapper_factory(method_name=k, method=v)

            class_dict[k] = wrapper
            setattr(cls, k, wrapper)

        super().__init__(class_name, bases, class_dict)

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

Вот как это выглядит в Grafana:

Но совсем необязательно изобретать свой велосипед. Есть много готовых решений, одно из которых — Sentry Performance Monitoring.

Sentry Performance Monitoring

Ключевым понятием тут является транзакция.

Если мы интегрируем и фронтенд, и бэкенд, транзакция начинается с какого-то пользовательского действия — например, с нажатия на кнопку. Если с Sentry Performance Monitoring интегрирован только бэкенд, транзакция начинается с запроса к API.

В самом интерфейсе Sentry Performance Monitoring отображается список всех транзакций с агрегированной статистикой по ним. Если раскрыть транзакцию, внутри будет представление, похожее на Waterfall View в Chrome DevTools. Там видно потраченное время на выполнение каждого этапа обработки запроса от рендеринга на фронте, до выполнения отдельных запросов к СУБД.

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

Боремся с High Cardinality при сборе метрик в Prometheus

Что делать, если нужно отследить какую-то метрику по каждому клиенту отдельно, а клиентов много?

Пример: сервис отправляет рассылки по разным каналам — допустим, через API Telegram или ВКонтакте. Нам хочется видеть частоту обращений к внешним сервисам по каждому каналу отдельно. Так мы узнаем, не превышаем  ли мы лимиты, или наоборот, как сильно не дотягиваем по скорости рассылки. По идее, чтобы видеть статистику по каждому каналу отдельно, в качестве метки атрибута нужно использовать ID канала.

MailingRequests.labels(
    channel_id=channel_id,
).inc(1)

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

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

slot = mailings_count % 32
...
MailingRequests.labels(
    slot=slot,
).inc(1)

В итоге у нас всегда ровно 32 графика, которые заполняются по очереди. 

Теперь первая рассылка показывает частоту запросов в первом графике, вторая — во втором, и так далее по кругу. За счёт того, что у нас на практике не бывает запущено больше 20-30 рассылок одновременно, не возникнет ситуации, когда две разных рассылки пишут в один слот. В итоге задача решена: можем видеть частоту по каждому каналу отдельно и не получаем бесконечное количество комбинаций метрик в Prometheus. В случае необходимости мы всегда можем найти проблемную рассылку по времени её отправки и номеру слота метрики, который сохраняется при её отправке.

Healthchecks

Хелсчеки в k8s

Хелсчек для подов в Kubernetes — это обычно какой-то эндпоинт, вроде /internal/health, скрытый от внешнего мира. Само наличие ответа от такого НТТР-эндпоинта уже даёт понимание, не висит ли сервис. Но в идеале стоит добавить туда проверку доступности ключевых зависимостей нашего сервиса: например, проверить возможность отправки запросов в СУБД. 

Но если мы говорим не про веб-сервисы, а про какие-то воркеры, особенно про обработку CPU-bound задач, целесообразно запустить веб-сервер, который отдаёт метрики и отвечает на хелсчек-запросы в отдельном потоке.

У нас была задача с тяжёлым сервисом, который выполнял задачи по кластеризации текстов. Такие задачи могут выполняться по несколько десятков минут. Если бы веб-сервер мониторинга был запущен в основном потоке, то хелсчеки бы фейлились, потому что event-loop был бы заблокирован самой синхронной задачей. Если просто вынести этот сервер в отдельный поток, то мы потеряем его ключевое качество: отслеживание факта, что сервис не завис и всё ещё выполняет обработку задач. Здесь возможно следующее решение: из рабочего потока передавать информацию о его прогрессе во вспомогательной поток, в котором будет запущен веб-сервер, отдающий метрики и информацию по хелсчекам. Если задача зависла, прогресс перестанет обновляться и хелсчек зафейлится.

Следует, впрочем, учитывать наличие GIL в Python. В нашем конкретном случае проблем с блокировкой потока с мониторингом не возникало.

Хелсчеки вовне

В случае хелсчеков по каким-то внешним серверам, например по серверу БД, количество вещей, за которым стоит следить, серьёзно увеличивается.

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

Healthchecks.io

Пример. У нас каждую ночь запускаются бэкапы, используя MongoDB, и вот этот скрипт запускается по cron раз в сутки:

#!/usr/bin/env bash

set -e

FILENAME="spro_mongo_prod_$(date +%Y-%m-%d_%H-%M-%S).gz"
FULL_PATH="/backups/mongo/$FILENAME"

echo "Creating backup..."
mongodump ...

[[ $(find "${FULL_PATH}" -size +10k) ]]

TOKEN=...
TTL=...

curl -i -XPUT "https://api.selcdn.ru/v1/.../spro_backups/$FILENAME" \
   -H "X-Auth-Token: $TOKEN" \
   -H "X-Delete-After: $TTL" \
   -T "$FULL_PATH"

Мы хотим:

• знать, действительно ли он каждый день запускается

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

Все, что нужно сделать — добавить эти два запроса через curl на развёрнутый у нас в контуре инстанс сервиса healthchecks.io:

#!/usr/bin/env bash

set -e

FILENAME="spro_mongo_prod_$(date +%Y-%m-%d_%H-%M-%S).gz"
FULL_PATH="/backups/mongo/$FILENAME"

echo "Creating backup..."
curl https://{{ your_hc_instance }}/ping/{{ heathchecks_ping_key }}/mongo_backup_prod/start || true

mongodump ...

[[ $(find "${FULL_PATH}" -size +10k) ]]

TOKEN=...
TTL=...

curl -i -XPUT "https://api.selcdn.ru/v1/.../spro_backups/$FILENAME" \
   -H "X-Auth-Token: $TOKEN" \
   -H "X-Delete-After: $TTL" \
   -T "$FULL_PATH"

curl https://{{ your_hc_instance }}/ping/{{ heathchecks_ping_key }}/mongo_backup_prod || true

Первый запрос сигнализирует о том, что задача с указанным именем запущена, второй — что успешно завершена.

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

Алерты

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

Чтобы это все объединить и атомарно выкатывать код, метрики и алерты, удобно использовать PrometheusRule из Prometheus Operator в Kubernetes. 

---
apiVersion: monitoring.coreos.com/v1
kind: PrometheusRule
metadata:
  labels:
    role: alert-rules
    prometheus: {{ .Values.prometheus_cluster }}
  name: spro-rules
spec:
  groups:
    - name: engine
      rules:
        - alert: HighBlockExecutionTime
          labels:
            {{- include "spro.alert_labels" $ | nindent 12 }}
            severity: warning
            category: engine
          expr: |
            histogram_quantile(
              0.5,
                sum by (namespace, type, kind, channel_kind, le) (
                  rate(spro_engine_blocks_exec_seconds_bucket{kind!~".*google_sheets", kind!="http_request"}[3m])
                )
            ) > 5
          annotations:
            description: '{{ "{{ $labels.channel_kind }}/{{ $labels.type }}/{{ $labels.kind }}: {{ $value }} > 5" }}'

По сути, мы при выкатке добавляем еще одну yaml-спеку, в которой описывается не какой-нибудь Deployment, а выражение на PromQL и аннотация, которая потом отправится в чатик через алерт-менеджер ответственным разработчикам или админам.

Мониторинг пользователей и trace_id

Предположим, что менеджер запускает в админке какую-то задачу. Задача состоит из нескольких этапов, и для её обработки задействовано несколько разных сервисов. На фронтенде генерируется какой-то случайный идентификатор – trace_id. Этот идентификатор привязывается к запросу пользователя и передаётся, например, в заголовке X-Request-ID. По мере прохождения каждого этапа обработки этого запроса, мы все время привязываем всю информацию в логах и в Sentry к этому trace_id. 

Зачем нужен trace_id на практике

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

1. Явно или неявно получаем от пользователя user_id, project_id или сообщение в чате, при обработке которого возникли проблемы

2. Находим одну любую запись в логе, относящуюся к процессу обработки этого сообщения или запроса, и из нее берем trace_id.

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

Sentry

Думаю, Sentry в представлении не нуждается, но я бы хотел упомянуть про один важный нюанс. Помимо тегов, которые есть в каждом issue по умолчанию (IP пользователя, уровень сообщения в логе и номер релиза), сюда можно добавлять произвольные атрибуты, по которым удобно организовать поиск. Например, user_id или trace_id, который поможет связать конкретную ошибку с конкретным запросом пользователя.

В Sentry SDK для этого есть метод Scope.set_tag().

У нас в проекте scope Sentry, логгер и различные атрибуты вроде user_id, project_id и trace_id объединены в одну сущность — Context.

В коде это выглядит следующим образом:

async def process_task(self, task: Task):
    with Context(trace_id=task.trace_id) as ctx:
        ctx.project_id = task.project_id
        try:
            await something()
        except Exception:
            ctx.logger.exception('something failed')

Мы получаем задачу из очереди, из неё берёмtrace_id, сгенерированный в предыдущем сервисе, project_id и начинаем выполнять обработку этой задачи. Если нам нужно залогировать какую-то информацию в лог или в Sentry, мы обращаемся к логгеру, который привязан к контексту. 

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

class Context:
    def __init__(self, trace_id: str | None = None):
        self._trace_id = trace_id or self._generate_trace_id()
        self._user_id = None
        self._project_id = None

        self._logger = self.create_logger()
        self._sentry_scope_cm: ContextManager[Scope] | None = None

    def __enter__(self) -> 'Context':
        self._sentry_scope_cm = push_scope()
        scope = self._sentry_scope_cm.__enter__()
        scope.set_tag('trace_id', self._trace_td)
        scope.set_extra('trace_id', self._trace_id)
        return self

    def exit (self, exc_type, exc_val, exc_tb):
        if self._sentry_scope_cm is not None:
            self._sentry_scope_cm.__exit__(exc_type, exc_val, exc_tb)

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

Полезный приём. В Sentry по дефолту объекты в стеке отображаются следующим образом:

То есть это просто имя класса и его id(). Это совершенно не информативно. Но мы знаем, что, например, дикты, Sentry показывает подробно: с интерактивным интерфейсом для раскрытия вложенных полей и подсветкой типов значений. Этим фактом можно воспользоваться, если наш класс контекста наследовать вот от такого миксина, который реализует интерфейс collections.abc.Mapping:

class SentryInspectableMixin(Mapping):
    def items(self):
        return self.__dict__.items()

    def __getitem__(self, item):
        return self.__dict__.__getitem__(item)

    def __iter__(self):
        return self.__dict__.__iter__()

    def __len__(self):
        return self.__dict__.__len__()

В результате контекст, хоть это и не дикт, будет отображаться в такой подробной развёртке по всем полям: 

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

Логи

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

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

Сбор логов. Loki

Для сбора логов мы используем Loki.  Вот так это выглядит:

У нас цветные логи, для этого мы используем библиотеку colorlog. Белым отмечено то сообщение, которое логируется из бизнес-логики, а серым — контекст, состоящий из кучи всяких идентификаторов. Вторая часть обычно не столь важна при визуальном просмотре, но очень удобна для индексации и поиске по атрибутам.  Если мы нажимаем на любую запись в логе, то видим контекст в разбивке по отдельным атрибутам.

Можно кликнуть на любой атрибут и посмотреть распределение по всей выборке логов. Например, мы видим, что в 87% случаев эта проблема затрагивала один и тот же проект: 

В Loki есть 2 вида атрибутов: те по которым происходит разбиение данных при хранении (индексируемые – labels), и те которые просто парсятся из строки по символу “=” (неиндексируемые – fields).

Пример поискового запроса (здесь app и component — индексируемые атрибуты, а по “pid=” мы просто ищем подстроку):

Логи. Контекст

Пример:

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

ctx.logger.info('Entering block {type=} {kind=} {name=}')

Как уже было указано выше, логгер привязан к контексту, и вся дополнительная информация к записи добавляется автоматически. Мы используем стандартный python-модуль logging, а для привязки контекста мы переопределяем методы process() и log() у LoggerAdapter, где прокидываем данные из контекста в поля словаря extra:

class SProContextLogger(LoggerAdapter):
    def __init__(self, ctx: 'Context', logger: Logger, extra: Optional[Mapping[str, Any]]):
        super().__init__(logger, extra)
        self.ctx = weakref.ref(ctx)

    def process(self, msg: Any, kwargs: MutableMapping[str, Any]) -> tuple[Any, MutableMapping[str, Any]]:
        ctx = self.ctx()
        assert ctx, 'Context is dead'

        extra = kwargs.setdefault('extra', {})
        data_str = ' '.join(
            f'{k}={getattr(ctx.data, k)}'
            for k in ctx.data.__dict__.keys()
            if k not in ctx.non_loggable_data and not k.startswith('_')
        )
        extra.update({
            'trace_id': ctx.trace_id,
            'ctx': ctx.trace_id,
            'user_id': ctx.user.id,
            'data': data_str,
        })

        return msg, kwargs

    def log(self, *args, **kwargs):
        with push_scope() as scope:
            if self.ctx is not None:
                scope.set_tag('trace_id', self.ctx().trace_id)

            stacklevel = kwargs.pop('stacklevel', 1) + 2
            return super().log(*args, **kwargs, stacklevel=stacklevel)

В форматной строке логгера мы указываем эти дополнительные поля в формате “field=%(key)s”:

class ColoredContextFormatter(GenericFormatter, colorlog.ColoredFormatter):
    FORMAT = '%(log_color)s%(asctime)s' \
             ' [%(module).16s:%(funcName).16s:%(lineno)d]' \
             ' %(levelname)s:' \
             ' %(white)s%(message)s' \
             ' %(thin_white)s' \
             'trace_id=%(trace_id)s %(data)s' \
             '%(reset)s'

Есть и другие способы для пробрасывания контекста в логи, например, ContextVar. Тогда не нужно создавать LoggerAdapter на каждый запрос, а контекст можно получить по текущему id таска в ивент-лупе asyncio. Подробно про разные варианты привязки контекста можно почитать в официальной документации.

Заключение

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

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

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