У меня нехорошее предчувствие... Это нечто неуловимое...

(c) Оби-Ван Кеноби

Звёздные войны. Эпизод I. Скрытая угроза

Привет, Хабр!

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

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

Цель этой статьи - рассказать, как я, будучи Node.js разработчиком, столкнулся с отсутствием мониторинга логов и как разработчику настроить свой первый Grafana-дашборд, который легко масштабировать в полноценную систему мониторинга.

Скрытая угроза

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

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

Прочитав вводные данные, понимаю, что, если ошибка массовая, то проще ее воспроизвести на дев стенде, чем копаться в сырых pm2 логах. Воспроизвести баг не удалось - пришлось лезть на сервер в логи, которые просто писались в консоль.

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

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

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

Инструментарий

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

легковесный - требует меньше ресурсов, чем ELK-стек
прост в настройке конфигураций для старта
Pino - один из самых быстрых асинхронных JSON-логгеров в Node.js, что позволяет справляться с потоками логов
удобный просмотр и визуализация логов в Grafana
не требований для сложной и тяжелой аналитики логов

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

Итак, на примере простого NestJS приложения, рассмотрим построение первого Grafana-дашборда с логами.

Установка Grafana и Loki в Docker

Начнем с настройки инфраструктуры для сбора и визуализации логов. Развернем Grafana и Loki с помощью docker-compose:

version: '3.8'

services:
  loki:
    image: grafana/loki:latest
    ports:
      - "3100:3100"
    command: -config.file=/etc/loki/local-config.yaml
    volumes:
      - loki_data:/loki
    healthcheck:
      test: ["CMD-SHELL", "wget -q --tries=1 -O- http://localhost:3100/ready"]
      interval: 10s
      timeout: 5s
      retries: 5
    restart: unless-stopped

  grafana:
    image: grafana/grafana:latest
    ports:
      - "3000:3000"
    environment:
      - GF_SECURITY_ADMIN_USER=admin
      - GF_SECURITY_ADMIN_PASSWORD=admin
    depends_on:
      - loki
    volumes:
      - grafana_data:/var/lib/grafana
    healthcheck:
      test: ["CMD-SHELL", "wget -q --tries=1 -O- http://localhost:3000/api/health"]
      interval: 10s
      timeout: 5s
      retries: 5
    restart: unless-stopped

volumes:
  loki_data:
  grafana_data:

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

Запуск инфраструктуры:

docker-compose up -d

После успешного запуска контейнеров настроим подключение Loki к Grafana.

Настройка Grafana с Loki Data source

Переходим на http://localhost:3000 и видим, что открылся интерфейс Grafana. Вводим логин и пароль и переходим во вкладку Data sources.

Здесь нажимаем Add new data source и в выпадающем списке выбираем Loki. Открывается вкладка с настройками Loki data source. Для подключения достаточно указать name и Connection. При запуске Loki в docker-compose указать Connection следует как http://loki:3100 (или вместо loki то название, которое вы указали в наименовании сервиса в docker-compose.yml).

Получаем настройки, как на картинке.

Нажимаем Save & test, и если Loki доступен, то data source сохраняется.

На следующем шаге настроим отправку логов в Loki из NestJS приложения.

Настройка Pino

Установим зависимости для работы с Pino в приложении:

npm i nestjs-pino pino-http pino-loki @nestjs/config --save

После установки настроим конфигурацию Pino:

import { ConfigModule, ConfigService } from '@nestjs/config';
import { LoggerModuleAsyncParams } from 'nestjs-pino';

export const pinoConfig: LoggerModuleAsyncParams = {
    imports: [ConfigModule],
    useFactory: () => ({
        pinoHttp: {
            level: 'info',
            customLogLevel: (res, err) => {
                if (err || res.statusCode >= 500) return 'error';
                if (res.statusCode >= 400) return 'warn';
                return 'info';
            },
            customSuccessMessage: (req, res) =>
                `${req.method} ${req.url} -> ${res.statusCode}`,
            customErrorMessage: (req, res, err) =>
                  `ERROR ${req.method} ${req.url} -> ${res.statusCode}: 
                      ${err?.message}`,
            serializers: {
                req(req) {
                    return {
                        method: req.method,
                        url: req.url,
                    };
                },
                res(res) {
                    return {
                        statusCode: res.statusCode,
                        responseTime: res.responseTime,
                    };
                },
                err(err) {
                    if (!err) return undefined;
                    return {
                        message: err.message,
                    };
                },
            },
            transport: {
                target: 'pino-loki',
                options: {
                    host: 'http://localhost:3100',
                    json: true,
                    batch: true,
                    labels: { app: 'nestjs-loki-grafana' },
                },
            },
        },
    }),
    inject: [ConfigService],
};

