Express v4 と log4js v4 で実践的なロガーを実装

はじめに

node.jsでアプリケーションログを出力する際に、業務でありがちなログのローテーションや、ログレベル毎にファイルを分けるとかの設定をlog4jsで実装してみました。

実装時の環境

以下の環境で実装しました。

・OS：Mac OS X v10.14.4
・Node：v12.1.0
・npm：v6.9.0

log4jsで指定できるログの種別

log4jsでは以下のログレベルを指定できます。

ログレベル	詳細
OFF	全てのログを取得しない。（使うことがあるのか疑問です）
MARK	エラーではないが常に表示しておきたい情報を出力。（使ったことないので憶測です）
FATAL	致命的なエラーの情報を出力。（システムの動作に影響を与えるエラー）
ERROR	予期しない実行時エラーの情報を出力。
WARN	使用が終了となった機能の使用、APIの不適切な使用等に対する警告を出力。（エラーではないが正常とは言い難いものはこちらに分類されます）
INFO	通常のログ。サーバーの起動、停止、ユーザーの操作情報等を出力。
DEBUG	デバッグ用のログレベル。システムの動作状況に関する詳細な情報を出力したい時に使用。
TRACE	トレース用のログレベル。デバッグでは出力しきれない詳細な情報を出力。
ALL	全てのログを取得

簡単なコードで実装してみる

ひとまず、簡単に出力してみます。
Expressとlog4jsをインストールします。

# package.jsonを生成
$ npm init -y

# Expressインストール（実装時の最新版です）
$ npm install express@4.16.4

# log4jsインストール（実装時の最新版です）
$ npm install log4js@4.1.0

以下のようなコードでログを出力できます。

const express = require ('express');
const app = express ();

const log4js = require ('log4js');
const logger = log4js.getLogger ();
logger.level = 'debug';

app.get ('/', (req, res) => {
  logger.debug ('デバッグログが出力されます');
  res.send ('log test');
});

app.listen (3000);

出力結果は以下の通り。
このログの出力では、console.log()と変わらないですね。

[2019-05-05T19:44:34.037] [Level { level: 10000, levelStr: 'DEBUG', colour: 'cyan' }] default - デバッグログが出力されます

実践的なログ出力

業務で使用するログの出力方式としては以下の基準は満たしておきたいです。

・ログはファイルに出力する。
・ログの種別毎に分ける。（システムログ、アプリケーションログ、アクセスログ）
・ログローテーションを行う。 （30日分保持とか5MB毎にファイル生成等）

ログファイルの出力設定について

ログをファイルに出力するには、log4x系によくあるappnedersとcategoriesを使用します。

以下はnodejsで実装する場合の一例です。
appendersには、logのタイプを指定します。下の例では、console出力用のAppenderを設定しています。
categoriesには、appendersで設定したAppenderを指定して、どのレベルで出力を行うかを指定します。

// <APP ROOT>/config/log4js-config.js
const log4js = require('log4js');

// ログ出力設定
log4js.configure({
  appenders: {
    consoleLog: {
      type: "console"
    }
  },
  categories: {
    "default": {
      // appendersで設定した名称を指定する
      // levelは出力対象とするものを設定ここではALL（すべて）
      appenders: ["consoleLog"],
      level: "ALL"
    }
  }
});

// ログカテゴリはdefaultを指定する
const logger = log4js.getLogger("default");

// infoとかerrorとかで出力
logger.error("error message");

Appenderに設定するtypeでよく利用するものは以下の通り。

タイプ	詳細
console	コンソールログを出力する。
file	ファイルサイズによるローテーションと何ファイル保持するかを設定できる。
multiFile	主にAPIルート毎などログファイルの分離を行いたい時に使用する。
dateFile	日時でログローテーションするログの管理に使用する。何日分保持するかを設定できる。

上のコードを実行すると以下のような出力となります。
categoriesに設定したdefaultというカテゴリでログの内容が出力されます。

