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

Предыстория

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

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

Промежуточный слой

Первым на своём пути мы встречаем промежуточное ПО. В документации даже сказано:

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

Хорошо, вроде ничего сложного. Пора выбирать библиотеку логирования. Я обратился к pino, так как уже с ней знаком. Хотя любое решение будет лучше, чем console.log. Думаю, разберёмся с этим до обеда.

Начнём с настройки основного промежуточного ПО:

// middleware.ts

import { NextResponse, NextRequest } from "next/server";
export async function middleware(request: NextRequest) {
  return new NextResponse.next({
    request: request,
    headers: request.headers,
    // status: 200,
    // statusText: 'OK'
  });
}

export const config = {
  matcher: "/:path*",
};

Думаю, что у нас уже возникла проблема. Из своего промежуточного ПО мы можем передать не более 4 параметров. Единственное, что реально влияет на задействованный маршрут, это headers. Давайте не будем упускать тот факт, что нельзя использовать несколько промежуточных программ или связывать их в цепочку. Как же можно было так налажать? Мы используем программные прослойки с начала 2010-х, когда только появился Express.

Как бы то ни было, мы достаточно умны, и можем воспользоваться изящными решениями, которые предлагает нам современный Node.js. Обратимся к AsyncLocalStorage.

// app/logger.ts
import { AsyncLocalStorage } from "async_hooks";
import { Logger, pino } from "pino";

const loggerInstance = pino({
  // Необходимая конфигурация.
  level: process.env.LOG_LEVEL ?? "trace",
});

export const LoggerStorage = new AsyncLocalStorage<Logger>();

export function logger(): Logger | null {
  return LoggerStorage.getStore() ?? null;
}

export function requestLogger(): Logger {
  return loggerInstance.child({ requestId: crypto.randomUUID() });
}

// middleware.ts
export async function middleware(request: NextRequest) {
  LoggerStorage.enterWith(requestLogger());
  logger()?.debug({ url: request.url }, "Started processing request!");

  return NextResponse.next();
}

Уфф…самое тяжёлое позади. Теперь протестируем всё это. Переходим на localhost:3000 и видим следующее:

{ requestId: 'ec7718fa-b1a2-473e-b2e2-8f51188efa8f' } { url: 'http://localhost:3000/' } 'Started processing request!'
 GET / 200 in 71ms
{ requestId: '09b526b1-68f4-4e90-971f-b0bc52ad167c' } { url: 'http://localhost:3000/next.svg' } 'Started processing request!'
{ requestId: '481dd2ff-e900-4985-ae15-0b0a1eb5923f' } { url: 'http://localhost:3000/vercel.svg' } 'Started processing request!'
{ requestId: 'e7b29301-171c-4c91-af25-771471502ee4' } { url: 'http://localhost:3000/file.svg' } 'Started processing request!'
{ requestId: '13766de3-dd00-42ce-808a-ac072dcfd4c6' } { url: 'http://localhost:3000/window.svg' } 'Started processing request!'
{ requestId: '317e054c-1a9a-4dd8-ba21-4c0201fbeada' } { url: 'http://localhost:3000/globe.svg' } 'Started processing request!'

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

Я не Next.js и томить вас ожиданиями не стану. Это вывод браузера. Почему? Ну, потому что по умолчанию средой выполнения промежуточного ПО в Next.js является edje. Да, мы можем переключиться на среду nodejs, которая должна нормально заработать. Вот только на деле это может оказаться не так.

Я пробовал такой подход в свеженьком проекте Next.js, и у меня получилось. Но вот повторить это в реальном проекте мне не удалось. Не подумайте, я не сумасшедший. Ну да ладно, основная проблема всё равно не в этом. Мы постепенно к ней приближаемся.

Перелистывая местные хроники безумств

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

// app/page.tsx
export default function Home() {
  logger()?.info("Logging from the page!");
 
  return <div>Real simple website!</div>
}

 Теперь обновляем страницу и получаем: 

✓ Compiled / in 16ms
 GET / 200 in 142ms

И всё? И всё. Ничего. Совсем.

Для сохранения исторической ясности покажу, как этот вывод должен выглядеть:

✓ Compiled / in 2.2s
[11:38:59.259] INFO (12599): Logging from the page!
    requestId: "2ddef9cf-6fee-4d1d-8b1e-6bb16a3e636b"
 GET / 200 in 2520ms

