これは、なにをしたくて書いたもの？
Node.jsでアプリケーションを書く時のロギングライブラリは、どういうものがあるのかちょっと気になりまして。
調べた感じ、以下のようなものがありそうです。
GitHub - winstonjs/winston: A logger for just about everything.
GitHub - trentm/node-bunyan: a simple and fast JSON logging module for node.js services
GitHub - log4js-node/log4js-node: A port of log4js to node.js
GitHub - npm/npmlog: The logger that npm uses
今回は、この中でもstar数が多いwinstonを試してみることにしました。
winston
winstonは、複数のトランスポート（出力先）をサポートするロギングライブラリです。
GitHub - winstonjs/winston: A logger for just about everything.
ロガーを作成する時に、
- 出力先
- ログフォーマット
- 出力するログレベル
などを設定できますが、カテゴリ別にロガーを作成したり、デフォルトロガーを設定したりもできます。
Working with multiple Loggers in winston
ログの出力先には、ビルトインではコンソール、ファイル、HTTP、Streamが選べ、その他にもコミュニティなどでいろいろと
実装されているようです。
winston/transports.md at 3.2.1 · winstonjs/winston · GitHub
フォーマットについては、logformでのものが扱えるようです。
GitHub - winstonjs/logform: An mutable object format designed for chaining & objectMode streams
Logstashフォーマットとかもあったりします。
とりあえず、今回は簡単に試してみるとしましょう。
環境
今回の環境は、こちら。
$ node -v v10.15.3 $ npm -v 6.4.1
準備
winstonのインストール。
$ npm i winston
インストールされたwinstonのバージョン。
"dependencies": { "winston": "^3.2.1" }
今回は、こちらを使っていきたいと思います。
winstonを使っていろいろ試す
それでは、ここからいくつか簡単にwinstonを使ったコードを書いていきましょう。
Getting Started的な
なにはともあれ、まずは動かしてみます。
こんなコードを用意。
winston-example1.js
const winston = require('winston'); const logger = winston.createLogger({ level: 'info', format: winston.format.json(), // default transports: [ new winston.transports.Console() ] }); logger.debug('Debug Message'); logger.info('Info Message'); logger.warn('Warn Message'); logger.error('Error Message');
ログ出力先をコンソール、出力するログレベルをinfo以上に、ログフォーマットをJSONにしました。ログ出力先（Transport）は、
指定しないとエラーになります。
ロガーのデフォルト設定は以下に記載がありますが、ログフォーマットはJSON、ログ出力レベルはinfo以上みたいです。
実行。
$ node winston-example1.js
{"message":"Info Message","level":"info"}
{"message":"Warn Message","level":"warn"}
{"message":"Error Message","level":"error"}
ログ出力レベルがinfo以上なので、debugのものは出力されていませんね。また、ログフォーマットはJSONです。
ちなみに、ログレベルの一覧はこちら。
今回はdebug、info、warn、errorしか使っていませんが、もっとたくさんあることがわかります。
ログにタイムスタンプを入れ、メッセージをフォーマット指定できるようにしてみる
先ほどのログには、実行時のタイムスタンプがありません。できれば、タイムスタンプを表示したいところです。
また、ログメッセージに%sのようなフォーマット指定もできるようなので、こちらも合わせて試してみました。
winston-example2.js
const winston = require('winston'); const format = winston.format; const logger = winston.createLogger({ level: 'info', format: format.combine( format.timestamp(), // timestampを出力する format.splat(), // String interpolation splat for %d %s-style messages. format.json() ), transports: [ new winston.transports.Console() ] }); logger.debug('Debug Message'); logger.info('Info Message'); logger.warn('Warn Message'); logger.error('Error Message'); logger.debug('%s %s', 'Debug','Message'); logger.info('%s %s', 'Info', 'Message'); logger.warn('%s %s', 'Warn', 'Message'); logger.error('%s %s', 'Error', 'Message');
こちらは、フォーマットをcombineで組み合わせることで設定しています。
format: format.combine(
format.timestamp(), // timestampを出力する
format.splat(), // String interpolation splat for %d %s-style messages.
format.json()
),
この指定する順番が大事みたいで、jsonの後にtimestampを入れたりすると、タイムスタンプは出力されません…。
詳細は、logformを見てみるとよいでしょう。
GitHub - winstonjs/logform: An mutable object format designed for chaining & objectMode streams
確認。
$ node winston-example2.js
{"message":"Info Message","level":"info","timestamp":"2019-05-21T14:21:17.627Z"}
{"message":"Warn Message","level":"warn","timestamp":"2019-05-21T14:21:17.628Z"}
{"message":"Error Message","level":"error","timestamp":"2019-05-21T14:21:17.628Z"}
{"level":"info","message":"Info Message","timestamp":"2019-05-21T14:21:17.629Z"}
{"level":"warn","message":"Warn Message","timestamp":"2019-05-21T14:21:17.629Z"}
{"level":"error","message":"Error Message","timestamp":"2019-05-21T14:21:17.629Z"}
タイムスタンプがログに入り、%sの部分も置換されるようになっています。
タイムスタンプのフォーマットを変えたい場合は、timestampにformatで指定すればよいみたいです。
ログフォーマットに任意の項目を追加する
ログフォーマットに、任意の項目を追加してみましょう。要するに、カスタムフォーマットの作り方です。
今回は、「hostname」という項目を足してみました。
winston-example3.js
const winston = require('winston'); const format = winston.format; const hostname = format((info, opts = {}) => { let value; if (!opts.hostname) { value = 'myhost'; } else { value = opts.hostname; } if (!opts.alias) { info.hostname = value; } else { info[opts.alias] = value; } return info; }); const logger = winston.createLogger({ level: 'info', format: format.combine( format.timestamp(), hostname(), // custom format format.json() ), transports: [ new winston.transports.Console() ] }); logger.debug('Debug Message'); logger.info('Info Message'); logger.warn('Warn Message'); logger.error('Error Message');
フォーマットは、format関数で作成します。今回は、ホスト名（固定ですが）を入れることにしました。
const hostname = format((info, opts = {}) => { let value; if (!opts.hostname) { value = 'myhost'; } else { value = opts.hostname; } if (!opts.alias) { info.hostname = value; } else { info[opts.alias] = value; } return info; });
この関数を、formatオプションで指定します。
format: format.combine(
format.timestamp(),
hostname(), // custom format
format.json()
),
確認。
$ node winston-example3.js
{"message":"Info Message","level":"info","timestamp":"2019-05-21T14:25:30.017Z","hostname":"myhost"}
{"message":"Warn Message","level":"warn","timestamp":"2019-05-21T14:25:30.018Z","hostname":"myhost"}
{"message":"Error Message","level":"error","timestamp":"2019-05-21T14:25:30.018Z","hostname":"myhost"}
「hostname」という項目が増えましたね。
今回は使っていませんが、このhostnameにオプションを与えると、動作のカスタマイズができるようになります。以下のコードで、
infoは実際に出力するログの情報で、optsはformatを作成する時のオプションです。
const hostname = format((info, opts = {}) => { let value; if (!opts.hostname) { value = 'myhost'; } else { value = opts.hostname; } if (!opts.alias) { info.hostname = value; } else { info[opts.alias] = value; } return info; });
オプションは、こんな感じで指定します。
hostname({ alias: 'servername' }), // custom format
ログを複数の出力先に出力する
出力先（Transport）を複数指定することで、ログを複数のターゲットに出力することができます。
たとえば、コンソールとファイルに出力する場合。
winston-example4.js
const winston = require('winston'); const logger = winston.createLogger({ level: 'info', transports: [ new winston.transports.Console({ level: 'warn' }), new winston.transports.File({ filename: 'app.log', level: 'debug' }) ] }); logger.debug('Debug Message'); logger.info('Info Message'); logger.warn('Warn Message'); logger.error('Error Message');
出力先（Transport）単位で、設定を変更することもできます。
transports: [ new winston.transports.Console({ level: 'warn' }), new winston.transports.File({ filename: 'app.log', level: 'debug' }) ]
今回はデフォルトのログレベルはinfoにしていますが、コンソールはwarn、ファイルはdebugにしてみました。また、ファイルの方の
出力先はapp.logとします。
確認。
$ node winston-example4.js
{"message":"Warn Message","level":"warn"}
{"message":"Error Message","level":"error"}
コンソールには、infoも出なくなりました。ファイルのログを見てみましょう。
$ cat app.log
{"message":"Debug Message","level":"debug"}
{"message":"Info Message","level":"info"}
{"message":"Warn Message","level":"warn"}
{"message":"Error Message","level":"error"}
こちらは、debugレベルまで出力されています。
Transportは、他にもデイリーでローテーションするものだったりといろいろあるので、確認してみるとよいでしょう。
winston/transports.md at 3.2.1 · winstonjs/winston · GitHub
CLIログフォーマットにする
ここまでJSONフォーマットでログを出力していましたが、もっとCLIっぽいログでも出力してみようかなと。
こんな感じのフォーマットでどうでしょう。
winston-example5.js
const winston = require('winston'); const format = winston.format; const logger = winston.createLogger({ level: 'info', format: format.combine( format.timestamp(), // timestampを出力する format.cli(), format.printf(info => `[${info.timestamp}] ${info.level} ${info.message}`) ), transports: [ new winston.transports.Console() ] }); logger.debug('Debug Message'); logger.info('Info Message'); logger.warn('Warn Message'); logger.error('Error Message');
タイムスタンプを入れたCLIフォーマットで、追加したタイムスタンプの位置はprintfで決定します。
確認。
$ node winston-example5.js [2019-05-21T14:33:57.427Z] info Info Message [2019-05-21T14:33:57.428Z] warn Warn Message [2019-05-21T14:33:57.428Z] error Error Message
ログレベルは、カラーで出力されます。
CLIフォーマットの正体は、colorize、padLevelsを組み合わせたものです。
カラー表示をやめたければ、cliの部分をsimpleにするとよいでしょう。
format: format.combine(
format.timestamp(), // timestampを出力する
format.simple(),
format.printf(info => `[${info.timestamp}] ${info.level} ${info.message}`)
),
ログにErrorを出力させる
ログ出力の際には、try〜catchしたErrorを出力させたいこともあるでしょう。
あんまりドキュメントにそれっぽいことが書かれていなかったので、試してみましたがこんな感じっぽいです。 winston-example6.js
const winston = require('winston'); const logger = winston.createLogger({ transports: [ new winston.transports.Console() ] }); logger.error('error: ', new Error('Oops!!')); // OK logger.error(new Error('Oops!!')); // NG
2つ目のログ出力は、NG例です。
確認。
$ node winston-example6.js
{"level":"error","message":"error: Oops!!","stack":"Error: Oops!!\n at Object.<anonymous> (/path/to/winston-example6.js:9:25)\n at Module._compile (internal/modules/cjs/loader.js:701:30)\n at Object.Module._extensions..js (internal/modules/cjs/loader.js:712:10)\n at Module.load (internal/modules/cjs/loader.js:600:32)\n at tryModuleLoad (internal/modules/cjs/loader.js:539:12)\n at Function.Module._load (internal/modules/cjs/loader.js:531:3)\n at Function.Module.runMain (internal/modules/cjs/loader.js:754:12)\n at startup (internal/bootstrap/node.js:283:19)\n at bootstrapNodeJSCore (internal/bootstrap/node.js:622:3)"}
{"level":"error"}
ひとつ目のログは、こんな感じに出力されています。
{"level":"error","message":"error: Oops!!","stack":"Error: Oops!!\n at Object.<anonymous> (/path/to/winston-example6.js:9:25)\n at Module._compile (internal/modules/cjs/loader.js:701:30)\n at Object.Module._extensions..js (internal/modules/cjs/loader.js:712:10)\n at Module.load (internal/modules/cjs/loader.js:600:32)\n at tryModuleLoad (internal/modules/cjs/loader.js:539:12)\n at Function.Module._load (internal/modules/cjs/loader.js:531:3)\n at Function.Module.runMain (internal/modules/cjs/loader.js:754:12)\n at startup (internal/bootstrap/node.js:283:19)\n at bootstrapNodeJSCore (internal/bootstrap/node.js:622:3)"}
よくよく見ると、指定したメッセージに、さらにErrorのメッセージが追加されていますね。
"message":"error: Oops!!"
これは、このあたりで行われているようです。
https://github.com/winstonjs/winston/blob/3.2.1/lib/winston/logger.js#L241-L242
また、2つ目のログは、Errorの情報がキレイに無視されています。
{"level":"error"}
というわけで、メッセージとは別にErrorを指定しましょうということで。
logger.error('error: ', new Error('Oops!!')); // OK
その他
カテゴリーとかも便利かなぁとは思いますが、今回はいいかなぁと。
Working with multiple Loggers in winston
メモとしては、書き留めておく程度にしておきます。
とりあえず、基本的な使い方としてはこんなところではないでしょうか。