[2019-05-05T20:30:24.433] [Level { level: 40000, levelStr: 'ERROR', colour: 'red' }] default - error message

モジュールの設計

システムログ、アプリケーションログ、アクセスログの設計は以下の通りです。

.
├── config
│   └── log4js-config.js  ←ログ設定モジュール
├── lib
│   └── log
│       ├── logger.js        ←ルートロガーモジュール（各設定モジュールを統合する）
│       ├── accessLogger.js  ←アクセスログ出力モジュール
│       └── systemLogger.js　←システムログ出力モジュール
├── log
│   ├── access               ←アクセスログが出力されるディレクトリ
│   ├── application          ←アプリケーションログが出力されるディレクトリ
│   └── system               ←システムログが出力されるディレクトリ
├── package-lock.json
├── package.json
└── server.js                ←Expressアプリケーション

システムログの実装

まずはシステムログから実装します。
今回作成するシステムログの要件は以下の通りです。

・エラーログのみを出力。
・1ファイルが一定のサイズになった時にローテーションする。（5MBでローテーション）
・/log/system/system.log に出力する。
・世代管理は5ファイルまでとする。

File Appenderを使う

システムログの出力設定には、File Appenderを使用します。
File Appenderで指定できる設定は以下の通りです。

設定	型	詳細
type	string	設定できる値は file のみ。
filename	string	出力ファイルのパスを設定。
maxLogSize	number	ログファイルの最大サイズ（byteで指定）この数値に達するとローテーションが実行されます。
backups	number	ログファイルの最大保持数を指定。
layout	object	ログ出力のレイアウトを指定。（日付のフォーマット等の設定）
compress	boolean	ログファイルの保持数が上限に達した場合に古いログを削除するかの設定（trueに設定すると削除）

実装

ファイルを出力する際に、パスの指定をする必要があるので、pathモジュールをインストールします。

$ npm install path

ログ設定モジュールにシステムログ用の設定を追加します。

// <APP ROOT>/config/log4js-config.js
const path = require("path");
// ログ出力先は、サーバー内の絶対パスを動的に取得して出力先を設定したい
const APP_ROOT = path.join(__dirname, "../");

// ログ出力設定
// log4jsはルートロガーで使用するので、エクスポートに変更
module.exports = {
  appenders: {
    consoleLog: {
      type: "console"
    },
    // ADD
    systemLog: {
      type: "file",
      filename: path.join(APP_ROOT, "./log/system/system.log"),
      maxLogSize: 5000000, // 5MB
      backups: 5, // 世代管理は5ファイルまで、古いやつgzで圧縮されていく
      compress: true
    }
  },
  categories: {
    default: {
      // appendersで設定した名称を指定する
      // levelは出力対象とするものを設定ここではALL（すべて）
      appenders: ["consoleLog"],
      level: "ALL"
    },
    // ADD
    system: {
      appenders: ["systemLog"],
      level: "ERROR"
    }
  }
};

ルートロガーモジュールを作成します。
このモジュールは、ログ設定モジュールを元にロガーを生成します。

// <APP ROOT>/lib/log/logger.js
const log4js = require("log4js");
const config = require("../../config/log4js-config.js");
log4js.configure(config);

// それぞれのログ種別ごとに作成
const console = log4js.getLogger();
const system = log4js.getLogger("system");  // 上で作成したcategoriesのsystemで作成します。

// ログ種別のエクスポート
module.exports = {
  console,
  system
};

ログ出力モジュールは、上で作成したモジュールとは別に作成します。

// <APP ROOT>/lib/log/systemLogger.js
const logger = require("./logger").system;

module.exports = (options) => (err, req, res, next) => {
  logger.error(err.message);
  next(err);
}

Expressアプリに実装します。

// <APP ROOT>/server.js
const express = require("express");
const app = express();

app.get('/', (req, res) => {
  logger.debug('デバッグログが出力されます');
  res.send('log test');
});

// 意図的にエラーを起こすルート
app.get("/error", (req, res) => {
  throw new Error("システムログの出力テスト Errorです");
});

