Слепота
Прод. Пользователь пишет: «сайт тупит». Ты открываешь сайт - всё быстро. Открываешь консоль браузера - чисто. И всё, тупик. Ты не знаешь, что у него тормозило, когда, на какой странице и из-за чего.
Это и есть слепота. И обиднее всего то, что Next.js-приложение - это сервер. Рендер страниц, server actions, запросы к бэкенду - всё это код, который выполняется у тебя на машине, и ты мог бы знать про него всё. Но не знаешь, потому что не логируешь.
В какой-то момент я устал гадать и прикрутил логирование: pino, Loki, Grafana. Дальше - про то, что это дало, почему именно так, и стоило ли оно вообще того.
Оговорка про код. Дальше будет несколько фрагментов, но это псевдокод - упрощённый до сути. Рабочие версии длиннее: типы, обработка ошибок, край-кейсы. Здесь только идея.
Что это дало
Начну с конца - с того, что я теперь вижу и чего не видел раньше.
- Какая ручка бэкенда сколько отвечает. Не «бэкенд медленный», а «эндпоинт цен отвечает 1.2 секунды на 95-м перцентиле, и стало хуже после вчерашнего деплоя».
- Где именно отваливается. Таймаут до бэкенда теперь не «ой, у пользователя не открылись цены», а конкретная строка: какой сервис, какой запрос, сколько ждали, почему упало.
- Как быстро открывается сайт у реальных людей. Не у меня на ноуте с оптоволокном, а у пользователя с дешёвым Android - его LCP, его перцентили.
- Весь путь одного запроса. Один фильтр - и видно всю цепочку: страница отрендерилась, дёрнулись три ручки бэкенда, одна тормознула, пользователь получил такой-то LCP.
Вот реальная (обезличенная) строка из Loki - бэкенд не ответил за 5 секунд:
{
"level": "error",
"event": "fetch",
"service": "catalog_prices",
"url": "https://catalog-api.internal/v1/prices?city=almaty",
"duration_ms": 5004,
"aborted": true,
"err_name": "TimeoutError",
"requestId": "5f2869b1...",
"release": "a1b2c3d4",
"msg": "fetch_failed"
}Одна строка - и инцидент понятен целиком: какая ручка, какой город, сколько ждали, что упало, на какой сборке. Раньше такое расследование занимало полдня переписки «а что было, а когда, а у кого».
Почему pino, Loki, Grafana
console.log пишет строки. Человек их прочитает, машина - нет. А когда логов тысячи в минуту, читать их глазами бессмысленно: нужны графики, фильтры, перцентили. Для этого лог должен быть структурированным - не текстом, а объектом с полями.
pino ровно это и делает: каждая запись - JSON-объект. Он быстрый, почти не добавляет оверхеда, и пишет в stdout - дальше дело за инфраструктурой.
Loki - это хранилище логов, Grafana - то, где ты на них смотришь: графики, дашборды, алерты. Связка популярная и дешёвая: Loki не индексирует содержимое строк (в отличие от Elasticsearch), поэтому хранить в нём много - подъёмно по деньгам.
Ключевая мысль: ты не «пишешь логи». Ты складываешь структурированные события, по которым потом можно задавать вопросы. Чтобы вопросы было удобно задавать, у каждого события есть пара служебных полей:
event- что произошло:fetch,page_render,client_web_vital. Главная ось фильтрации.release- git SHA сборки. После деплоя сразу видно, новая версия начала тормозить или нет. Бесценно.requestId- про него отдельный раздел, это вообще главная фича.
Сквозной requestId - то, ради чего всё заиграло
Отдельные логи - это просто куча строк. Магия начинается, когда строки одного запроса можно собрать вместе.
Для этого нужен сквозной идентификатор - requestId. Он рождается в начале запроса (его проставляет nginx или ingress, либо генерируем сами) и дальше попадает в каждую строку: в лог рендера, в логи всех запросов к бэкенду и даже в клиентские метрики - сервер отдаёт requestId в HTML, клиент прикладывает его к своим логам.
Протаскивать его аргументом через каждую функцию - ад. Поэтому он живёт в AsyncLocalStorage - это «контекст», привязанный к жизненному циклу запроса:
// в начале запроса - один раз
runWithContext({ requestId, route }, () => renderPage())
// дальше где угодно, без проброса аргументов
const log = getLogger() // подмешает requestId из контекста сам
log.info({ event: "fetch", ... })
Что это даёт на практике: в Grafana пишешь один фильтр по requestId - и получаешь всю историю запроса в хронологии. Это превращает «логи» в «трассировку». Разница примерно как между «у меня есть фотографии» и «у меня есть видео».
Сэмплирование - иначе Loki разорит
Неприятная правда: на проде логов МНОГО. Запросы к бэкенду - это процентов 90 всех строк, и почти все они скучные: 200 OK, быстро. Хранить это всё - деньги на ровном месте.
Но и просто «логировать поменьше» нельзя - потеряешь как раз тот единственный запрос, который сломался.
Решение - head-based сэмплирование. В начале запроса один раз бросаем монетку: логировать этот запрос целиком или нет. Решение кладём в тот же контекст. Дальше: повезло (скажем, 10% запросов) - сохраняем все его события, полную трассу; не повезло - выкидываем скучные fetch-логи этого запроса.
Важная деталь: ошибки, не-2xx ответы и медленные запросы сохраняются всегда, мимо всякого сэмплирования. Сэмплируем только зелёный шум:
shouldDrop(line):
if line.event не fetch/axios: keep // остальное не трогаем
if line.status >= 400: keep // ошибки - всегда
if line.duration_ms >= 1s: keep // тормоза - всегда
else: drop, если запросу не выпал жребий
Технически это вешается одним хуком на сам логгер - он решает, писать строку или молча её проглотить. В местах вызова логирования не меняется ничего.
Итог: объём fetch-логов падает в 10 раз, а всё важное - ошибки, тормоза и полные трассы 10% запросов - остаётся. Дашборды не врут, инциденты разбираются.
Что именно логируем
Три типа событий, по убыванию пользы.
Запросы к бэкенду. Главное. Оборачиваем fetch в обёртку, которая меряет время и пишет лог. Заодно ставим таймаут - чтобы зависший бэкенд не держал наш запрос вечно:
loggedFetch(service, url, opts):
start = now()
try:
res = await fetch(url, { ...opts, timeout: 5s })
log.info({ event: "fetch", service, status: res.status, duration_ms: now()-start })
return res
catch err:
log.error({ event: "fetch", service, aborted: isTimeout(err), duration_ms: now()-start })
throw err
Что даёт: тайминги каждой ручки, p95, и - главное - таймауты. Та строка из начала статьи родилась именно здесь.
Рендер страниц. Обёртка над рендером (в App Router - над серверным компонентом, в Pages Router - над getServerSideProps). Заодно это удобная точка, где рождается requestId и контекст запроса. Что даёт: видно, какая страница рендерится медленно и не деградировал ли рендер после деплоя.
Web Vitals с клиента. Единственное, что снимается в браузере: LCP, CLS, INP - то, как сайт ощущается живым пользователем. Хук Next.js useReportWebVitals отдаёт метрики, клиентский логгер копит их в буфер и шлёт пачкой на сервер - по таймеру или когда пользователь уходит со страницы (через sendBeacon, чтобы отправка пережила закрытие вкладки). Что даёт: реальная производительность у реальных людей, а не у тебя на ноуте.
Grafana: вопросы, на которые теперь есть ответ
Логи в Loki - дальше LogQL. Несколько запросов, которые реально пригодились.
Медленные ручки бэкенда:
{app="storefront"} | json | event="fetch" | duration_ms > 1000Все таймауты:
{app="storefront"} | json | event="fetch" | aborted="true"Весь путь одного запроса - та самая трассировка:
{app="storefront"} | json | requestId="5f2869b1..."Эти запросы кидаются на дашборд: p95 по ручкам, счётчик таймаутов, распределение LCP. Один раз настроил - и больше не гадаешь «тормозит или кажется», а смотришь на цифры.
Практические грабли
Коротко - то, на чём посидел.
- Middleware - это Edge Runtime. pino там не работает: нет нужных Node.js API. Если логируешь в middleware - только
console.logс JSON руками. - Доставка в Loki - развилка. Транспорт
pino-lokiшлёт логи прямо из приложения (быстро завести, но транспорты pino гоняют worker threads, и бандлер Next.js ломает им пути). Либо приложение пишет в stdout, а рядом стоит агент (Grafana Alloy, Promtail, Vector) и шлёт сам. В кластере выбрал второе: приложение не должно отвечать за доставку - упал Loki, агент разрулит с буфером и ретраями. - Не делай уникальные поля метками Loki.
requestId,duration_ms,urlкак label - это взрыв индекса. Метки - только для низкокардинального:app,env,release. Остальное достаётся из JSON прямо в запросе. - redact обязателен. Токены, куки, телефоны не должны утекать в логи. Настраивается один раз в конфиге pino.
Стоило ли оно того
Да, и сильно.
Не из-за красивых дашбордов. А из-за того, что изменился сам режим работы. Раньше отладка прода была археологией: собираешь обрывки, опрашиваешь людей, гадаешь. Теперь это вопрос с ответом - открыл Grafana, отфильтровал, увидел.
По времени костяк - логгер, контекст, обёртка над fetch это пара дней. Сэмплирование и клиентские метрики докручивались потом, по мере того как Loki начинал пухнуть, а вопросов становилось больше.
Кому не стоит: если у вас лендинг или маленький сайт без серверной логики - это оверкилл, хватит и встроенной аналитики хостинга. Логирование такого уровня окупается там, где Next.js реально работает как бэкенд: ходит в кучу сервисов, рендерит динамику, и цена минуты простоя не равна нулю.
Для такого проекта это не «ещё одна модная штука в стек». Это разница между «чинить вслепую» и «видеть».