SEROKU の開発を例に、弊社で使っているリモートデバッグとロガーの Tips をご紹介します。
当記事は 2018 年と過去の記事ですが、現在でも応用可能な Tips になっています。

記事の最後に関連記事を掲載しています。よろしければご参考にどうぞ。

案件としても OSS 成果物としても、JavaScript を利用するシチュエーションは増え続けています。まだまだ枯れた言語とは言い難い状況で、使われるバージョンも ES5 から ES7 まで進化を続け、新しい文字列リテラルや async/await のような「イマドキの JavaScript の書き方」を紹介する記事は多い中、デバッグはこうあるべきという情報は比較的少ないように思います。

本記事の前編にあたる「イマドキの JavaScript 開発で使える、リモートデバッグとロガーの Tips (前編)」では、システム開発に於けるデバッガ、ロガーの大切さと、他の言語・フレームワークと比べた際の JavaScript 開発環境に於けるビハインドについて説明しました。

本記事ではいよいよ JavaScript の世界での理想的なロガーの具体的な設定方法を紹介します。

理想の世界

まずは前編で掲げたゴールの再掲です。

対象システム

以下の3つのシナリオをカバーすることにします。

• シナリオA

  • node.js (Express)

• シナリオB

  • node.js (Express) + webpack/babel によるクライアントビルド

• シナリオC

  • next.js on Express

やりたいこと

• 記述側

  • サーバーサイド、クライアントサイド両方で同じログモジュールを利用できる
  • ログレベルを指定したログ出力行の記述ができる

• 出力側

  • サーバーサイド、クライアントサイド両方で同じログモジュールを利用できる

  • development, production 等の環境用の設定ファイルでデフォルトの挙動を設定できる

    • 環境変数設定により、上記を一時的に変更できる

  • プロダクト全体でのデフォルトログ出力レベルを設定できる

  • ログのネームスペースごとにログ出力レベルを設定できる

  • development, production 等の環境に応じて出力フォーマットを変更できる

    • development 環境ではフォーマットされたログ出力
    • production 環境下では JSON フォーマット出力による高速なログ出力

• 過去の資産の有効利用

  • 今まで記述された debug ライブラリによる記述を変更することなく、新しいロギングライブラリによる出力を可能にする

利用ライブラリ選定

node.js 環境向けのロガーでは、winston、Bunyan、log4js、pino あたりが有名処です。

npm の weekly download, Github のスター数で言えば、勢力図は 2018/08 現在以下のようになっています。

pino (選外)

上記のうち、pino は筆者も実際に Production 環境で利用したことがあり、その処理速度は素晴らしいものがあります。Extreme Mode の発想なども興味深く、設計と API 双方からスピードに対するこだわりがにじみ出ていました。 Github の Issue の開発スタッフのストイックさも特徴的です。

ただ、ログレベルと出力先(出力方法)の設定が他ライブラリと比べて貧弱で、今回の理想の世界を実現する上で足枷となったため、選外としました。

log4js (選外)

log4js は名前からも分かるとおり、log4j を意識したライブラリです。Appender や Layouts など、Java 界隈のエンジニアには概念的に馴染みやすいものと言えるでしょう。

こちらは機能的には問題ないものの、ブラウザ利用向けの周辺ライブラリが見当たらなかったことから選外としました。

Bunyan を採用

残る2つ、Winston と Bunyanは機能的にはどれも申し分ありません。今回は勢力図では3番手(Github stars では2番手)である Bunyan (バニヤンと読むらしいです) を採用することにします。

コラム: Winston と Bunyan
Winston と Bunyan の違いは何でしょうか？
比較記事としてはかなり古いのですが以下が有名です。
Comparing Winston and Bunyan Node.js Logging
こちらの記事からは、ストレージへのログ書き込みを主眼としていた Winston に比べて、Bunyan にはシンプルで魅力的なアイデンティティーを持っていることがわかります。

• JSON 出力を標準とした作り
• 書き込み対象として Writable Stream interface を意識した作り

これらはコンテナ時代にマッチしますし、出力先がどこであれストリームとして扱うというのは、よりクリーンな設計思想に見えます。
上記記事は執筆された時から長い時間が経過し、つい先日(2018.06)には Winston 3.0 がリリースされました。強力な Transport は Winston の大きな特徴でしたが、winston-transport という

Stream implementation & legacy Transport wrapper.

が外部モジュールとして作成され、従来の Transports エコシステムをそのまま利用可能なストリーム実装、という形式にコア部分が書き直されたようです。思想的には Bunyan に寄った形になったと見ていいでしょう。ただし、リリースされてまだ間もないため、信頼性という意味では v3 系の採用はもう少し時間をおいた方がいいかもしれません。