// systemロガー
const systemLogger = require("./lib/log/systemLogger");
// ロガーをExpressに実装
app.use(systemLogger());

app.listen(3000);

ログ出力をテストしてみます。

# サーバー起動
$ node server.js

# curlでerrorルートにアクセス
$ curl localhost:3000/error

curlでアクセスすると、以下のようなログが出力されます。
また、systemディレクトリ、system.logファイルが存在しない場合は自動生成されます。

# <APP ROOT>/log/system/system.log
[2019-05-05T21:53:57.674] [Level { level: 40000, levelStr: 'ERROR', colour: 'red' }] system - システムログの出力テスト Errorです

次は、ログローテーションの機能を確認してみましょう。
以下のコマンドを実行して5MBのファイルを生成しておきます。

$ mkfile 5m ./log/system/system.log

ログ出力をテストしてみます。

# サーバー起動
$ node server.js

# curlでerrorルートにアクセス
$ curl localhost:3000/error

system.log(5MB)のファイル名がsystem.log.1に変更され、新しくsystem.logファイルが生成されるはずです。
次は、ログの保持は5ファイルまでにしていたので、こちらを確認してみましょう。
system.log.1~5までの5ファイル(5MB)、system.log(5MB)を用意します。

ログ出力のテストをしてみます。

# サーバー起動
$ node server.js

# curlでerrorルートにアクセス
$ curl localhost:3000/error

一番古いログ（作成日付が古いもの）がgzで生成され、system.logがsystem.log.1へと名前が変更されるはずです。
以上でシステムログの実装は完了です。

アプリケーションログの実装

アプリケーションログの要件は以下の通りです。

・エラーログのみ出力。
・機能毎にログファイルを分割する。
・1ファイルが一定のサイズになった時にローテーションする。（5MBでローテーション）
・/log/application/.log に出力する。
・世代管理は5ファイルまでとする。

Multi File Appenderを使う

アプリケーションログの実装には Multi File Appenderを使用します。
Multi File Appenderで指定できる設定は以下の通りです。

設定	型	詳細
type	string	設定できる値は multiFile のみ。
base	string	出力ファイルのパスを設定。（ファイル名は記述しない）
property	string	ログを分離する条件を設定。
extension	string	ログファイル名のサフィックスを設定。（拡張子のこと）
layout	object	ログ出力のレイアウトを指定。（日付のフォーマット等の設定）
maxLogSize	number	ログファイルの最大サイズ（byteで指定）この数値に達するとローテーションが実行されます。
backups	number	ログファイルの最大保持数を指定。
compress	boolean	ログファイルの保持数が上限に達した場合に古いログを削除するかの設定（trueに設定すると削除）

実装

ログ設定モジュールにシステムログ用の設定を追加します。

// <APP ROOT>/config/log4js-config.js
const path = require('path');
// ログ出力先は、サーバー内の絶対パスを動的に取得して出力先を設定したい
const APP_ROOT = path.join(__dirname, '../');

// ログ出力設定
module.exports = {
  appenders: {
    consoleLog: {
      type: 'console',
    },
    systemLog: {
      type: 'file',
      filename: path.join(APP_ROOT, './log/system/system.log'),
      maxLogSize: 5000000,
      backups: 5,
      compress: true,
    },
    // ADD
    applicationLog: {
      type: "multiFile",
      base: path.join(APP_ROOT, "./log/application/"),
      property: "key",
      extension: ".log", // ファイルの拡張子はlogとする
      maxLogSize: 5000000, // 5MB
      backups: 5, // 世代管理は5ファイルまで、古いやつからgzで圧縮されていく
      compress: true,
    },
  },
  categories: {
    default: {
      appenders: ["consoleLog"],
      level: "ALL"
    },
    system: {
      appenders: ["systemLog"],
      level: "ERROR"
    },
    // ADD
    application: {
      appenders: ["applicationLog"],
      level: "ERROR"
    }
  },
};

