🚀

スタートアップでのO11yの第一歩：NestJSでの構造化ログ実装

gamonges

2025/04/03に公開

はじめに

この前久しぶりにSRE系のイベントに参加して、SREの匂いを懐かしんできました。
というわけでSREっぽいアウトプットしようかと。

弊社ではまだ正式ローンチ前の段階ですが、初期の段階からObservability（011y）を高める取り組みをしていて
その初手として

監視ツールの導入
構造化ログ
APMの導入
の３つを進めています。

ローンチ前にO11y、いる？

初期の段階でObservabilityが必要かどうかは意見が分かれるかもしれませんが
弊社では正式ローンチ前から推し進める決定をしています。

スタートアップのプロダクトで必要なことは、なるべく早くユーザーに価値を届けることです。
価値を届ける上でプロダクトで一番重要なことは「動くこと」です。
早さを優先しすぎた結果、価値をデリバリーできないことは
作りたてのサービスを利用してくれているユーザーを裏切ってしまうことになりかねません。

そうならないように、初期の段階からプロダクトの状態を把握しておく必要があります。
そのために011yを高めて、十分に価値を届けられている状態かシステム観点で計測できるようにしていこうと思っています。

本記事では、まず構造化ログをどう実装していったか書いていきます。

構造化ログの構造・インターフェイス定義

弊社のバックエンドAPIはNestJSで作られていて
ウェブ経由からのアクセスと、SQS経由のイベント処理の２つにコンテキストが大きく分かれています。
そのため、各コンテキストごとに最適なログ構造をインターフェイスで明確に定義しています。

ウェブ経由のアクセスログ

ウェブ経由のアクセスログは、リクエスト開始時（ApiStart）と終了時（ApiFinish）の詳細を別々に記録します。

export interface ApiLog {
    method: string;
    path: string;
    endpointUrl: string;
    callerIp?: string;
    callerUserAgent?: string;
    callerReferer?: string;
    callerHost?: string;
  }

  export interface ApiStart {
    requestBody?: object;
    queryParams?: object;
  }

  export interface ApiFinish {
    statusCode: number;
    durationMs: number;
    requestBody?: object;
    queryParams?: object;
    responseBody?: object;
    error?: ErrorLog;
  }

SQSイベント処理のログ構造

SQS経由の処理についても、開始時（SqsStart）と終了時（SqsFinish）のログを別々に取ることで、処理の流れやパフォーマンスを詳しく把握できるようにします。

  export interface SqsLog {
    messageId: string;
    queueName: string;
    messageType: string;
  }

  export interface SqsStart {
    messageParams?: object;
    messageOptions?: SqsMessageOptions;
  }

  export interface SqsFinish {
    durationMs: number;
    error?: ErrorLog;
  }

構造化する上で大事にした意識

ログ定義の際に意識したのは、以下のような5W1Hを明確に表現することです。

誰が（どのユーザーか、イベント元）
何を（対象のエンドポイント、イベント内容）
いつ（タイムスタンプ）
どこで（エラー発生箇所）
なぜ（エラー原因）
どうやって（処理内容、リクエストボディ）

構造化ログのメリットとして以下が挙げられると思っています。

検索と分析のしやすさ
- 構造化されることで、ログの特定のプロパティごとに検索やフィルタリング、可視化がしやすい状態になる
一貫性
- 構造を定義することでログ形式を統一することができ、ログ管理がしやすくなる
ツールとの統合
- 監視SaaSツールには構造化ログの検索や可視化をしやすいものが多いので、ツールの恩恵を受けやすい
  構造化の先には検索、分析があり、その先にはデバッグやパフォーマンス最適化があります。

今回の構造化で全てを網羅できているわけではないですが、改善のサイクルを回していくための初手は打てたんじゃないかなと思ってます。

インターフェイス実装例全体

logger.type.ts

  export const LogLevel = {
    fatal: 'fatal',
    error: 'error',
    warn: 'warn',
    info: 'info',
    debug: 'debug',
    verbose: 'verbose',
  } as const;
  export type LogLevel = EnumUnion<typeof LogLevel>;

  export interface SqsLog {
    messageId: string;
    queueName: string;
    messageType: string;
  }

  export interface SqsStart {
    messageParams?: object;
    messageOptions?: SqsMessageOptions;
  }

  export interface SqsFinish {
    durationMs: number;
    error?: ErrorLog;
  }

  export interface ApiLog {
    method: string;
    path: string;
    endpointUrl: string;
    callerIp?: string;
    callerUserAgent?: string;
    callerReferer?: string;
    callerHost?: string;
  }

  export interface ApiStart {
    requestBody?: object;
    queryParams?: object;
  }

  export interface ApiFinish {
    statusCode: number;
    durationMs: number;
    requestBody?: object;
    queryParams?: object;
    responseBody?: object;
    error?: ErrorLog;
  }

  export interface ApiLogContext {
    statusCode: number;
    endpointUrl: string;
    callerIp?: string;
    callerUserAgent?: string;
    callerReferer?: string;
    callerHost?: string;
  }

  export type ErrorLog =
    | {
        topLevelMessage: string;
        stack?: string;
      }
    | unknown;
}

