Node.js + Express + log4jsで、アクセスログとリクエストログを取る。

• facebook

オフィス狛 技術部のKoma（Twitterアカウントの中の人＆CEO）です。

平成最後の投稿です。

弊社では「Node.js + Express」でAPIを作成する事が多々あるのですが、
その際、アクセスログは別レイヤーで出力して、リクエストログは各業務処理内で出力しています。

今回、それを共通化してまとめたいと思います。
各バージョンは以下の通りです。

node 10.13.0
log4js 3.0.6

※それぞれ、ちょっと前のバージョンになるので、参考にされる方はご注意下さい。

log4js のインストール

まずは log4js のインストールです

npm install log4js

Configファイルの作成

ログの出力レベルなどの設定関連は、別ファイルにしたいので、
「[プロジェクトルート]/src/config」に「log4js.config.json」ファイルを作成します。
ファイルの中身は今回は以下のようにしました。

{
  "appenders": {
    "ConsoleLogAppender": {
      "type": "console"
    },
    "SystemLogAppender": {
      "type": "file",
      "filename": "./log/system.log",
      "maxLogSize": 5000000,
      "backups": 3
    },
    "HttpLogAppender": {
      "type": "dateFile",
      "filename": "./log/http.log",
      "pattern": ".yyyy-MM-dd",
      "daysToKeep": 7
    },
    "AccessLogAppender": {
      "type": "dateFile",
      "filename": "./log/access.log",
      "pattern": ".yyyy-MM-dd",
      "daysToKeep": 7
    }
  },
  "categories": {
    "default": {
      "appenders": ["ConsoleLogAppender"],
      "level": "all"
    },
    "system": {
      "appenders": ["SystemLogAppender"],
      "level": "info"
    },
    "http": {
      "appenders": ["HttpLogAppender"],
      "level": "info"
    },
    "access": {
      "appenders": ["AccessLogAppender"],
      "level": "info"
    }
  }
}

各設定とも「filename」でログの保存場所＆ファイル名を指定しています。
「type」によってローテーションが違いますが、
「"type": "file"」の場合は、「maxLogSize」で最大ファイルサイズ（byte）を指定し、
それを超えた場合、「backups」に記載している世代分は保存されます。

「"type": "dateFile"」の場合は、「pattern」に記載した形式（今回は「yyyy-MM-dd」）、つまり日毎にローテーションされ、「daysToKeep」に記載している日付分は保存されます。
詳しくは本家のドキュメントを参照ください。

出力ロジックの記載

続いて、app.jsにログ出力について記載していきます。

const log4js = require('log4js');
const express = require('express');
const cors = require('cors');
const cookieParser = require('cookie-parser');
const bodyParser = require('body-parser');
require('dotenv').config();

// （中略）

app.use(bodyParser.json());
app.use(bodyParser.urlencoded({ extended: false }));
app.use(cookieParser());
app.use(cors(corsOptions));

// health check
app.use('/health', check);

// ログ設定
log4js.configure('./src/config/log4js.config.json');
const systemLogger = log4js.getLogger('system'); 
const httpLogger = log4js.getLogger('http'); 
const accessLogger = log4js.getLogger('access');
app.use(log4js.connectLogger(accessLogger));
app.use((req, res, next) => {
  if (typeof req === 'undefined' || req === null ||
        typeof req.method === 'undefined' || req.method === null ||
        typeof req.header === 'undefined' || req.header === null) {
    next();
    return;
  }
  if (req.method === 'GET' || req.method === 'DELETE') {
    httpLogger.info(req.query);
  } else {
    httpLogger.info(req.body);
  }
  next();
});
systemLogger.info("App start");

// API Version
const apiVersion = '/api/v2.1.0';

// 各業務API
app.use(`${apiVersion}/hoge/auth`, hogeAuth);
app.use(`${apiVersion}/hoge/master/user`, userMaster);

// （後略）

ポイントは、ログ出力設定をhealth checkの後、そして、業務APIの前に記載している事です。
（今回は、health checkからの接続をログに出力したくなかったので）

ただこれは、health checkのURLへの接続を前もって制限出来ている事が前提となります。
health checkのURLには、特定の信頼している接続元からのみ接続出来る事が分かっているので、ログは不要です、と。

では、ログ設定の部分を見ていきます。

まずは、先程作成した外部の設定ファイルを読み込みます。

log4js.configure('./src/config/log4js.config.json');

続いて、各設定を読み込みます。（configファイルの「categories」に記載した名前を使用します。）

const systemLogger = log4js.getLogger('system'); 
const httpLogger = log4js.getLogger('http'); 
const accessLogger = log4js.getLogger('access');

続いて、下記の記載で、Expressへのアクセスをログに出力することが可能になります。

app.use(log4js.connectLogger(accessLogger));

続いて、下記の記載で、接続時のリクエスト値をログに出力することが可能になります。

app.use((req, res, next) => {
  if (typeof req === 'undefined' || req === null ||
        typeof req.method === 'undefined' || req.method === null ||
        typeof req.header === 'undefined' || req.header === null) {
    next();
    return;
  }
  if (req.method === 'GET' || req.method === 'DELETE') {
    httpLogger.info(req.query);
  } else {
    httpLogger.info(req.body);
  }
  next();
});

当APIプロジェクトはRESTになっているので、
GETとDELETEはqueryで、それ以外（POST、PUT）は、bodyで送られてくる、という想定になっています。

※「next()」を忘れないようにして下さい。
これが無いと、そこで処理が終了してしまい、以降の業務API側に値が行き渡りません。

そして最後に

systemLogger.info("App start");

これは、単純にExpressを起動した時に一度だけ出力されます。

これで、Expressを起動するとログが出力されます。

今回は、設定ファイル（log4js.config.json）で「"filename": "./log/xxxx.log",」と記載しているので、 app.jsが格納しているディレクトリにlogディレクトリが作成され、その中に、ログが格納されます。
こんなイメージです。

ちなみに、今回は説明を省きましたが、
業務側で500エラーになった場合も、app.js内で最終的にcatchし、systemLoggerでエラー内容（スタックトレース）をシステムログに出力しています。

以上です。

平成最後の投稿、内容の割に長くなってしまいました。

それでは、また令和でお会いしましょう！


Express , log4js , Node.js