ルートロガーモジュールに追加します。

// <APP ROOT>/lib/log/logger.js
const log4js = require("log4js");
const config = require("../../config/log4js-config.js");
log4js.configure(config);

// それぞれのログ種別ごとに作成
const console = log4js.getLogger();
const system = log4js.getLogger("system");
const application = log4js.getLogger("application");  // ADD

// ログ種別のエクスポート
module.exports = {
  console,
  system,
  application,  // ADD
};

Expressアプリに実装します。

// <APP ROOT>/server.js
const express = require("express");
const app = express();

app.get('/', (req, res) => {
  logger.debug('デバッグログが出力されます');
  res.send('log test');
});

// 意図的にエラーを起こすルート
app.get("/error", (req, res) => {
  throw new Error("システムログの出力テスト Errorです");
});

// systemロガー
const systemLogger = require("./lib/log/systemLogger");
// ロガーをExpressに実装
app.use(systemLogger());

//===
const logger = require("./lib/log/logger").application;
logger.addContext("key", "test");
logger.error("アプリケーションログの出力テスト Errorです");
//===

app.listen(3000);

サーバーを起動すると、test.logという名前のファイルが作成されるはずです。

$ node server.js

# <APP ROOT>/log/application/test.log
[2019-05-06T07:50:08.500] [Level { level: 40000, levelStr: 'ERROR', colour: 'red' }] application - アプリケーションログの出力テスト Errorです

この実装で、アプリケーションログは出力できますが、アプリケーションログだけlogger.addContext()とlogger.error()の2行を書くのはダサいので修正します。

以下のような指定で出力できるようにしたい。

logger.error("test", "1行で出力できるようにしたい");

ルートロガーを修正します。

アプリケーションロガーを拡張して、アプリケーションID(key)と出力内容(message)を取得して、ログを出力できるようにします。

// <APP ROOT>/lib/log/logger.js
const log4js = require("log4js");
// log4jsの中からlevelを設定しているファイルを指定
// https://github.com/log4js-node/log4js-node/blob/master/lib/levels.js を参照
const levels = require("log4js/lib/levels").levels;
const config = require("../../config/log4js-config.js");
log4js.configure(config);

// それぞれのログ種別ごとに作成
const console = log4js.getLogger();
const system = log4js.getLogger("system");

// アプリケーションロガー拡張
const ApplicationLogger = function () {
  this.logger = log4js.getLogger("application");
};
const proto = ApplicationLogger.prototype;
for (let level of levels) {
  // log4jsのソースコード見ると、大文字になっているので小文字にします。
  level = level.toString().toLowerCase();
  proto[level] = (function (level) {
    return function (key, message) {
      const logger = this.logger;
      logger.addContext("key", key); // logger.Context("key", "test") で実装していたところをこちらで任意の値が設定できるようにする
      logger[level](message);
    };
  })(level);
}

// 新たにロガーを生成
const application = new ApplicationLogger();

// ログ種別のエクスポート
module.exports = {
  console,
  system,
  application,
};

Expressアプリケーションを修正します。

// <APP ROOT>/server.js
const logger = require("./lib/log/logger").application; // ADD
const express = require("express");
const app = express();

app.get('/', (req, res) => {
  logger.debug('デバッグログが出力されます');
  res.send('log test');
});

// 意図的にエラーを起こすルート
app.get("/error", (req, res) => {
  throw new Error("システムログの出力テスト Errorです");
});

// systemロガー
const systemLogger = require("./lib/log/systemLogger");
// ロガーをExpressに実装
app.use(systemLogger());

//===
logger.error("test", "1行で出力できるようにしたい"); // 今度はkeyとメッセージのみで出力できる
logger.error("app1","こちらは別のログファイルで出力される");  // ついでなのでこちらの確認もします
//===

app.listen(3000);

以下のログが出力されるはずです。

# <APP ROOT>/log/application/test.log
[2019-05-06T08:14:33.930] [Level { level: 40000, levelStr: 'ERROR', colour: 'red' }] application - 1行で出力できるようにしたい