Краткое объяснение конфигурации:

настройка уровня логирования - оставляем дефолтный "info"
обязательно указываем serializers, который позволяет нам выводить в будущем дашборде только те поля, которые нам нужны (например, без чувствительных данных)
в качестве транспорта указываем "pino-loki"
особенно важно в options указать host, где развернут Loki (в нашем случае localhost) и labels (для чего эта настройка необходима станет ясно дальше)

Теперь добавим LoggerModule с кастомной конфигурацией в основной AppModule:

import { Module } from '@nestjs/common';
import { AppController } from './app.controller';
import { AppService } from './app.service';
import { LoggerModule } from 'nestjs-pino';
import { pinoConfig } from './logger.config';

@Module({
    imports: [
        LoggerModule.forRootAsync(pinoConfig),
    ],
    controllers: [AppController],
    providers: [AppService],
})
export class AppModule {}

В функции запуска в файле main.ts указываем:

import { NestFactory } from '@nestjs/core';
import { AppModule } from './app.module';
import { Logger } from 'nestjs-pino';

async function bootstrap() {
    const app = await NestFactory.create(AppModule);

    app.useLogger(app.get(Logger));
    
    await app.listen(process.env.PORT ?? 3001);
}
bootstrap();

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

Запускаем приложение, например, в режиме разработки:

npm run start:dev

UPD: Порт веб-приложения изменен на 3001, так как Grafana заняла уже стандартный 3000 порт Неста.

Настройка Grafana-дашборда

Возвращаемся в Grafana интерфейс и переходим во вкладку Explore. Открывается окно настройки запроса. В выпадающем списке выбираем уже настроенный data source "loki", и вводим запрос на получение логов нашего приложения:

{app="nestjs-loki-grafana"}

Почему именное так? Ранее в конфигурации Pino мы указали labels: { app: 'nestjs-loki-grafana' }. Это и есть имя нашего приложения для интеграции с Loki.

Нажимаем Run query, и, если все правильно настроено, мы получаем наши первые логи приложения в интерфейсе Grafana.

Мы получили логи запросом, но теперь стоит настроить дашборд, чтобы логи сами регулярно обновлялись в интерфейсе. Переходим в Dashboards -> New dashboard -> Add visualization -> Выбираем Loki в качестве data source. В открывшемся окне снова вводим запрос из листинга кода выше. В меню справа выбираем формат вывода "Logs" и настраиваем параметры визуализации, например, я выбираю обязательный показ времени записи лога (Time) и красивый вывод JSON (Prettify JSON).

Нажимаем Save dashboard, выполняем какой-нибудь запрос в приложении и... Вуаля! Получаем наш первый дашбоард, который выглядит примерно так:

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

Выбор периода просмотра логов по датам в Grafana-дашборде

Поздравляю! Вы настроили только что первый дашборд с логами, который, надеюсь, станет отправной точкой для построения эффективной системы мониторинга состояния вашего веб-приложения.

Весь приведенный код можно посмотреть в репозитории: https://github.com/Ivanbyone/nestjs-loki-grafana

Что же дальше?

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

Какие пути развития можно предложить? Вот несколько идей:

создание информативного дашборда с группировкой логов по статус кодам (пример)
добавить Promtail для отправки логов в Loki
развернуть Prometeus и начать собирать метрики потребления ресурсов веб-приложением и инфраструктурой

Мониторинг состояния веб-приложения предоставляет неограниченную почву для кастомизаций и экспериментов.

Поэтому совет разработчикам: пробуйте и экспериментируйте, и да прибудет с вами сила!

Простой Grafana дашборд для логов NestJS (feat nestjs-pino, Loki)