Node.js Expressでlog4jsを使ってログ出力するmiddleware(logger)を組み込んでみた

はじめに

アプリケーションの開発時にはlog出力は必須となると思います。今回は、そのlogの種類としてはどんなものがありその役割は何か？を理解しつつ、実際にlogger（アプリケーションログ出力用、アクセスログ出力用）を作成していくという事をやってみました。

ソースコード全体は以下。

ログ出力するmiddlewareを実装する

結論

※以下ではES Modulesを利用しているが、ES Modulesを利用しない場合には、importの部分を"const appRoot = require('app-root-path');"にするなどモジュール管理の実装を変更すればいい。ES Modulesを利用した実装のための設定については、Node.jsでimport・export（ES6の構文）を使えるようにwebpack × Babelの設定をやってみたを参照。

// ./config/logger.config.js
import appRoot from 'app-root-path';
import path from 'path';

const LOG_ROOT_DIR = process.env.LOG_ROOT_DIR || appRoot.resolve('logs');

export default {
	appenders: {
		console: { type: 'console' },
		application: {
			type: 'dateFile',
			filename: path.join(LOG_ROOT_DIR, './application.log'),
			pattern: 'yyyyMMdd',
			keepFileExt: true,
			daysToKeep: 7
		},
		access: {
			type: 'dateFile',
			filename: path.join(LOG_ROOT_DIR, './access.log'),
			pattern: 'yyyyMMdd',
			keepFileExt: true,
			daysToKeep: 7
		}
	},
	categories: {
		default: {
			appenders: ['console'],
			level: 'ALL'
		},
		application: {
			appenders: ['console', 'application'],
			level: 'INFO'
		},
		access: {
			appenders: ['console', 'access'],
			level: 'INFO'
		}
	}
};

// ./src/lib/logger.js
import log4js from 'log4js';
import config from '../../config/log4js.config';

log4js.configure(config);

export const DefaultLogger = log4js.getLogger();
export const AppLogger = log4js.getLogger('application');
export const AccessLogger = log4js.getLogger('access');

// ./src/lib/application-logger.js
import { AppLogger } from './logger';

// eslint-disable-next-line no-unused-vars
export default (options = {}) => {
	return (err, req, res, next) => {
		AppLogger.error(err.message);
		next(err);
	};
};

// ./src/lib/access-logger.js
import log4js from 'log4js';
import { AccessLogger } from './logger';

const DEFAULT_LOG_LEBEL = 'auto';

export default (options = {}) => {
	const opts = options;
	opts.level = options.level || DEFAULT_LOG_LEBEL;

	return log4js.connectLogger(AccessLogger, opts);
};

// ./src/app.js
// 省略
import { AppLogger } from './lib/logger';
import applicationLogger from './lib/application-logger';
import accessLogger from './lib/access-logger';

// 省略
app.use('/public', express.static(appRoot.resolve('src/public')));

app.use(accessLogger()); // <- アクセスログは静的コンテンツの配信に対しては不要なのでここでmiddlewareを設定している

app.use('/', router);

app.use(applicationLogger());

app.listen(port, () => {
	AppLogger.info(`Application listening at ${port}`);
});

## 一部省略している
[root@localhost post-restaurant-reviews]# tree -I 'node_modules|.git'
.
├── babel.config.js
├── config
│   └── log4js.config.js
├── logs  ## <-このディレクトリにlogファイルが出力される
│   ├── access.log
│   ├── application.20220102.log
│   └── application.log
├── package.json
├── src
│   ├── app.js
│   ├── lib
│   │   ├── access-logger.js
│   │   ├── application-logger.js
│   │   └── logger.js
├── webpack.config.js
└── yarn.lock

以下で詳細を見ていくが、まずログの種類を見ていき、今回実装したログ出力ではどのログを出力させるようにしたのかについてみていく。その後、実際の実装内容についてみていく。

ログの種類

ログ出力の目的は、何かを監視・watchできるようにするために出力させるものと理解して良いだろう。その監視したい内容に応じて、ログの種類を分類してみると、以下のような感じで分類できると思う。

まず、ログの目的は思いつく所で、事業向け・運用向け・セキュリティ向けのログがあると思う（他にもあるかもしれないが今回はその3つで考えていく）。また、それぞれ具体化してみると以下の図表のようなログの分類ができるだろう。