# <APP ROOT>/log/application/app1.log
[2019-05-06T08:18:45.057] [Level { level: 40000, levelStr: 'ERROR', colour: 'red' }] application - こちらは別のログファイルで出力される

以上でアプリケーションログの実装は完了です。

アクセスログの実装

アクセスログの要件は以下の通りです。

・INFOログを出力。
・ファイルは日付でローテーションする。
・/log/access/access.log に出力する。
・世代管理は5ファイル（5日分）までとする。

Date Rolling File Appenderを使う

アクセスログの実装には、Date Rolling File Appenderを使用します。
Date Rolling File Appenderで指定できる設定は以下の通りです。

設定	型	詳細
type	string	設定できる値は、dateFile のみ。
filename	string	出力ファイルのパスを設定。
pattern	string	ログローテーションする際にサフィックス。（yyyy-MM-dd 等）
daysTokeep	number	ログファイル名のサフィックスを設定。（拡張子のこと）
layout	object	ログ出力のレイアウトを指定。（日付のフォーマット等の設定）
compress	boolean	ログファイルの保持数が上限に達した場合に古いログを削除するかの設定（trueに設定すると削除）
keepFileExt	boolean	patternで指定したサフィックスを.logの後につけるか前につけるかを指定。

Expressでアクセスログを出力するために

公式ドキュメントを見ると、log4js.connectLogger(logger,options)で指定できるようです。
loggerにはログ出力に使用するロガーを指定、optionsにはログレベルやログフォーマットを指定します。

optionsは指定できるものが多いので、まとめました。

①levelオプション

詳細
ログレベルを指定する。 "auto"または任意の値が設定できそうです。 "auto"を指定した場合、 ・3xx→WARNログ ・4xx、5xx→ERRORログ ・その他→INFOログ として出力されます。

②formatオプション

設定値	詳細
:date[フォーマット]	現在日時(サーバーサイド)、format指定にはelf/iso/webのいずれかを指定。
:http-version	リクエストHTTPのバージョンを表示。
:method	リクエストメソッド(POST、GET)を表示。
:referrer	リクエストのリファラを表示。
:remote-addr	リクエストのリモートアドレスを表示。
:remote-user	Basic認証を使用していた場合、リクエストユーザー名を表示。
:req[取得したいリクエストヘッダー]	指定したリクエストヘッダーを表示。
:res[取得したいレスポンスヘッダー]	指定したレスポンスヘッダーを表示。
:response-time[桁数指定]	レスポンス時間を指定した桁数で表示。
:status	レスポンスステータスを表示。
:url	リクエストURLを表示。
:user-agent	リクエストのUser-Agentを表示。

実装

ログ設定モジュールにアクセスログ用の設定を追加します。

// <APP ROOT>/config/log4js-config.js
const path = require('path');
// ログ出力先は、サーバー内の絶対パスを動的に取得して出力先を設定したい
const APP_ROOT = path.join(__dirname, '../');

// ログ出力設定
module.exports = {
  appenders: {
    consoleLog: {
      type: 'console',
    },
    systemLog: {
      type: 'file',
      filename: path.join(APP_ROOT, './log/system/system.log'),
      maxLogSize: 5000000,
      backups: 5,
      compress: true,
    },
    applicationLog: {
      type: "multiFile",
      base: path.join(APP_ROOT, "./log/application/"),
      property: "key",
      extension: ".log",
      maxLogSize: 5000000,
      backups: 5,
      compress: true,
    },
    // ADD
    accessLog: {
      type: "dateFile",
      filename: path.join(APP_ROOT, "./log/access/access.log"),
      pattern: "yyyy-MM-dd", // 日毎にファイル分割
      daysToKeep: 5, // 5日分の世代管理設定
      compress: true,
      keepFileExt: true,
    }
  },
  categories: {
    default: {
      appenders: ["consoleLog"],
      level: "ALL"
    },
    system: {
      appenders: ["systemLog"],
      level: "ERROR"
    },
    application: {
      appenders: ["applicationLog"],
      level: "ERROR"
    },
    // ADD
    access: {
      appenders: ["accessLog"],
      level: "INFO"
    }
  },
};