NestJSでの実装例

ロガーのライブラリにはPinoを採用しました。
もともと使用していたWinstonから変更したのもあり、
将来的なロガー変更にも対応できるように、ロガーの抽象化をしています。

myservice-logger.ts
export abstract class MyServiceLogger {
  protected config: ConfigService;
  protected logContext?: string;
  protected logIcon?: string;

  constructor(config: ConfigService) {
    this.config = config;
  }

  protected abstract write(message: string, meta: any): void;

  public setContext(context: string, icon?: string) {
    this.logContext = context;
    this.logIcon = icon || '';
    return this;
  }

  abstract info(message: string, meta?: any): void;
  abstract fatal(message: string, meta?: any): void;
  abstract error(message: string, meta?: any): void;
  abstract warn(message: string, meta?: any): void;
  abstract debug(message: string, meta?: any): void;
  abstract verbose(message: string, meta?: any): void;

  /** SQS イベント処理開始のログを記録します。 */
  abstract logSqsStart(meta: LoggerTypes.SqsLog & LoggerTypes.SqsStart): void;
  /** SQS イベント処理終了のログを記録します。 */
  abstract logSqsFinish(meta: LoggerTypes.SqsLog & LoggerTypes.SqsFinish): void;

  /** APIリクエストのログを記録します。 */
  abstract logApiStart(meta: LoggerTypes.ApiLog & LoggerTypes.ApiStart): void;
  /** APIレスポンスのログを記録します。 */
  abstract logApiFinish(meta: LoggerTypes.ApiLog & LoggerTypes.ApiFinish): void;
}

これにより、ロガーの差し替えやフォーマット変更時に発生する影響を局所化し、コード変更を最小限に抑えられるようにしています。

こちらの実装部分が以下

public logSqsStart(meta: LoggerTypes.SqsLog & LoggerTypes.SqsStart) {
    this.debug(`SQS Process Start`, meta);
  }

  public logSqsFinish(meta: LoggerTypes.SqsLog & LoggerTypes.SqsFinish) {
    if (meta.error) {
      this.error(`SQS Process Finish`, meta);
    } else {
      this.info(`SQS Process Finish`, meta);
    }
  }

  public logApiStart(meta: LoggerTypes.ApiLog & LoggerTypes.ApiStart) {
    this.debug(`API Process Start`, meta);
  }
  public logApiFinish(meta: LoggerTypes.ApiLog & LoggerTypes.ApiFinish) {
    if (meta.error) {
      const processedError = this.createFormattedErrorData(meta.error);

      const processedMeta = {
        ...meta,
        error: processedError,
      };
      this.error(`API Process Finish with Error`, processedMeta);
    } else {
      const processedResponseBody = this.includeRequestBody
        ? meta.responseBody
        : undefined;

      this.info(`API Process Finish`, {
        ...meta,
        responseBody: processedResponseBody,
      });
    }
  }

こんな感じでログ出力用のメソッド内で、
必要なデータが入り適切なログレベルで出力されるように実装しています。

ロガー実装全体

Pino-logger.ts
...
@Injectable({ scope: Scope.REQUEST })
export class PinoLogger extends MyServiceLogger {
  private readonly logger: Logger;
  private readonly logFormatType: LoggerTypes.LogFormatType;
  private readonly logLevel: LoggerTypes.LogLevel;
  private readonly includeRequestBody: boolean;
  private readonly contextId?: string;

  private apiLogMeta: Partial<LoggerTypes.ApiLog & LoggerTypes.ApiStart>;

  constructor(
    config: ConfigService,
    private readonly context: LoggerContext = new LoggerContext()
  ) {
    super(config);
    ...
  }

  static withNoContext() {
    return new PinoLogger(new ConfigService());
  }

  private setBasicMeta() {
    const basicMeta = {
      organizationId: this.context.organizationId,
      dresscodeUserId: this.context.dresscodeUserId,
    };
    return basicMeta;
  }