Ладно, что-то я затянул, пора переходить к сути. Функция logger возвращает null. Почему? Не уверен, но мне кажется, что рендеринг выполняется не в том же асинхронном контексте, что и промежуточное ПО.

И что с этим делать? Вы не поверите. Помните, что из промежуточной программы можно передать лишь одно значение — headers? Да, именно это нам и нужно.

Следующий код не для слабонервных:

// app/log/serverLogger.ts
import { pino } from "pino";

export const loggerInstance = pino({
  // Необходимая конфигурация.
  level: process.env.LOG_LEVEL ?? "info",
});

// app/log/middleware.ts
// Да, нужно разделить логгеры ...
// Здесь почти всё то же самое.
import { loggerInstance } from "./serverLogger";

export function requestLogger(requestId: string): Logger {
  return loggerInstance.child({ requestId });
}

// app/log/server.ts
import { headers } from "next/headers";
import { loggerInstance } from "./serverLogger";
import { Logger } from "pino";
import { NextRequest } from "next/server";

const REQUEST_ID_HEADER = "dominik-request-id";

export function requestHeaders(
  request: NextRequest,
  requestId: string,
): Headers {
  const head = new Headers(request.headers);
  head.set(REQUEST_ID_HEADER, requestId);
  return head;
} 

// Да, эта функция должна быть асинхронной ...
export async function logger(): Promise<Logger> {
  const hdrs = await headers();
  const requestId = hdrs.get(REQUEST_ID_HEADER);
 
  return loggerInstance.child({ requestId });
}
 
// middleware.ts
import { logger, LoggerStorage, requestLogger } from "./app/log/middleware";
import { requestHeaders } from "./app/log/server"; 

export async function middleware(request: NextRequest) {
  const requestId = crypto.randomUUID();
  LoggerStorage.enterWith(requestLogger(requestId));
 
  logger()?.debug({ url: request.url }, "Started processing request!");

  return NextResponse.next({ headers: requestHeaders(request, requestId) });
}

// app/page.tsx
export default async function Home() {
  (await logger())?.info("Logging from the page!");

  // ...
}

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

Вас принимают за детей

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

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

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

Взглянем на пример из документации:

import { createServer } from 'http'
import { parse } from 'url'
import next from 'next'

const port = parseInt(process.env.PORT || '3000', 10)
const dev = process.env.NODE_ENV !== 'production'
const app = next({ dev })
const handle = app.getRequestHandler()

app.prepare().then(() => {
  createServer((req, res) => {
    const parsedUrl = parse(req.url!, true)
    handle(req, res, parsedUrl)
  }).listen(port)

  console.log(
    `> Server listening at http://localhost:${port} as ${
      dev ? 'development' : process.env.NODE_ENV
    }`
  )
})

Обратите внимание, что здесь снова handle не получает никакие параметры — только URL запроса, сам сырой запрос и ответ.

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

// app/logger.ts
// Возвращаемся к нашей вариации с AsyncLocalStorage.
import { pino, Logger } from "pino";
import { AsyncLocalStorage } from "async_hooks";

const loggerInstance = pino({
  // Вся необходимая конфигурация.
  level: process.env.LOG_LEVEL ?? "info",
});

export const LoggerStorage = new AsyncLocalStorage<Logger>();

export function logger(): Logger | null {
  return LoggerStorage.getStore() ?? null;
}

export function requestLogger(): Logger {
  return loggerInstance.child({ requestId: crypto.randomUUID() });
}

// server.ts
import { logger, LoggerStorage, requestLogger } from "./app/logger";

app.prepare().then(() => {
  createServer(async (req, res) => {
    // Новый код.
    LoggerStorage.enterWith(requestLogger());
    logger()?.info({}, "Logging from server!");

    const parsedUrl = parse(req.url!, true);
    await handle(req, res, parsedUrl);
  }).listen(port);
});

// middleware.ts
import { logger } from "./app/logger";

export async function middleware(request: NextRequest) {
  logger()?.info({}, "Logging from middleware!");
  return NextResponse.next();
}

// app/page.tsx
import { logger } from "./logger";

export default async function Home() {
  logger()?.info("Logging from the page!");

  // ...
}

Хорошо, теперь протестируем наше решение. Обновляем браузер, и …

> Server listening at http://localhost:3000 as development
[12:29:52.183] INFO (19938): Logging from server!
    requestId: "2ffab9a2-7e15-4188-8959-a7822592108f"
 ✓ Compiled /middleware in 388ms (151 modules)
 ○ Compiling / ...
 ✓ Compiled / in 676ms (769 modules)

