自分はどちらかというとRubyistなのですが、最近Node.jsの案件を手伝っていて、全ログにリクエストIDを入れたのでメモ。

前提

リクエストIDとは

Webのシステムで、リクエストIdつまりリクエスト毎に固有のIDをログに入れるということが一般的になっています。

どういうことかというと、システムがリクエストを受け取ってからなるべく早いタイミングでIDを振って、各コンポーネントはそのIDをログ出力などに含めます。こうすることで特定のリクエストに関する情報が追いやすくなるので障害調査などが非常に楽になります。

リクエストIDの発行

IDの発行ですが、ロードバランサなどWebアプリそのものよりフロントに置かれるシステムで発行することが多いと思います。
herokuなどのPaaSでは、X-Request-Idヘッダーという形でシステムがリクエストに発行したIDを渡してくれる事が多く、これを使うことになります。
また、nginxでは、$request_idという変数があり、これをリバースプロキシの際にリクエストのX-Request-Idヘッダーに入れるように設定することで実現出来ます。apacheでも同様です。

https://devcenter.heroku.com/articles/http-request-id
http://nginx.org/en/docs/http/ngx_http_core_module.html#var_request_id
http://stackoverflow.com/a/38447872/5598558
http://serverfault.com/a/797611

開発中やフロントシステムから渡ってこない場合は、UUID v4とか、nginxみたいにランダムな16進を16バイト分とか、webアプリ側で生成します。

Ruby on Railsでは

webアプリ側ですが、例えばRuby on Railsの場合は、標準でリクエストIDをX-Request-Idヘッダーで受け取り（無ければ生成）、これをログに出力する仕組みがあります。

これを既存のNode.js、というかlog4jsでログ出力しているExpressのwebアプリで実現しましたっていうのが、この記事です。

環境

一応、実装時の環境です：

Node.js v4.4.x (LTS)
- 使えるES6は使ってます。（全部は使えないのです。 http://node.green/ 参照）
Express 4.13.x
- Expressに特化したことはしていないつもりなので、他のConnect系のフレームワークでも参考にはなるかと。
log4js 0.6.x
- 最後のレイアウトの所だけですので、他のライブラリでも参考になるかと。

実装

そもそも

「リクエストIDをThread localにストアして、ロガーで出力時にそれを読めば良いんでしょ。」くらいの軽い感覚で始めたんですが、そもそもJSの非同期はスレッドではないんですね。

Node的コールバックやらPromiseやら、内部では基本的にイベント型の非同期処理でシステムが動いているので、各処理がどのイベントに端を発した処理なのかを判別する仕組みが必要な訳ですが、JSにはそんな仕組みが備わっているわけでは無く…

Domain

で、Node.jsのDomainという仕組みを使うことになります。

https://nodejs.org/api/domain.html

赤く"Deprecated"と出ますが、実際の所は"pending deprecation"（v6.4現在）ということで、代わりの仕組みが実現されたらdeprecateされる予定、ということです。なのでそんなにすぐ無くなる感じでは無いようです。まあミッションクリティカルなロジックには使わない方が良いですが、将来ログにリクエストIDが出なくなったとしてもシステム自体は止まらないので関係ないですね。そのときには代わりの仕組みが出来ているでしょうし。

Domainは主にエラーハンドリングのための仕組みです。ですが、あるイベントに端を発した一連の処理をグループしてトラックしてくれる、というのがその真の価値です。

リクエスト毎にdomainを作成すると、同じリクエストから出発した処理では同じdomainオブジェクトが現domainとして取れます。なのでこのdomainオブジェクトにピギーバックしてThread localと同じような仕組みを実現できます。

コンポーネント

実装ですが、大きく4つのコンポーネントで構成しました。

domainをリクエスト毎に作成
- 本来のエラーハンドリングにも使いましょう
リクエスト毎のdomainを使ってrequest-localな値を保管する仕組み
- 色々使えそうですが、ミッションクリティカルなロジックは依存しない方がよいでしょう
リクエストIDを取得/発行、request-localに管理する仕組み
- リクエストIDはログ以外でも使えます
ロガーでrequest-localのリクエストIDをログに出力

domainをリクエスト毎に作成

基本的にはミドルウェアスタックの一番最初の方でdomainを作り、そのdomain内でそれ以降のミドルウェアを実行させることになります。

app.use(function(req, res, next) {
    let d = domain.create();
    d.add(req);
    d.add(res);
    d.run(next);
});

実際にはnode-domain-middlewareを使うのが便利です。