ログを何に使うか？（目的）	具体的には…
事業	マーケティング
運用	サービス、アプリ、インフラ
セキュリティ	監視、監査

それぞれのログの分類ごとに何を監視するのか？を具体化してみると、以下の図表のように書くことができるだろう（他にもあると思われるが、今回は以下のように考える）。

何用のログか？	具体的にはどんなログか？（ログとして記録・出力させるものは何か？）
マーケティング用	KPI、KGIに関連する監視項目（CVR、アクション数、アクセス数など）のログ。
サービスの運用用	サービスの正常性・ヘルスチェックのための、HTTPのステータスコード（200・400・500など）のログ。
アプリの運用用	エラーログ。
インフラの運用用	リソースに関わる各種パラメータ（CPU、メモリ、コネクションプールなど）のログ。
監視用	外部からの不正操作があったか？分かるようにするようなログ。
監査用	内部・関係者による不正操作があったか？分かるようにするようなログ。

この中で今回、以下の図表でまとめた3つのログを出力させるという事をやってみた（※アプリケーションログとエラーログは分けずに単にアプリケーションログと言ったりする事もあるようなので、今回実際に実装したloggerは2つ（アプリケーションログ出力用、アクセスログ出力用））。

ログの通称	ログの中身のイメージ
アクセスログ	サーバリクエスト、レスポンス
アプリケーションログ	アプリケーションの動作状況・ある実行された操作の内容と操作時の値
エラーログ	システムエラー・キャッチできなかった例外

log4jsについて

今回はlog4jsというライブラリを使ってloggerの実装をやってみた。log4jsについてその仕組みを少しここで取り上げて理解を深めていく。

logger本体（ログ出力を行うインスタンス）の設定をする必要があるが、その仕組みとしては以下のようになっている。appendersというのがログの出力先に関する設定を定義するプロパティで、代表的なものはCore Appendersに書かれている。categoriesのプロパティでは、そのappendersを使い、どのログレベルで出力するのか？の情報を追加して設定を定義する。

※"categories"の"appenders"プロパティはarrayなので、複数のappenderを設定することができる（appenders (array of strings) - the list of appender names to be used for this category. A category must have at least one appender.）。

※categoriesの"level"プロパティだが、ログ出力させたいレベルの最低レベルを定義する項目で、例えば、"ERROR"にすると、"ERROR"・"FATAL"・"MARK"の三種類のログレベルのみloggerで出力される。ちなみに、log4jsではログレベルは内部的には数字で扱われており、それはlevels.jsの部分で実装されている。

※"const defaultLogger = log4js.getLogger();"としている部分だが、これは公式にIf no category is specified, the events will be routed to the appender for the default category. と書かれている通り、カテゴリ未指定なのでdefaultに設定されている内容でloggerが生成される（log4js.getLogger('default')と同じ意味）。

※categoriesについては、公式に、

You must define the default category which is used for all log events that do not match a specific category.

と書かれているように、必ず"default"というカテゴリ（loggerのインスタンス生成時、どのカテゴリーにもマッチしないような時に使用されるデフォルトのカテゴリ）を定義する必要があるので注意。

・参考：log4js-node API

log4jsでlogger（ログ出力するもの）を作成する

具体的に、アプリケーションログ出力用、アクセスログ出力用のそれぞれのloggerの実装を見ていく。

アプリケーションログ出力用のloggerについて

"log4js.config.js"内に設定をしていく。今回はapplication.logというファイルにログを出力させるために、Core AppendersのDate Rolling File Appenderを使っている。Date Rolling File Appenderは

This is a file appender that rolls log files based on a configurable time, rather than the file size.

と書かれているように、ファイルサイズではなく、日付でログファイルを変えていく仕組みで動く。そのため、例えば1月2日と1月3日にアプリケーションログが記録されると、以下のようにファイルが1日分ごとに分割される。

設定できるオプションとしてはConfigurationに書かれている通りで、今回の設定内容としては、

・filename
　出力するログファイル名の設定で、今回は環境変数で設定可能な出力先ディレクトリ以下にapplication.logというファイル名でログを出力させるようにしている（もし環境変数がなければexpressのプロジェクトルート以下のlogsディレクトリにapplication.logというファイルが出力される）。