И всё. Да они издеваются. Какого хрена?

Тут вы можете подумать, что AsyncLocalStorage работает не так. И вполне можете оказаться правы, но я напомню, что headers() и cookies() используют AsyncLocalStorage. Это то преимущество разработчиков Next.js, которого у нас нет.

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

• Заголовки

• NextResponse.redirect / NextResponse.rewrite для перенаправления ответа с дополнительными параметрами (например, /[requestId]/page.tsx)

Как вы могли заметить, радужным ни один из них в нашем случае не выглядит. К вам просто относятся как к детям. Разработчики Next.js имеют чёткое представление о том, как всё должно работать, и вы либо ему подчиняетесь, либо проходите мимо. Обратите внимание: если бы это касалось только промежуточного ПО, то я бы не стал тратить свои выходные на всю эту критику фреймворка React. У меня есть дела поважнее. Но это постоянная боль, с которой при работе с Next.js вы встречаетесь ежедневно.

Vercel может лучше

Бесит же в этом примере то, что Vercel может справиться с подобными задачами намного лучше. Я не хочу излишне хвалить Svelte(Kit), так как их последние решения вызывают у меня опасения, но этот фреймворк намного лучше Next.js. Давайте заглянем в их документацию по промежуточному ПО:

handle — эта функция выполняется при каждом получении запроса сервером SvelteKit [...] Она позволяет изменять заголовки или тело ответа, либо полностью обходить SvelteKit (для программной реализации маршрутов, например).

Пока звучит неплохо. 

locals — чтобы добавить собственные данные в запрос, который передаётся обработчикам в +server.js и серверным функциям load, заполните объект event.locals как показано ниже.

На моих глазах от радости навернулись слёзы. Туда также можно передавать реальные объекты и классы — например, логгер.

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

Вот так выглядит реальный инжиниринг. SvelteKit — это продукт Vercel. Но как так получается, что флагманский проект уступает побочному по возможностям? Что за чертовщина?

Учёные открыли сверхмассивную чёрную дыру в https://github.com/vercel/next.js/issues

Мне больше нечего особо добавить, но раз уж мы тут все собрались, то будет уместным упомянуть про баг-трекер на GitHub. Это, пожалуй, вершина всей той мусорной кучи недоразумений, которые есть в Next.js. Это то место, куда все надежды и мольбы приходят умирать. Среднее время ответа на баг-репорт здесь — никогда. Я из спортивного интереса решил поискать истории отправки отчётов о багах и их обсуждения касательно тех проблем, с которыми сталкивался сам. В итоге я даже готов принимать ставки на то, сколько лет уйдёт, чтобы получить ответ от команды Next.js.

Думаете, я шучу? Здесь годами лежат сотни запросов с кучей эмодзи 👍 в ожидании официального ответа. И когда этот ответ, наконец, приходит, в нём говорится, что вы действуете неправильно, и решение для ваших реальных проблем уже в разработке. После этого упомянутое «решение» ещё несколько лет томится в канареечной версии.   

Я сам лично отправлял два баг-репорта год назад. Имейте в виду, что для создания валидного баг-репорта вам нужно воспроизвести проблему.

• https://github.com/vercel/next.js/issues/67034

• https://github.com/vercel/next.js/issues/64253

И что же ты получаешь за время, потраченное на минимальное воспроизведение бага? Всё верно. Полное молчание.

Я бы сообщил ещё о десятке проблем, которые встречал, но после такого уже не стал.

Честно говоря, даже не знаю, существуют ли ещё те баги.

Какие здесь можно сделать выводы?

Не знаю. Лично я больше не хочу использовать Next.js. Вы можете решить, что это всего-навсего одна проблема, которую я преувеличил. Но в этом фреймворке на каждом углу можно встретить баги и пограничные случаи. Как они вообще умудрились сделать так, что TypeScript компилируется медленнее Rust? Зачем проводить различие между кодом, выполняющемся на клиенте и на сервере, не предоставляя никаких инструментов для использования этого факта? Зачем? Почему? И так далее. Не думаю, что у меня хватит ресурса, чтобы вытащить всех нас из этого болота Next.js. Но я обязательно озвучу своё мнение, если в итоге мы напишем другое приложение. Посмотрим, вдруг трава в нём окажется зеленее.