なお、domainは基本的にはエラー処理のための仕組みです。以下の記事がよくまとまっていて参考になります。

http://qiita.com/naomichi-y/items/ad6c39fecb961913e573

なお、エラーを拾った場合、アプリケーションが正しい状態にない可能性が高いので、そのまま次のリクエストを受け付けたりするのは止めましょう（という警告がdomainのドキュメントに書かれているので、エラーハンドリングを実装する場合には気をつけましょう）。

リクエスト局所記憶

だいたい以下の様なmoduleですね。
domain.activeにSymbolをキーにしてMapオブジェクトを突っ込んでおります。

const domain = require('domain');
const PAYLOAD_KEY = Symbol("Payload for request-local-storage");


module.exports.middleware = function() {
    return function(req, res, next) {
        let currentDomain = domain.active;
        if (currentDomain == null) {
            return next(new Error('Domain for the request must be setup.'));
        }
        currentDomain[PAYLOAD_KEY] = new Map();
        next();
    };
};

module.exports.getCurrentStorage = function() {
    let currentDomain = domain.active;
    if (currentDomain == null) {
        return undefined
    }
    return currentDomain[PAYLOAD_KEY]
};

module.exports.get = function(key) {
    let currentStorage = this.getCurrentStorage();
    if (currentStorage == null) {
        return undefined
    }
    return currentStorage.get(key);
};

module.exports.set = function(key, value) {
    let currentStorage = this.getCurrentStorage();
    if (currentStorage == null) {
        return undefined
    }
    return currentStorage.set(key, value);
};

使い方

例のごとくミドルウェアでフックします。

app.use(requestLocalStorage.middleware());

あとはどこからでもrequestLocalStorage.set(key, value)とかrequestLocalStorage.get(key)すると、リクエスト毎の値の出し入れができます。

リクエストIDの取得・発行、値の記憶

だいたい以下の様なmoduleですね。

const secureRandom = require('secure-random');
const requestLocalStorage = require('./request-local-storage');


function generateRequestId() {
    // like nginx
    return secureRandom.randomBuffer(16).toString('hex')
}

module.exports.middleware = function() {
    return function(req, res, next) {
        let requestId;
        if (req.header('X-Request-Id')) {
            requestId = req.header('X-Request-Id');
        } else {
            requestId = generateRequestId();
        }
        requestLocalStorage.set('requestId', requestId);
        next();
    }
};

module.exports.get = function() {
    return requestLocalStorage.get('requestId');
};

使い方

例のごとくミドルウェアでフックします。

app.use(requestId.middleware());

あとはどこからでもrequestId.get()すると、現在の処理をトリガしたリクエストのIDがもらえます。

log4js

さて、最後にlog4jsですが、appender定義の際にpatternレイアウトを使ってtokensにrequestIdを定義して出力に含めます。パターンは用途に合わせて調整します。

const log4js = require('log4js');
const requestId = require('./request-id');

log4js.configure({
    appenders: [{
        type: "console",
        layout: {
            type: "pattern",
            pattern: "%[[%d{ISO8601}] [%x{requestId}] %-5p %c -%] %m",
            tokens: {
                requestId: () => requestId.get()
            }
        }
    }]
});

まとめ

こんな感じ。

const express = require('express');
const log4js = require('log4js');
const nodeDomainMiddleware = require('node-domain-middleware');
const requestLocalStorage = require('./request-local-storage');
const requestId = require('./request-id');

log4js.configure({
    appenders: [{
        type: "console",
        layout: {
            type: "pattern",
            pattern: "%[[%d{ISO8601}] [%x{requestId}] %-5p %c -%] %m",
            tokens: {
                requestId: () => requestId.get()
            }
        }
    }]
});

let app = express();
app.use(nodeDomainMiddleware);
app.use(requestLocalStorage.middleware());
app.use(requestId.middleware());

結論

Railsでは当たり前のことを実装するのにだいぶ苦労しました。
Node.jsは、まだまだ非同期処理が色々と面倒ですが、体感できるくらい処理が速いことも多いです。

とはいえ早くRubyに戻りたいw（記事を読んで下さっている皆様からは怒られそうな結びですが）

追記（2019/11/27）

私自身はNode.jsから離れてしばらく経ちましたが、当記事を参照してくださっている記事が追加されましたので、追記しておきます。

Node.jsでのリクエストIDのログ出力

裏で使っている仕組みは同じみたいですが、domainを扱うあたりでrequest-contextというnpmが使えるそうです。

Node.jsでログにRequestIdを入れる

前提