ログトレースによる生産上の頭痛の種の最小化

シーンを設定しよう：

プロダクションでクリティカル・インシデントが発生しました。それは あなたである。あなたは100の異なるサービスのログを調査し、完全に迷子になった。どのアクションがどの反応を引き起こしたのか？エラーはこのAPIコールに関係しているのか、それとも別のAPIコールに関係しているのか？私たちは皆、そのような経験をしたことがある。そして私たちは皆、それが楽しいものではないことに同意するだろう。

しかし がある。解決策がある。プロダクションの問題をすべて解決するわけではないが、非常に役立つソリューションだ。そして朗報は、それがあなたのサービスに簡単に統合できるということだ。

ログのトレース。

簡単そうに聞こえるだろう？しかし実際には、それはほとんどあらゆる種類の調査のための強力なツールになり得る。というのも、今日のモダンなアーキテクチャでは、ユーザーがサイトのボタンを1つ押すと、APIゲートウェイ、ビジネスサービス、データベース、別のサービス、集中型メッセージバス、別のサービスなどにAPIリクエストが発行されるからだ。

何十万人ものユーザーによって1秒間に何百回も起こるあらゆるフローによって生成される何百ものログが氾濫する圧倒的な旅なのだ。 ふぅー。

ログトレースとはどういう意味ですか？

これらのコンセプトの実装に入る前に、ログをトレースするという意味を理解しよう。トレースとは通常、データを集計するために使用できる識別子を追加することを意味する。それぞれのIDの意味は、好みの問題である。一つのリクエストの全てのデータに追加される一つのトレースIDを持つこともできます。あるいは、1つのサービスのコンテキストで使用される一連のスパンIDを持つこともできます。基本的な考え方は以下の通りです：

basic log tracing flow

理解すべき重要な概念が2つある：

1. トレースによって各リクエストの全サービスのログを集約する

2. ビジネス・ロジックの邪魔にならないよう、トレースはインフラに任せる。

では、どうやってそれを実行するのか？

各リクエストのログを集計

このコンセプトはとても簡単だ。非常にシンプルな2つのルールに従う必要がある：

• リクエストに対して書くログにトレース ID を追加し、IO 操作をするたびにトレース ID を渡す。

• つのサービスがメッセージバスを介して同じリクエストで通信する場合、バスに追加されたメッセージにトレースIDを追加します。二つのサービスが http リクエストで通信する場合、リクエストのヘッダーにトレース ID を追加します。こうすることで、並行して発生する他のリクエストやログのノイズなしに、 一つのリクエストのフロー全体を追うことができます。

ビジネスロジックとインフラの分離

送受信されたデータをすべて追跡できるようにするには、かなりの量のコーディングが必要になります。このようなインフラストラクチャーのコンセプトは、できる限りビジネス・ロジックから切り離したいものです。幸運なことに、私たちのケースでは、トレース管理をほぼ完全に分割することは簡単です。

我々のコードでは、様々なイベントやエラーに対してログを書き、そのログにデータを追加している。トレースをすべてのログに並行して追加しながら、これらのフローを変更しないようにしたい。今日我々が使っているツールのほとんどは、受け取ったリクエストにインターセプターを追加することができる。IOツールとロギングツールにインターセプターを追加するようにすれば、既存のコードに触れることなく、すべてのログを確実にトレースできるようになります。

最も簡単に説明する方法は、私たちのサービスでの実例を示すことだ。

このコードは、httpリクエストを受信し、いくつかのログを書き、次のサービスにhttpリクエストを行うnodejsサービスのものである。これはインターセプターを配置した3つの場所のうちの1つである：インバウンドリクエスト、ロギング、アウトバウンドリクエスト。

function tracingMiddleware(req,res,next) {
    ns.run(() => {
        let traceId = req.headers['x-b3-traceid'];
        let spanId = req.headers['x-b3-spanid'];
        if (!traceId || !spanId) {
            traceId = uuid().replace(/-/g, '');
            spanId = uuid().replace(/-/g, '').substring(16);
        }
        ns.set('traceId', traceId);
        ns.set('spanId', spanId);
        next();
    });
}

私たちはExpressをAPIインフラとして使用し、expressを実装しています。 ミドルウェアを実装している。リクエストからトレースIDを抽出するか、あるいはチェーン内の最初のサービスであれば新しいトレースIDを作成する。そして、セッション・ストレージ・ツールにトレースIDをセットし、すべてのステップでトレースIDを取得できるようにする。

に注目してほしい。 ns.set.これは cls-hookedこれはノードの非同期フックをラップする継続ローカルストレージパッケージである。これによって、各セッションのトレースIDをローカルに保存することができます。しかし、もしあなたが Node 14 を使っているなら、この機能はすでに 非同期ローカルストレージ.しかし、この方法がクールなのは、どの言語でも実装できることです。

次に、セッションストレージからトレースIDを取得し、すべてのログ行に追加するインターセプターをロギングツールに追加する：

function createBunyanStreamMiddleware(streams) {
    return {
        type: 'raw',
        level: process.env.LOG_LEVEL,
        stream: {
            write: (entry) => {
                if(ns && ns.active) {
                    entry['traceId'] = ns.get('traceId');
                    entry['spanId'] = ns.get('spanId');
                }
                streams.forEach((stream) => {
                        stream.stream.write(entry)
                });
            }
        }
    }
}

最後に、httpツールにインターセプターを追加し、リクエストが発射される前に、リクエストヘッダーにトレースIDを追加する：

function insertTracingHeaders(config = {}){
    if(ns && ns.active) {
        const traceId = ns.get('traceId');
        const spanId = ns.get('spanId');
        if (!config.headers) {
            config.headers = {};
        }
        if (traceId && spanId) {
            config.headers['x-b3-parentspanid'] = spanId;
            config.headers['x-b3-traceid'] = traceId;
        }
    }
    return config;
}

全体の流れは次のようになる：

tracing flow with interceptors

結論として

ログトレースはいろいろな場面で使われますが、この特別な使い方をすることで、 エラーを調査するときの頭痛の種をかなり防ぐことができます。各フローのリクエストログに簡単にアクセスできるので、 何千もの無関係なログを調べる必要がなくなります。

私たちは個人的に、これらのコンセプトを適用したサービスにおいて、ログ調査の効率と価値が急上昇したと断言できます。それ以来、他の方法でログをふるいにかけても、しっくりこないのです。

次回、本番で重大なインシデントが発生し、それを解決するのはあなた次第だが、少なくとも今回はログがあなたの味方になってくれるだろう。