  public setApiLogMeta(
    meta: Partial<LoggerTypes.ApiLog & LoggerTypes.ApiStart>
  ) {
    this.apiLogMeta = meta;
  }

  /** ログフォーマットに基づいて Pino ロガーインスタンスを作成します。 */
  public createLoggerInstance(): Logger {
    const loggerOptions = this.getLogFormat(this.logFormatType);
    return pino(loggerOptions);
  }

  /** 指定するフォーマットによって出力形式を変えています */
  private getLogFormat(logFormat: LoggerTypes.LogFormatType): LoggerOptions {
    switch (logFormat) {
      case 'json':
        return this.getJsonFormat();
      case 'local':
        return this.getLocalFormat();
      case 'both':
        throw new NotImplementedException(
          'logFormat: "both" is not implemented'
        );
    }
  }

  private getJsonFormat(): LoggerOptions {
    return {
      level: this.logLevel,
      customLevels: {
        verbose: 100,
      },
      formatters: {
        level: (label: string) => {
          return { level: label };
        },
        //        log: (obj) => this.maskSensitiveData(obj),
      },
      timestamp: () => {
        return `,"time":"${new Date().toISOString()}"`;
      },
      mixin: () => {
        const dresscodeLogMeta = {
          contextId: this.contextId,
          loggerContext: this.logContext || 'unknown',
        };

        return { ...dresscodeLogMeta, ...(this.apiLogMeta || {}) };
      },
    };
  }

  /**
   * ローカル環境用のログフォーマットを指定するメソッド
   * @example
   * INFO [2025-02-13 10:34:18]: 💬{context:SampleController(hello)} - method:GET - path:/v2/sample/hello - message:API Process Finish
   * ERROR [2025-02-13 10:34:49]: 🚨{context:SampleController(error)} - method:GET - path:/v2/sample/error - message:API Process Finish
   */
  private getLocalFormat(): LoggerOptions {
    return {
      level: this.logLevel,
      customLevels: {
        verbose: 100,
      },
      formatters: {
        level: (label: string) => {
          return { level: label };
        },
      },
      timestamp: () => {
        return `,"time":"${new Date().toISOString()}"`;
      },
      mixin: () => {
        const dresscodeLogMeta = {
          contextId: this.contextId,
          loggerContext: this.logContext || 'unknown',
        };

        return { ...dresscodeLogMeta, ...(this.apiLogMeta || {}) };
      },
      transport: {
        target: 'pino-pretty',
        options: {
          singleLine: true,
          colorize: true,
          messageFormat: '{msg}',
        },
      },
    };
  }

  private formatErrorStack(stack: string | string[] | undefined) {
    if (stack == null) return stack;
    if (typeof stack === 'string') {
      const remainingLines = stack
        .split('\n')
        .slice(1)
        .map((line) => `    ${line}`)
        .join('\n');
      return `🔴 発生エラー: ${stack.split('\n')[0]}\n${remainingLines}`;
    }

    const formattedStack = stack.map((s, index) => {
      const prefix =
        index === 0 ? '🔴 発生エラー: ' : `🔹 原因エラー(${index}): `;

      // スタックトレースの先頭行（エラーメッセージ部分）を抽出
      const firstLine = s.split('\n')[0];

      // スタックトレースの残りの部分をインデント
      const remainingLines = s
        .split('\n')
        .slice(1)
        .map((line) => `    ${line}`)
        .join('\n');

      return `${prefix}${firstLine}\n${remainingLines}`;
    });

    return formattedStack.join('\n');
  }

  /**
   * エラーオブジェクトをログ出力用にフォーマットされたエラーデータに変換します
   * @param error 変換対象のエラーオブジェクト
   * @returns フォーマット済みのエラーデータ
   */

  private createFormattedErrorData(error: unknown): LoggerTypes.ErrorLog {
    if (error instanceof Error) {
      /**
      * cause プロパティによってネストしたエラーの全ての stack を抽出し、
      * 外側のエラーから順に並べて返す。
      */
      const stack = extractNestedStacks(error);
      return {
        topLevelMessage: error.message,
        stack: this.formatErrorStack(stack),
      };
    }
    return error;
  }

  protected write(level: LoggerTypes.LogLevel, message: string, meta?: any) {
    const baseMeta = {
      ...this.setBasicMeta(),
      level: level,
      loggerContext: this.logContext || 'unknown',
      ...(this.logFormatType === 'local'
        ? { levelIcon: LoggerTypes.LOG_LEVEL_ICONS[level] }
        : {}),
    };
    const pinoLogLevel = match(level)
      .with('verbose', () => 'verbose')
      .with('debug', () => 'debug')
      .with('info', () => 'info')
      .with('warn', () => 'warn')
      .with('error', () => 'error')
      .with('fatal', () => 'fatal')
      .otherwise(() => 'info');

    const finalMeta = { ...baseMeta, ...meta };

    if (typeof this.logger[pinoLogLevel] === 'function') {
      this.logger[pinoLogLevel](finalMeta, message);
    } else {
      this.logger.info(finalMeta, message);
    }
  }

