【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](https://www.npmjs.com/package/uuid)で行います。

# 参考

- [Node.jsでログにRequestIdを入れる](https://qiita.com/ippei_ukai/items/adea86744777cbef5eba)
- [Node.js で Log に userId を自動で出力する方法](https://qiita.com/waterada/items/3b3cedc86e1a4eb47d91)

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

- [Node.jsでのリクエストIDのログ出力（express, log4js, request-context）](https://qiita.com/ippei_ukai/items/adea86744777cbef5eba)

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


# request-context
変数をリクエスト単位で取り扱うことができるパッケージです。
[request-context](https://www.npmjs.com/package/request-context)

### 注意
[request-context](https://www.npmjs.com/package/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
```

### 準備

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

### set
```js
requestContext.set('request:id', requestId)
```

### get
```js
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
```