準備 ― 依存関係整備

ではここからは実際のコードの紹介です。
まずは package.json から。シナリオA～Cまで全てで必要になるものを全て挙げます。

"dependencies": {
    "browser-bunyan": "^1.3.0",
    "bunyan": "^1.8.12",
    "bunyan-format": "^0.2.1",
    "express-bunyan-logger": "^1.3.3",
    "minimatch": "^3.0.4",
    "module-alias": "^2.0.6",
    "next-bunyan": "^0.0.1",
},
"_moduleAliases": {
    "@services/logger": "lib/service/logger"
},

「"_moduleAliases" ってなんだよ？？」と思われる方もいらっしゃるかもしれません。ひとまずおまじない的に書いておいてください。便利な使い方を後述します。

Let's Try！ ― シナリオA

シナリオAは、node.js (Express) 環境向けのロガー設定です。

設定用ファイル

利用時のイメージを掴みやすいよう、コンフィグファイルから作っていきましょう。

config/logger/config.dev.js

module.exports = {
  default: 'info',

  //// configure level for name
  // 'myapp:*': 'debug',
  'myapp:utils:third-party': 'error',
};

config/logger/config.prod.js

module.exports = {
  default: 'info',
};

上記2ファイルは、それぞれ開発時の設定ファイル、本番環境用の設定ファイルです。
'${ログネームスペース}': '${ログレベル}' という書式の記述をカンマ区切りで列挙できるような形式です。ログネームスペースはここではコロン区切りの blob となっていますが、実際にはどんな文字列でも構いません。

デフォルトのログレベルは default というキーで指定できます。

そして以下は、今し方作成した設定を NODE_ENV 毎に読みわけるためのファイルです。

config/index.js

function envShortName() {
  switch (process.env.NODE_ENV) {
    case 'production':
      return 'prod';
    default:
      return 'dev';
  }
}

module.exports = {
  logger: require(./logger/config.${envShortName()}),
};

サービスモジュール

次に、ロガーインスタンスを作成するようなサービスモジュールを作成します。まずは上で定義したような設定ファイルを読み込む機能は考慮しないコードです。

services/logger/index.js--(WIP)

const bunyan = require('bunyan');   // will be replaced to browser-bunyan on browser by next-bunyan

const isBrowser = typeof window !== 'undefined';
const isProd = process.env.NODE_ENV === 'production';
const isTest = process.env.NODE_ENV === 'test';

let stream = isTest
  ? require('./stream.test')
  : isProd
    ? require('./stream.prod')
    : require('./stream.dev');

// logger store
let loggers = {};

/**
 * determine logger level
 * @param {string} name Logger name
 */
function determineLoggerLevel(name) {
  if (isBrowser && isProd) {
    'error';
  }

  return 'info';
}

module.exports = (name) => {
  // create logger instance if absent
  if (loggers[name] == null) {
    loggers[name] = bunyan.createLogger({
      name,
      stream,
      level: determineLoggerLevel(name),
    });
  }

  return loggers[name];
};

まだこのファイルだけでは動作させることはできません。このファイルから参照するストリーム設定用のファイルが必要です。

ストリーム設定ファイル

まずは開発環境用のファイル。

services/logger/stream.dev.js

const isBrowser = typeof window !== 'undefined';

let stream = undefined;

// browser settings
if (isBrowser) {
  const ConsoleFormattedStream = require('@browser-bunyan/console-formatted-stream').ConsoleFormattedStream;
  stream = new ConsoleFormattedStream();
}
// node settings
else {
  const bunyanFormat = require('bunyan-format');
  stream = bunyanFormat({ outputMode: 'short' });
}

module.exports = stream;

開発環境では、ブラウザ上ではフォーマット済み文字列をブラウザコンソールに、node.js 上では同じくフォーマットされた文字列を実行中のコンソールに出力します。

次に本番環境用。

services/logger/stream.prod.js

const isBrowser = typeof window !== 'undefined';

let stream = undefined;

// browser settings
if (isBrowser) {
  const ConsoleFormattedStream = require('@browser-bunyan/console-formatted-stream').ConsoleFormattedStream;
  stream = new ConsoleFormattedStream();
}
// node settings
else {
  // do nothing
  // output JSON to stdout
}

module.exports = stream;

こちらはブラウザ上の設定は開発環境用と同じですが、node.js 上は stream 変数を undefined のままにしています。Bunyan のデフォルト挙動となり、stdout に JSON 形式で出力されます。

