0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

Day 18

KCCS 先端技術開発 Advent Calendar 2025

@kccs_yoshiteru-imamura(Yoshiteru Imamura)in京セラコミュニケーションシステム（先端技術開発）

Next.jsでAsyncLocalStorageを用いたリクエストログ出力（その１）

0
Posted at

京セラコミュニケーションシステム株式会社 先端技術統括部 開発イノベーション部 開発イノベーション3課の今村です。
最近、Next.jsを用いたWebシステムを開発した際のTipsを執筆いたします。

はじめに

今回、loggerとしてpinoを使用しました。
Webシステムのサーバーロジックでは同時に複数のリクエストを処理しますが、普通にログを出力すると単純に時系列で出力されるため、出力されたログから一つのリクエストの括りがわからず、解析に苦労するということがあります。
本記事は、リクエスト中のログに対して、ログの中にRequestIDを埋め込む方法になります。

対象読者

  • Next.jsで開発した経験のある人で、ログ出力に困っているエンジニア

前提条件

今回の記事にのせているコードは、以下の環境で動作確認しています。

バージョン
Node 22.21.1
Next.js 16.0.6
pino 10.1.0

※Node.jsの環境は構築済みの前提です。

loggerの追加

MITライセンスですが、商用利用される場合はご注意ください。

下記コマンドにてpinoパッケージをインストールします。

npm install pino

サンプルプログラムについて

本記事では、サーバーロジックにてリクエスト時に独自のRequestIDを採番し、ログ出力時にRequestIDを含めることで、同一リクエスト中のログが判断できるようにします。

通常のログ出力

先ずは、通常のログ出力を行うコードを書いてみましょう。

logger定義

pinoのラッパーモジュールを定義します。

lib/logger.ts
import pino from "pino";

export const logger = pino({
  level: "debug",
  timestamp: pino.stdTimeFunctions.isoTime,
  formatters: {
    level: (label: string) => {
      return {
        level: label,
      };
    },
  },
})

サーバーロジック

非常にシンプルですが、/api/log_test URIでログ出力するだけのコードです。

app/api/log_test/route.ts
import { NextResponse } from "next/server";
import { logger } from "@/lib/logger";

const sleep = (ms: number): Promise<void> => {
  return new Promise((resolve) => setTimeout(resolve, ms));
};

function log_test_process() {
  logger.debug("log_test_process");
}

export async function GET() {
  const result = {status: 200};

  logger.debug("request test start.");

  log_test_process();
  await sleep(3000);

  logger.debug("request test end.");

  return NextResponse.json(result);
}

リクエスト

以下のURIで２つのブラウザからアクセスすると、２セットのstart～endまでのデバッグログが表示されます。

http://localhost:3000/api/log_test

{"level":"debug","time":"2025-12-01T07:19:15.795Z","pid":30446,"hostname":"d473eacc45c7","msg":"request test start."}
{"level":"debug","time":"2025-12-01T07:19:15.795Z","pid":30446,"hostname":"d473eacc45c7","msg":"log_test_process"}
{"level":"debug","time":"2025-12-01T07:19:17.582Z","pid":30446,"hostname":"d473eacc45c7","msg":"request test start."}
{"level":"debug","time":"2025-12-01T07:19:17.582Z","pid":30446,"hostname":"d473eacc45c7","msg":"log_test_process"}
{"level":"debug","time":"2025-12-01T07:19:18.798Z","pid":30446,"hostname":"d473eacc45c7","msg":"request test end."}
{"level":"debug","time":"2025-12-01T07:19:20.584Z","pid":30446,"hostname":"d473eacc45c7","msg":"request test end."}

今回のサンプルは単純なsleepだけですが、実際のロジックではリクエストごとに処理時間が異なるため、ログの出力順序は保証されません。
そのため、start～endのログは、どれがセットになっているのか判断できないことになります。

リクエスト単位がわかるログ出力

リクエスト単位として、RequestIDを採番し、その値をログに出力します。
GETメソッドから呼ばれる関数のログでも意識せずにRequestIDを出力したいですよね。
そこで、AsyncLocalStorageの出番になります。
AsyncLocalStorageは、非同期処理（コンテキスト）ごとに、共通で使用できる変数のようなデータを安全に保持・共有する仕組みを提供します。
上記のプログラムをAsyncLocalStorageを利用したコードに変えてみましょう。

AsyncLocalStorage定義

非同期処理中に保持する値を定義します。
今回は、リクエストメソッド・URL・RequestIDを保持することにします。

lib/request-context.ts
import { AsyncLocalStorage } from "node:async_hooks";

export type RequestStore = {
  method?: string;
  url?: string;
  requestId?: string;
};

export const requestStore = new AsyncLocalStorage<RequestStore>();

logger定義