  public info(message: string, meta?: any) {
    return this.write(LoggerTypes.LogLevel.info, message, meta);
  }

  public fatal(message: string, meta?: any) {
    return this.write(LoggerTypes.LogLevel.fatal, message, meta);
  }

  public error(message: string, meta?: any) {
    return this.write(LoggerTypes.LogLevel.error, message, meta);
  }

  public warn(message: string, meta?: any) {
    return this.write(LoggerTypes.LogLevel.warn, message, meta);
  }

  public debug(message: string, meta?: any) {
    return this.write(LoggerTypes.LogLevel.debug, message, meta);
  }

  public verbose(message: string, meta?: any) {
    return this.write(LoggerTypes.LogLevel.verbose, message, meta);
  }

  public logSqsStart(meta: LoggerTypes.SqsLog & LoggerTypes.SqsStart) {
    this.debug(`SQS Process Start`, meta);
  }

  public logSqsFinish(meta: LoggerTypes.SqsLog & LoggerTypes.SqsFinish) {
    if (meta.error) {
      this.error(`SQS Process Finish`, meta);
    } else {
      this.info(`SQS Process Finish`, meta);
    }
  }

  public logApiStart(meta: LoggerTypes.ApiLog & LoggerTypes.ApiStart) {
    this.debug(`API Process Start`, meta);
  }
  public logApiFinish(meta: LoggerTypes.ApiLog & LoggerTypes.ApiFinish) {
    if (meta.error) {
      const processedError = this.createFormattedErrorData(meta.error);

      const processedMeta = {
        ...meta,
        error: processedError,
      };
      this.error(`API Process Finish with Error`, processedMeta);
    } else {
      const processedResponseBody = this.includeRequestBody
        ? meta.responseBody
        : undefined;

      this.info(`API Process Finish`, {
        ...meta,
        responseBody: processedResponseBody,
      });
    }
  }
}

NestJSでのロガーDI注入

今回、ロガーの抽象化を挟んでいるため
NestJSのDIではPinoによって実装されたロガーではなく、抽象化されたMyServiceLoggerの方を
注入していくことになります。

普通に実装するとこんな感じ

export declare const LOGGER = "LOGGER"

@Module({
  imports: [ApiContextModule, SqsContextModule],
  providers: [
    PinoLogger,
    LoggerContext,
    {
      provide: LOGGER,
      useClass: PinoLogger,
    },
  ],
})
export class LoggerModule {}

ただこの書き方だと、LOGGER（MyServiceLogger）という目印、抽象に対してPinoLoggerが具象、実装として合っているかが担保できていません。
せっかくTypeScriptで書いているのでこちらの記事を参考に
型安全な実装をしています。

logger.module.ts
export const provideClass = <
  T extends abstract new (...args: any) => any,
  U extends new (...args: any) => InstanceType<T>,
>(
  abstractClass: T,
  useClass: U
): ClassProvider => ({
  provide: abstractClass,
  useClass,
});

@Module({
  imports: [ApiContextModule, SqsContextModule],
  providers: [
    PinoLogger,
    LoggerContext,
    provideClass(MyServiceLogger, PinoLogger),
  ],
  exports: [MyServiceLogger],
})
export class LoggerModule {}

まとめ

そんなわけでNestJSとPinoでの構造化ログ実装の例を紹介させてもらいました。
実装後はネストしたエラースタックの確認や、特定ユーザーやコンテキストのログ検索に役立っています。

今回はログに関する紹介だけになりましたが
引き続きトレースによるテレメトリの拡充をして、各種SLI/SLOの定義を行いログに頼りすぎないアラート設計をするなど
Observabilityを高めていく取り組みをしていく予定です。
このはじめの一歩が我々にとって大きな一歩になるように💪

スタートアップの環境で、グローバル展開を目指しているプロダクトの信頼性に興味がある方は
ぜひお話ししましょう！

DRESS CODE TECH BLOGPublication

DRESS CODEのProduct & Technologyチームによるテックブログです！プロダクトマネジメントからモデリング、アーキテクチャ、フロントエンド、バックエンド、SRE、セキュリティなどなど様々なテーマで情報を発信しています！

Discussion

ログインするとコメントできます