ルートロガーモジュールに追加します。

// <APP ROOT>/lib/log/logger.js
const log4js = require("log4js");
const levels = require("log4js/lib/levels").levels;
const config = require("../../config/log4js-config.js");
log4js.configure(config);

// それぞれのログ種別ごとに作成
const console = log4js.getLogger();
const system = log4js.getLogger("system");
const access = log4js.getLogger("access");  // ADD

const ApplicationLogger = function () {
  this.logger = log4js.getLogger("application");
};
const proto = ApplicationLogger.prototype;
for (let level of levels) {
  level = level.toString().toLowerCase();
  proto[level] = (function (level) {
    return function (key, message) {
      const logger = this.logger;
      logger.addContext("key", key);
      logger[level](message);
    };
  })(level);
}

const application = new ApplicationLogger();

// ログ種別のエクスポート
module.exports = {
  console,
  system,
  application,
  access,      // ADD
};

ログ出力モジュールは、ルートロガーモジュールとは別に作成します。

// <APP ROOT>/lib/logger/accessLogger.js
const log4js = require("log4js");
const logger = require("./logger").access;

module.exports = (options) => {
  options = options || {};  // オプションを指定する場合はそちらを使う
  options.level = options.level || "auto";  // ない場合、autoを設定
  return log4js.connectLogger(logger, options);  // ログ設定 Expressのアクセスログと結びつける
};

Expressアプリに実装します。

loggerの設定で、levelにautoを設定したので、ステータス毎にどのように出力されるかも確認してみます。

// <APP ROOT>/server.js
const accessLogger = require("./lib/log/accessLogger");  // ADD
const logger = require("./lib/log/logger").application;
const systemLogger = require("./lib/log/systemLogger");
const express = require("express");
const app = express();
app.use(systemLogger());
// ADD
app.use(accessLogger());

app.get('/', (req, res) => {
  logger.debug('デバッグログが出力されます');
  res.send('log test');
});

// ADD
app.get("/access1", (req, res) => {
  res.status(200).send("access test 200");
});
// ADD
app.get("/access2", (req, res) => {
  res.status(304).send("access test 304");
});
// ADD
app.get("/access3", (req, res) => {
  res.status(404).send("access test 404");
});
// ADD
app.get("/access4", (req, res) => {
  res.status(500).send("access test 500");
});

app.get("/error", (req, res) => {
  throw new Error("システムログの出力テスト Errorです");
});

app.listen(3000);

curlでaccess1~4にアクセスすると、以下のようにステータス毎にログレベルの表示が変化します。

# <APP ROOT>/log/access/access.log
[2019-05-06T09:39:28.034] [Level { level: 20000, levelStr: 'INFO', colour: 'green' }] access - ::1 - - "GET /access1 HTTP/1.1" 200 15 "" "curl/7.54.0"
[2019-05-06T09:40:06.079] [Level { level: 30000, levelStr: 'WARN', colour: 'yellow' }] access - ::1 - - "GET /access2 HTTP/1.1" 304 - "" "curl/7.54.0"
[2019-05-06T09:40:10.745] [Level { level: 40000, levelStr: 'ERROR', colour: 'red' }] access - ::1 - - "GET /access3 HTTP/1.1" 404 15 "" "curl/7.54.0"
[2019-05-06T09:40:16.519] [Level { level: 40000, levelStr: 'ERROR', colour: 'red' }] access - ::1 - - "GET /access4 HTTP/1.1" 500 15 "" "curl/7.54.0"

以上でアクセスログの実装は完了です。

今回作成したデモアプリはこちら に格納しました。

参考資料

紹介しきれていない設定がまだあるので、こちらを参考にすると細かい設定ができると思います。

・log4jsの公式マニュアル
・GitHub上にあるdocs