・daysToKeep
　ログを何日間保持するか？の設定（デフォルトだと0になっているので1日で消える）。今回は1週間保存するようにしている。

・pattern
　daysToKeepの設定により、何日間かログファイルが保存されることになるが、同じファイル名で保存する事はできない。そこで、過去のログファイルについてはこのpatternに設定されている内容で、日付をファイル名に追記する事で同じファイル名にならないようにするが、その日付のフォーマットをどのようにするか？の設定。デフォルトだとyyyy-MM-dd（2022-01-01）だが、今回はyyyyMMdd（20220101）にしている。

・keepFileExt
　patternに沿ってログファイル名に日付を追記するが、その追記する際にファイル拡張子を保持するか？の設定。デフォルトはfalseで保持しないなので、日付はapplication.log.20220101のようにファイル拡張子の後につく。今回はtrueにしたので、application.20220101.logになる。

という感じ（その他の設定項目についてはConfigurationを参照）。

あとはこれをlog4jsで読み込んで、categoriesの設定でlogger生成すればいい。具体的には、

import log4js from 'log4js';
import config from '../../config/log4js.config';

log4js.configure(config);
export const AppLogger = log4js.getLogger('application');

のように、log4jsでconfigurationを読み込み、applicationのカテゴリの設定内容でloggerを生成。次に、expressの本体でmiddlewareとして読み込ませる（middlewareは別ファイルに切り出す＋エラー発生時にログを出力させるのでエラー処理のmiddleware（"(err, req, res, next) => {}"の部分）で実装する）。

import { AppLogger } from './logger';

// eslint-disable-next-line no-unused-vars
export default (options = {}) => {
	return (err, req, res, next) => {
		AppLogger.error(err.message);
		next(err);
	};
};

app.use(applicationLogger());

アクセスログ出力用のloggerについて

こちらも『アプリケーションログ出力用のloggerについて』の項で書いたDate Rolling File Appenderを使う。設定内容については、ファイル名が違うだけで『アプリケーションログ出力用のloggerについて』の項の内容と同じ。設定をlog4jsで読み込んで、categoriesの設定でlogger生成する部分もほぼ同じで、categoriesだけ"access"になる。

export const AccessLogger = log4js.getLogger('access');

アクセスログ用のloggerもmiddlewareとして、expressの本体に読み込ませるが、今回はlog4jsに実装されているConnect / Express Loggerを使う。これは公式の例をみると分かるが、関数"log4js.connectLogger()"の返り値はmiddlewareの関数になっているので、これをそのままexpressに渡せばいい（log4jsの実装としては、connect-logger.jsがそれ）。

というわけで、middlewareの実装としては、

// 省略

export default (options = {}) => {
	// 省略
	return log4js.connectLogger(AccessLogger, opts);
};

のように、"return log4js.connectLogger(...);"とするだけでいい。

※アクセスログのmiddlewareをexpressのどの位置で読み込ませるか？だが、静的コンテンツの配信に対するアクセスは静的コンテンツが単にクライアントに変えるだけなのであまり記録しても意味ないので、動的なコンテンツ（routerの部分）に対するアクセスを記録する事にした。そのため、"app.use('/', router)"の直前で、

app.use(accessLogger());

のように、アクセスログ出力用のmiddlewareを読み込ませている。expressのmiddlewareに読み込み順があるという事については、Middleware functions are executed sequentially, therefore the order of middleware inclusion is important.と書かれている通り。

※connectLoggerのoptionsで設定できる内容は、公式に、

The log4js.connectLogger supports the passing of an options object that can be used to set the following:

・log level
・log format string or function (the same as the connect/express logger)
・nolog expressions (represented as a string, regexp, or array)
status code rulesets

と書かれている通り。

※optionsで設定できる"level"についてだが、これは"auto"が選択できる。このautoは公式に、

Added automatic level detection to connect-logger, depends on http status response, compatible with express 3.x and 4.x.

と書かれているように、自動でログレベルを検出してくれる機能。autoにするとそれに乗っかる設定になる。

まとめとして

今回はlog4jsを使ってログ出力をするmiddlewareを作成するという事をやってみた。基本的なloggingのやり方については理解が深まったが、本番ではもっと追加の設定が必要になると思うので、さらに理解を深めていきたいと思った。