最後にテスト用です。

services/logger/stream.test.js

const bunyanFormat = require('bunyan-format');
const stream = bunyanFormat({ outputMode: 'short' });

module.exports = stream;

ここまでで、require('services/logger')('myapp:mymodule') のように呼び出すことで、myapp:mymodule ネームスペース用のロガーインスタンスを生成することができます。

このままでは最初に作った設定ファイル群が活きないので、services/logger/index.js に手を加えます。

services/logger/index.js

const bunyan = require('bunyan');   // will be replaced to browser-bunyan on browser by next-bunyan
const minimatch = require('minimatch');

const isBrowser = typeof window !== 'undefined';
const isProd = process.env.NODE_ENV === 'production';
const isTest = process.env.NODE_ENV === 'test';

let config = require('../../config').logger;

let stream = isTest
  ? require('./stream.test')
  : isProd
    ? require('./stream.prod')
    : require('./stream.dev');

// logger store
let loggers = {};

// merge configuration from environment variables
const envLevelMap = {
  INFO:   'info',
  DEBUG:  'debug',
  WARN:   'warn',
  TRACE:  'trace',
  ERROR:  'error',
};
Object.keys(envLevelMap).forEach(envName => {   // ['INFO', 'DEBUG', ...].forEach
  const envVars = process.env[envName];         // process.env.DEBUG should have a value like 'growi:routes:page,growi:models.page,...'
  if (envVars != null) {
    const level = envLevelMap[envName];
    envVars.split(',').forEach(ns => {          // ['growi:routes:page', 'growi:models.page', ...].forEach
      config[ns.trim()] = level;
    });
  }
});

/**
 * determine logger level
 * @param {string} name Logger name
 */
function determineLoggerLevel(name) {
  if (isBrowser && isProd) {
    'error';
  }

  let level = config.default;

  // retrieve configured level
  Object.keys(config).some(key => { // breakable forEach
    // test whether 'name' matches to 'key'(blob)
    if (minimatch(name, key)) {
      level = config[key];
      return;                       // break if match
    }
  });

  return level;
}

module.exports = (name) => {
  // create logger instance if absent
  if (loggers[name] == null) {
    loggers[name] = bunyan.createLogger({
      name,
      stream,
      level: determineLoggerLevel(name),
    });
  }

  return loggers[name];
};

かなりごちゃっとしていますが、やっていることは環境変数や設定ファイルの map で定義しているネームスペースごとにログレベルを変更しているだけです。

使ってみよう！

ここまでのコードで、

• シナリオA

  • node.js (Express)

環境はカバーできたことになります。それでは使ってみましょう。以下のように定義、利用します。

app.js

const logger = require('services/logger')('myapp:app');

(..snip..)

// listen
expressApp.listen(process.env.PORT, err => {
  if (err) {
    throw err;
  }
  logger.info('> Ready on http://localhost:' + process.env.PORT + ' [' + process.env.NODE_ENV + ']');
});

以下のようなショートフォーマットされたログが出力されるはずです。

10:00:00.000Z  INFO myapp:app: > Ready on http://localhost:3000 [development]

「require('../../../../services/logger') …あれ、まだ足りない？」

Java と違ってパッケージの概念がない JavaScript では、require や import 時の階層の解決は頭の痛い問題です。

そこで、packages.json に記述した _moduleAliases の出番です。これによってどの階層にあるファイルからでも @services/logger で先ほど作成したロガーモジュールを参照できます。

利用側のコードとしては、どのファイルからでも

const logger = require('@services/logger')('myapp:...');

という書き方で参照可能になります。

環境変数で設定を上書きする

本番ディプロイ後に思わぬトラブルに見舞われ、特定のモジュールのログを吐き出したい、という要求もあることでしょう。以下のように環境変数を設定することで、一時的にログレベルを変更することができます。

• DEBUG=myapp:app,myapp:routes:*
• TRACE=myapp:services:passport

キーがログレベルの大文字表現、値がログネームスペースのカンマ区切りとなります。

debug ライブラリ代替

既存の debug ライブラリによるログ出力行が山のようにあるプロジェクトに対して、一つ一つを新しいロガーの記述に書き換えていくのは大変です。

ここでまたpackages.json に記述した _moduleAliases が活躍します。
まずは package.json の _moduleAliases に以下を追加しましょう。

package.json

"_moduleAliases": {
    "debug": "lib/services/logger/alias-for-debug"
},

そして alias-for-debug.js を作成します。

