Node.jsアプリケーションのログ出力に、winstonを使ってみる

これは、なにをしたくて書いたもの？

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

Using the Default Logger

ログの出力先には、ビルトインではコンソール、ファイル、HTTP、Streamが選べ、その他にもコミュニティなどでいろいろと
実装されているようです。

winston/transports.md at 3.2.1 · winstonjs/winston · GitHub

フォーマットについては、logformでのものが扱えるようです。

Formats

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以上みたいです。

Creating your own Logger

実行。

$ node winston-example1.js 
{"message":"Info Message","level":"info"}
{"message":"Warn Message","level":"warn"}
{"message":"Error Message","level":"error"}

ログ出力レベルがinfo以上なので、debugのものは出力されていませんね。また、ログフォーマットはJSONです。

ちなみに、ログレベルの一覧はこちら。

Logging Levels

今回は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を入れたりすると、タイムスタンプは出力されません…。

Combine

詳細は、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の部分も置換されるようになっています。

ところで、タイムゾーンがUTC感。

タイムスタンプのフォーマットを変えたい場合は、timestampにformatで指定すればよいみたいです。

Timestamp

ログフォーマットに任意の項目を追加する

ログフォーマットに、任意の項目を追加してみましょう。要するに、カスタムフォーマットの作り方です。

Creating custom formats

今回は、「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は、他にもデイリーでローテーションするものだったりといろいろあるので、確認してみるとよいでしょう。

GitHub - winstonjs/winston-daily-rotate-file: A transport for winston which logs to a rotating file each day.

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

カラー表示をやめたければ、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

その他

カテゴリーとかも便利かなぁとは思いますが、今回はいいかなぁと。