Express v4 と log4js v4 で実践的なロガーを実装
この記事はQiitaの記事をエクスポートしたものです。内容が古くなっている可能性があります。
はじめに
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でローテーション)
・
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でローテーション)
・
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ログを出力。
・ファイルは日付でローテーションする。
・
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"
以上でアクセスログの実装は完了です。
今回作成したデモアプリはこちら に格納しました。
参考資料
紹介しきれていない設定がまだあるので、こちらを参考にすると細かい設定ができると思います。