services/logger.alias-for-debug.js

/**
 * return 'debug' method of bunyan logger
 *
 * This is supposed to be used as an replacement of "require('debug')"
 *
 * @param {string} name
 */
module.exports = (name) => {
  const bunyanLogger = require('./index')(name);
  return bunyanLogger.debug.bind(bunyanLogger);
};

これで、debug ライブラリを利用して出力されたログは、Bunyan 内でログレベル debug として取り扱われます。具体的には、

const debug = require('debug')('myapp:routes:page');

debug('Debug message!');

のように利用していた部分はそのまま Bunyan で処理されるので、myapp:routes:page ログネームスペースの出力レベルを debug 以上にすることでログが出力されるようになります。

この機能を利用することで、debug ライブラリを利用してログ出力しているサードパーティー製ライブラリのログも、同じ設定ファイル(環境変数)でログの出し分けを設定することができます。

(おまけ) 開発時の Express ログ向け設定

Express のログをどう出したいかは好みになりますが、「ヒューマンリーダブルかどうか」を重視すると、morgan の出力ほど見やすいものはありません。しかもほぼコンフィグレスです。一方Bunyan を使って同等の情報量にしようとすると、設定が煩雑になります。

以下は、低速かつ JSON 出力できない morgan は開発環境のみで利用し、一方で本番環境では express-bunyan-logger を利用して高速に JSON 出力するような設定を行うコードです。

/**
 * initialize logger for Express
 * @param {object} expressApp
 */
initExpressLogger(expressApp) {
  const isProd = process.env.NODE_ENV === 'production';

  // use bunyan
  if (isProd) {
    const expressBunyanLogger = require('express-bunyan-logger');
    const logger = require('@services/logger')('express');
    expressApp.use(expressBunyanLogger({ logger }));
  }
  // use morgan
  else {
    const morgan = require('morgan');
    expressApp.use(morgan('dev'));
  }
}

Let's Try！ ― シナリオB

シナリオBは、node.js (Express) + webpack/babel によるクライアントビルド両方で利用できる設定です。

といっても、ここまでに作ったファイルは完全に流用できますので、必要なのは webpack の設定のみです。

webpack.js

(..snip..)

resolve: {
  alias: {
    '@services/logger': 'services/logger',
    // replace bunyan
    'bunyan': 'browser-bunyan',
  }
},

(..snip..)

node.js 向けには package.json の _moduleAliases で行っていたことを、webpack でも設定するというだけです。ただし、require('bunyan') は require('browser-bunyan') に置き換わることになります。

使ってみよう！

使い方は全く同じです。あえて ES Module での import 風に書くと以下のようになります。

components/Component1.mjs

import loggerFactory from '@services/logger';
const logger = loggerFactory('myapp:components:comp1');

export default class extends React.Component {

  render() {
    logger.debug('test: debug: render() about');
    logger.info('test: info: render() about');

(..snip..)

Let's Try！ ― シナリオC

シナリオCは、next.js 向けの設定です。

ここでもシナリオAで作ったファイルはそのまま流用できます。シナリオBで行った webpack 用の設定を、next.js 専用の設定ファイルの書式で書き直すだけです。

next.config.js

const path = require('path');
const withBunyan = require('next-bunyan');

module.exports = withBunyan({
  webpack: (config, { dev }) => {

    (..snip..)

    // resolve
    config.resolve.alias = Object.assign({
      '@services/logger': path.resolve(__dirname, './services/logger'),
    }, config.resolve.alias || {});

    // Important: return the modified config
    return config;
  },

(..snip..)

require('bunyan') => require('browser-bunyan') への置き換えは、next-bunyan がやってくれます。

使ってみよう！

シナリオBと全く同じですので割愛します。

まとめ

中編ではロギングに関して実際のコードを紹介し、node.js, webpack/babel, そして next.js という3つのシナリオ、3つの環境で理想的なロギングを行うことができるようになりました。柔軟なログネームスペース、ログレベルの設定や運用時の一時的な変更だけでなく、これまで debug ライブラリを使っていたコードベースに対しても二重管理することなく美しいログ出力ができるシステムを実現可能です。

手前味噌ですがこれらのコードは移植性も高いので、全てのプロジェクトにファイルをコピーして持っていくだけで同じ効能を得ることができます。チーム内のロギングに関する学習コスト節約にもなるのではないでしょうか。

次回、後編では、デバッガ利用の「理想の世界」を実現する具体的なコードを紹介していきます。

関連記事

イマドキの JavaScript 開発で使える、リモートデバッグとロガーの Tips (前編)