マイクロサービスにおけるログ出力に役立つNode.jsのAsyncLocalStorage

はじめに

こんにちは、テックリードのかどたみです。 弊社では以前の記事でも紹介したとおりマイクロサービス開発にNestJSを利用しています。今回はNestJSでマイクロサービス開発をする際のログの出力についてご紹介します。

この記事はエモーションテック Advent Calendar 2022の6日目の記事です。

背景

マイクロサービスのメリットの一つとして、サービスごとに開発するドメインの範囲を狭め、機能追加や改修の影響範囲を最小限にできることが挙げられます。

しかし、いざ運用しようとするとユーザーからのアクセス一つにおいて複数のサービスで処理が走ることから、どのサービスで障害になっているのか、どのユーザーがどこまでアクセスできているのかなどバグ発生時の原因や影響範囲の特定に時間がかかることもあります。

そこで、マイクロサービス間でログに出力する内容を揃えることで分析をしやすくなるようにベストプラクティスを参考にガイドラインを定めました。 このガイドラインに沿ったログを出力する上でNestJSにおいてAsyncLocalStorageを用いて工夫した点を紹介できればと思います。

ログ構造の統一

ではまず、ログの構造をどのようなものにするかですが、我々のサービスではJSON形式でログを出力しています。検索性能も高いですし、様々なサービスもJSONの解析をサポートしてくれているので迷う余地はありませんでした。

続いて内容ですが、ベストプラクティスに則り、以下のような内容を出力しています。

• ログレベルや出力時間、ステータスコードといった基本情報
• フロントエンドからのリクエストで一意になるID
• 各マイクロサービスが受け取るリクエストで一意になるID(execution_id)
• 実行ユーザーの情報
• 実行開始時刻

ログレベルや出力時間などの基本的な情報は一般的なログライブラリやフレームワーク自身が出力するのをサポートしてくれていますが、それ以外のデータは自分でコードを書かなければ出力できません。 愚直にpresentation層に渡されてくるリクエスト情報から必要な情報を引数で渡すのも1案ですが、なかなか面倒です。そこで今回はNode.jsのAsyncLocalStorageという仕組みを利用しました。

AsyncLocalStorage

AsyncLocalStorageは「非同期操作を通じて一貫性を保ち、パフォーマンスが高くメモリセーフなストレージを作成できる」機能です。AsyncLocalStorageを利用することでリクエストごとに利用できるストレージを生成でき、ログに出力したいデータを格納しておくことによってログの要件を簡単に実現することができます。

実際のコード

まずは、AsyncLocalStorageを用いたストアを管理するクラスを作成します。

import { AsyncLocalStorage } from 'async_hooks';
import { Request, Response } from 'express';
import { ulid } from 'ulid';

export class RequestContextStorage {
  static storage = new AsyncLocalStorage<RequestContextStorage>();
  executionId: string;
  startedAt: Date;

  static get currentContext(): any {
    return this.storage.getStore();
  }

  // request情報とresponse情報も格納しておけば様々なデータをログに記録できる
  constructor(public readonly req: Request, public readonly res: Response) {
    // ここでログに利用したいデータを作成
    this.executionId = ulid();
    this.startedAt = new Date();
  }
}

続いてミドルウェアを用いて、リクエストごとにストレージを作成します。runメソッドを用いると第一引数に指定したオブジェクトはコールバック関数外からアクセスできなくなるため、リクエストごとに安全な領域が確保できます。

import { Injectable, NestMiddleware } from '@nestjs/common';
import { NextFunction, Request, Response } from 'express';
import { RequestContextStorage } from 'path/to/request-context.storage';

@Injectable()
export class RequestContextMiddleware implements NestMiddleware {
  use(req: Request, res: Response, next: NextFunction): void {
    RequestContextStorage.storage.run(
    new RequestContextStorage(req, res),
    async () => {
        next();
    },
    );
  }
}

これで準備は完了です。

使い方

では実際に使ってみましょう。使い方は簡単です。RequestContextStorage.currentContextを呼び出すだけで中身にアクセスできます。

import { LoggerService } from '@nestjs/common';
import { RequestContextStorage } from 'path/to/request-context.storage';

export class CustomApiLogger implements LoggerService {
  constructor(private execute_class?: string) {}

  log(message: string, logInfo: LogInfo = {}): void {
    console.log(this.createLog('info', message));
  }
 
  // errorやdebugなどは省略
 
  private createLog(level: string, message: string): string {
    // リクエストごとの情報にアクセス
    let log {
    level: level,
    time: new Date(),
    msg: message,
    // リクエストごとの情報にアクセス
    execution_id: RequestContextStorage.currentContext?.executionId,
    started_at: RequestContextStorage.currentContext?.startedAt,
    };
    return JSON.stringify(log);
  }
}

これによってLogger.log('hoge')と呼び出すだけでjsonログの中にリクエストごとに一意な値とリクエストの開始時刻を含めることができます。

おわりに

いかがでしたでしょうか？ マイクロサービスは開発面で大きなメリットを享受することができますが、運用では面倒事が増える場面も多いです。少しでも調査や保守に用いるログを有用なものにするための取り組みは大変重要だと思います。まだ弊社でも取り組みが始まったばかりですが、運用保守に少しでも貢献できるような仕組みを導入していきたいですね。

エモーションテックでは顧客体験、従業員体験の改善をサポートし、世の中の体験を変えるプロダクトを開発しています。プロダクトに興味のある方、マイクロサービスの運用保守を追求していきたい方、ぜひ採用ページからご応募をお願いいたします。

hrmos.co

hrmos.co