pinoでログにカスタム値を出力するために、mixinオプションを定義します。
mixinは、ログ出力時に毎回呼ばれ、戻り値をログに追加することができます。
今回は、request-context.tsで定義した、リクエストメソッド・URL・RequestIDを出力するようにします。

lib/logger.ts
import pino from "pino";
import { requestStore } from "@/lib/request-context";

export const logger = pino({
  level: "debug",
  timestamp: pino.stdTimeFunctions.isoTime,
  mixin(_context, level) {
    const store = requestStore.getStore();

    if (store) {
      return {
        method: store.method,
        url: store.url,
        requestId: store.requestId,
      };
    }

    return {};
  },
  formatters: {
    level: (label: string) => {
      return {
        level: label,
      };
    },
  },
});

サーバーロジック

GETの中で、非同期処理中に共有したいRequestStoreを生成します。
AsyncLocalStorage（request-contextで定義したrequestStore）のrunメソッドにRequestStoreを渡し、処理を実行します。
runで実行された非同期処理中は、どのメソッドからもRequestStoreの値を参照することができます。
そのため、log_test_process関数から呼ばれているlogger.debug関数でリクエストメソッド・URL・RequestIDを出力することができます。

app/api/log_test/route.ts
import { NextRequest, NextResponse } from "next/server";
import { logger } from "@/lib/logger";
import { requestStore } from "@/lib/request-context";
import type { RequestStore } from "@/lib/request-context";

const sleep = (ms: number): Promise<void> => {
  return new Promise((resolve) => setTimeout(resolve, ms));
};

function log_test_process() {
  logger.debug("log_test_process");
}

export function GET(request: NextRequest) {
  const store: RequestStore = {
    method: request.method,
    url: `${request.nextUrl.pathname}${request.nextUrl.search ?? ""}`,
    requestId: crypto.randomUUID(),
  };

  return requestStore.run(store, async () => {
    const result = {status: 200};

    logger.debug("request test start.");

    log_test_process();
    await sleep(3000);

    logger.debug("request test end.");

    return NextResponse.json(result);
  });
}

リクエスト

再度、以下のURIで２つのブラウザからアクセスし、２セットのstart～endまでのデバッグログを確認します。

http://localhost:3000/api/log_test

{"level":"debug","time":"2025-12-01T07:54:08.172Z","pid":41643,"hostname":"d473eacc45c7","method":"GET","url":"/api/log_test","requestId":"c261bc13-fea2-435f-be43-e36dc98913c0","msg":"request test start."}
{"level":"debug","time":"2025-12-01T07:54:08.173Z","pid":41643,"hostname":"d473eacc45c7","method":"GET","url":"/api/log_test","requestId":"c261bc13-fea2-435f-be43-e36dc98913c0","msg":"log_test_process"}
{"level":"debug","time":"2025-12-01T07:54:08.331Z","pid":41643,"hostname":"d473eacc45c7","method":"GET","url":"/api/log_test","requestId":"eb9a2bb1-4ee1-47fd-8f00-33bf09666db1","msg":"request test start."}
{"level":"debug","time":"2025-12-01T07:54:08.332Z","pid":41643,"hostname":"d473eacc45c7","method":"GET","url":"/api/log_test","requestId":"eb9a2bb1-4ee1-47fd-8f00-33bf09666db1","msg":"log_test_process"}
{"level":"debug","time":"2025-12-01T07:54:11.175Z","pid":41643,"hostname":"d473eacc45c7","method":"GET","url":"/api/log_test","requestId":"c261bc13-fea2-435f-be43-e36dc98913c0","msg":"request test end."}
{"level":"debug","time":"2025-12-01T07:54:11.332Z","pid":41643,"hostname":"d473eacc45c7","method":"GET","url":"/api/log_test","requestId":"eb9a2bb1-4ee1-47fd-8f00-33bf09666db1","msg":"request test end."}

ログにRequestID（requestId）が出力されることで、1,2,5行目と3,4,6行目が１リクエストで出力されたログであることが明確になりました。
（右にスクロールするとrequestIdが出てきます。）

今回は、ログにRequestIDを出力するところまでにします。
このコードでは、全てのGET,POST,PUT,DELETEなどのリクエストメソッドに、RequestStoreの生成とrunメソッド呼び出しを入れなければならず、ログに出力したい内容に対し変更が生じると、影響が大きくなります。
そこで、次回は、この部分をラッパー関数にしてシンプルにする方法を掲載したいと思います。

所属部署について

隼人事業所

隼人事業所は、工場の中に事務所があるという利点を活かし、ものづくりの現場に貢献できるシステム開発に取り組んでいます。
IT技術を活用して、新しい価値を創出をしていくことを目指しています。

おわりに

今回はAsyncLocalStorageの使い方を主としたサンプルコードにしていますが、実際のプロジェクトではもっと工夫しています。
次回はもう少し実践的なコードも掲載予定です。

本記事が、新たにNext.jsでの開発を始めようとしている方の参考になれば幸いです。

0
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?