Zenn
Open8

Next.jsのAPIルートのloggingどうするといいのか？

Next.js
y_meganey_megane

やりたいこと

Next.jsのAPI Routesのloggingをいい感じにする。
前提としてクライアントサイドとSSRは今回は考慮しない。

１. APIルートへのアクセスログを出したい。

{timestamp} GET /path 200 のようなイメージ。
いちいちAPIごとに書くのは面倒だし漏れるのがイヤなのでミドルウェアのような仕組みで全APIルートにアクセスログを仕込みたい。

2. 任意のログをフォーマットとログレベルを指定して出力したい

logger.info, logger.debug のようなよくあるloggingライブラリの感覚で使えて環境変数で出力レベルを制御したい。
一括でフォーマットを定義したい。

y_meganey_megane

console.log系

要するにprint。一括フォーマット指定とかは当然できない。
console.log, infoは標準出力に出る。

これをラップして自作もできるが流石に低機能だしいちいち作りたくない。
Console | Node.js v19.3.0 Documentation

一応実装と出力

export default async function handler(
  req: NextApiRequest,
  res: NextApiResponse<ModelResponse[]>
) {
    if (req.method == "GET") {
      console.log("log - GET /models");
      console.info("info - GET /models");
      console.warn("warn - GET /models");
      console.error("error - GET /models");
      res.status(200).OK();
    } else {
      res.status(404).end("Not found");
    }
}

出力

log - GET /models
info - GET /models
warn - GET /models
error - GET /models
y_meganey_megane

https://github.com/topics/logger?l=javascript
jsのloggerタグをGitHubで検索。

pinojs/pino: 🌲 super fast, all natural json logger
klaudiosinani/signale: Highly configurable logging utility
expressjs/morgan: HTTP request logger middleware for node.js

2023年1月時点でスター数はこの３つが上位。

pinoはアクティブに動いている。
signareは2019年が最終リリース。最終コミットは2022年4月。
morganは最終リリースが2020年3月。

下2つは開発動いてない気配がある？

y_meganey_megane

pino

pinojs/pino: 🌲 super fast, all natural json logger

install

npm install pino

実装

import {pino} from "pino"

export default async function handler(
  req: NextApiRequest,
  res: NextApiResponse<ModelResponse[]>
) {
    if (req.method == "GET") {
      const logger = pino();
      logger.debug("debug - GET /hello");
      logger.info("info - GET /hello");
      logger.warn("warn - GET /hello");
      logger.error("error - GET /hello");
      res.status(200).OK();
    } else {
      res.status(404).end("Not found");
    }
}

出力

{"level":30,"time":1672929080697,"pid":75196,"hostname":"mypc","msg":"info - GET /hello"}
{"level":40,"time":1672929080697,"pid":75196,"hostname":"mypc","msg":"warn - GET /hello"}
{"level":50,"time":1672929080697,"pid":75196,"hostname":"mypc","msg":"error - GET /hello"}

デフォルトだと

  • debugレベル
  • タイムスタンプがepochTime
  • JSON形式

など

y_meganey_megane

APIドキュメント
pino/api.md at master · pinojs/pino

nameを与える、debugレベルにする、タイムスタンプの書式変更など少しカスタム。

日付書式の指定は関数が用意されている。
api.md#pino-stdtimefunctions at master · pinojs/pino

export default async function handler(
  req: NextApiRequest,
  res: NextApiResponse<ModelResponse[]>
) {
  if (req.method == "GET") {
      const logger = pino(
        {
          name: "api/hello",
          level: "debug",
          formatters: {
            level: (label) => ({ level: label }), // default: { level: number }
            bindings: (bindings) => ({
              pid: bindings.pid,
              hostname: bindings.hostname,
              name: bindings.name
            })
          },
          timestamp: pino.stdTimeFunctions.isoTime
        },
        pino.destination(2) // stderr
      );
      logger.debug("debug - GET /hello");
      logger.info("info - GET /hello");
      logger.warn("warn - GET /hello");
      logger.error("error - GET /hello");
    } else {
      res.status(404).end("Not found");
    }
}


{"level":"debug","time":"2023-01-05T14:42:48.816Z","pid":75196,"hostname":"mypc","name":"api/hello","msg":"debug - GET /hello"}
{"level":"info","time":"2023-01-05T14:42:48.816Z","pid":75196,"hostname":"mypc","name":"api/hello","msg":"info - GET /hello"}
{"level":"warn","time":"2023-01-05T14:42:48.816Z","pid":75196,"hostname":"mypc","name":"api/hello","msg":"warn - GET /hello"}
{"level":"error","time":"2023-01-05T14:42:48.816Z","pid":75196,"hostname":"mypc","name":"api/hello","msg":"error - GET /hello"}
y_meganey_megane

