【Node.js】ログにリクエストIDを記録する

概要

各APIリクエストに対して一意なIDを付与しログに記録しておくと、なにかと便利です。

• リクエストID付与なし

[2020-01-01T00:00:00.000] DEBUG system - start // APIリクエスト1
[2020-01-01T00:00:00.000] DEBUG system - start // APIリクエスト2
[2020-01-01T00:00:00.000] DEBUG system - start // APIリクエスト3
[2020-01-01T00:00:00.005] DEBUG system - continue
[2020-01-01T00:00:00.005] DEBUG system - continue
[2020-01-01T00:00:00.010] DEBUG system - continue
[2020-01-01T00:00:00.010] DEBUG system - finish
[2020-01-01T00:00:00.015] DEBUG system - finish
[2020-01-01T00:00:00.015] ERROR system - error // どのAPIリクエストのエラー？

• リクエストID付与あり

[2020-01-01T00:00:00.000] [request-id-01] DEBUG system - start // APIリクエスト1
[2020-01-01T00:00:00.000] [request-id-02] DEBUG system - start // APIリクエスト2
[2020-01-01T00:00:00.000] [request-id-03] DEBUG system - start // APIリクエスト3
[2020-01-01T00:00:00.005] [request-id-01] DEBUG system - continue
[2020-01-01T00:00:00.005] [request-id-02] DEBUG system - continue
[2020-01-01T00:00:00.010] [request-id-03] DEBUG system - continue
[2020-01-01T00:00:00.010] [request-id-03] DEBUG system - finish
[2020-01-01T00:00:00.015] [request-id-02] DEBUG system - finish
[2020-01-01T00:00:00.015] [request-id-01] ERROR system - error // APIリクエスト1でエラー

本記事では、request-contextを使用してAPIリクエスト毎に一意なリクエストIDを管理、ログに記録する方法を書きます。
APIサーバーはNode.js + Express + log4jsの最小構成を想定、リクエストIDの発行はuuidで行います。

参考

• Node.jsでログにRequestIdを入れる
• Node.js で Log に userId を自動で出力する方法

実装当時は上記の資料しか見つけることができず、その分とても助かりました。
後述するdomainのDeprecatedについても詳細に書かれています。

• Node.jsでのリクエストIDのログ出力（express, log4js, request-context）

本記事の投稿にあたって再度情報を整理していたところ発見しました。
当時の私が実現したかったことそのものであり、大変勉強になりました。

request-context

変数をリクエスト単位で取り扱うことができるパッケージです。
request-context

注意

request-contextにも書かれている通り、request-contextは現在Node.jsでdepricatedになっているdomainに依存しています。

See the Domain Docs for further information on error handling for domains. Note that the domain module is pending deprecation!

domainのdepricatedについては先述した参考資料内で詳細に取り扱われておりますので、そちらをご確認ください。

npm install

npm install request-context

準備

const requestContext = require('request-context')
app.use(requestContext.middleware('request')) // request: name of namespace

set

requestContext.set('request:id', requestId)

get

contextService.get('request:id');

サンプルコード

app.ts

import { NextFunction, Request, Response } from 'express'

const express = require('express')
const app = express()
const port = 3001

// add requestId
const { v4: uuidv4 } = require('uuid')
const requestContext = require('request-context')
app.use(requestContext.middleware('request'))
app.use((req: Request, res: Response, next: NextFunction) => {
  const requestId: string = uuidv4()
  requestContext.set('request:id', requestId)
  next()
})

const requestIdRouter = require('./routes/requestid.js')
app.use('/requestid', requestIdRouter)

app.listen(port, () => {
  console.log(`Example app listening on port ${port}!`)
})

modules/logger.ts

const log4js = require('log4js')
const logger = log4js.getLogger('system')
const requestContext = require('request-context')

const retRequestId = (): string => {
  return requestContext.get('request:id')
}

log4js.configure({
  appenders: {
    system: {
      type: 'file',
      filename: './log/system.log',
      layout: {
        type: 'pattern',
        pattern: '[%d{ISO8601}] [%x{requestId}] %-5p %c - %m',
        tokens: {
          requestId: retRequestId
        }
      }
    },
    console: {
      type: 'console',
      level: 'debug',
      layout: {
        type: 'pattern',
        pattern: '[%d{ISO8601}] [%x{requestId}] %-5p %c - %m',
        tokens: {
          requestId: retRequestId
        }
      }
    }
  },
  categories: {
    default: { appenders: ['system', 'console'], level: 'debug' }
  }
})

module.exports = logger

routes/requestid.ts

import { Request, Response } from 'express'

const express = require('express')
const router = express.Router()

const logger = require('./../modules/logger')

router.get('/', async (req: Request, res: Response) => {
  logger.debug('logger 1')
  logger.debug('logger 2')
  
  setTimeout(() => {
    logger.debug('logger 3')
  }, 1000)

  res.status(200).send()
})

module.exports = router

結果

GET /requestを2回実行

[2020-03-21T00:30:27.900] [319121f2-3c36-4c55-84c2-a7477d2b4e54] DEBUG system - logger 1
[2020-03-21T00:30:27.901] [319121f2-3c36-4c55-84c2-a7477d2b4e54] DEBUG system - logger 2
[2020-03-21T00:30:28.261] [f9f7f350-4549-430b-bd99-5ae17f907f21] DEBUG system - logger 1
[2020-03-21T00:30:28.262] [f9f7f350-4549-430b-bd99-5ae17f907f21] DEBUG system - logger 2
[2020-03-21T00:30:28.902] [319121f2-3c36-4c55-84c2-a7477d2b4e54] DEBUG system - logger 3
[2020-03-21T00:30:29.262] [f9f7f350-4549-430b-bd99-5ae17f907f21] DEBUG system - logger 3