pino-prettyをtargeに指定するとJSONではなくフラットな文字列＋装飾で出力される。

npm install pino-pretty 

      const logger = pino(
        {
          transport: {
            target: "pino-pretty"
          },
          name: "api/hello",
          level: "debug",
          formatters: {
            level: (label) => ({ level: label }) // default: { level: number }
          },
          timestamp: pino.stdTimeFunctions.isoTime
        },
        pino.destination(2) // stderr
      );
      logger.debug("debug - GET /hello");

[00:03:40.236] DEBUG (api/hello/91941): debug - GET /hello
y_meganey_megane

最終的に、こんな感じでよくあるgetLoggerを作成。

import pino from "pino";

/** pinoのカスタムLoggerを返す */
export default function getLogger(name?: string) {
  const logger = pino(
    {
      // transport: {
      //   target: "pino-pretty" // jsonではなく単純な文字列として出力
      // },
      name: name,
      level: process.env.LOG_LEVEL ?? "info",
      formatters: {
        level: (label) => ({ level: label }), // default: { level: number }
        bindings: (bindings) => ({
          pid: bindings.pid,
          hostname: bindings.hostname,
          name: bindings.name
        })
      },
      timestamp: pino.stdTimeFunctions.isoTime
    },
    pino.destination(2) // stderr
  );
  return logger;
}

各APIルートのファイルで以下のように使う。

const logger = getLogger("api/hello")
logger.info("hello)
  1. 任意のログをフォーマットとログレベルを指定して出力したい

はこれにて概ね達成。

y_meganey_megane

１. APIルートへのアクセスログを出したい。
について考える。

・・・途中経過を書き忘れていた。
色々いじったが、現状としてはNext.jsのミドルウェアとして、所定のパスのリクエストに対してアクセスログもどきを出す。loggerは引き続きpinoを利用。

現状

export function getBrowsweLogger(name?: string) {
  const logger = pino({
    level: process.env.LOG_LEVEL ?? "info"
  });
  return logger;
}

import { NextResponse } from "next/server";
import type { NextRequest } from "next/server";

import { getBrowsweLogger } from "./config/logging";

const logger = getBrowsweLogger("access-log");
export function middleware(request: NextRequest) {
  const dt = new Date().toISOString();

  // middlewareでpinoを使うとブラウザ実行時の書式になりAPIのログと書式がずれるため、
  // APIのログ形式に手動で整形してから出力している。
  // APIログ例: {"level":"debug","time":"2023-01-05T17:49:10.122Z","name":"api/hello","msg":"PUT /hello"}
  logger.info(
    JSON.stringify(
      {
        level: "info",
        time: dt,
        name: "access-log",
        method: request.method,
        path: request.nextUrl.pathname
      },
      null,
      0
    )
  );
  return NextResponse.next();
}

export const config = {
  // ミドルウェアを実行するパスを調整する
  matcher: ["/api/:path*"]
};

課題

課題1

2.任意のログをフォーマットとログレベルを指定して出力したい

でカスタムしたpinoのLoggerとはまた別にLoggerを定義している。
加えて、ミドルウェアの実装内でログ出力用のJSONを自力で作っている。

理由としては、2で作ったgetLoggerをそのまま使ったら 出力先にpino.destination(2) を指定している部分がエラーになった。
またこの指定を消して動かしても、ログ出力のフォーマットが設定と異なるものになるため。

原因1

pinoはサーバーサイドとしてNode.jsで動かすこともできるし、クライアントサイドとしてブラウザで動かすこともできる。この辺の挙動の違いが原因…と思ってるがまだ理解できてない。
Next.jsのミドルウェアはサーバー側＝Node.jsで動いてるから2のloggerと同じ扱いだと思っていたが、どうも挙動を見る限りブラウザ側としてpinoが動作していそう。

課題2

もうひとつの課題として、アクセスログにステータスコードを出したい（上の実装はそもそもそうなってない状態のもの）が、 const res = NextRequest.next(); res.statusとしても常にステータスに200が入ってしまう。というかうまくレスポンスが入らない、という事象。
これは単にしょうもない実装ミスなのかもしれない。とりあえず現状はそう。

作りたいイメージはこう

let res;
try{
  res = NextRequest.next()
}finally{
  logger.info("ステータスや処理時間を含むログ")
}