decoratorを使ってログ出力コードの削減し可読性を上げた話

この記事では TypeScript ver4.x にて実験的な機能である decorator を使い、ログ出力コードを削減・コードの可読性を上げた経験を紹介します。

はじめに

こんにちは、NeWork 開発チームの加藤です。普段はオンラインワークスペースサービス NeWork の開発エンジニアをしています。

今回は TypeScript ver4.x にて実験的な機能である decorator を使った事例紹介をします。我々開発チームではログ出力のためのロジックの記述がコード全体の可読性を下げているという課題があり、decorator を活用することでこの課題を解決しました。その経験をもとに、良かった点・悪かった点(苦労した点)含めて紹介したいと思います。

背景

NeWork 開発チームでは、TypeScript を用いて開発しています。その中で開発中のコードの挙動を確認したり、エラー発生の監視その後の原因特定のために、ログ出力を行っています。

ログ出力は router, service, gateway などの各レイヤーで行っており、それぞれのレイヤーでログ出力を行うために以下のようなコードを書いていました。（※コードはサンプルです）

const async getUser = (userId:string): Promise<MyUser> => {

  // 呼び出しログ表示ロジック
  Logger.getInstance().info(
    `getUser start: userId ${userId}`, // ログメッセージ
    LOG_POSITION.SERVICE, // ログ出力レイヤー(レイヤーごとに定数を用意しています)
    LOG_PADDING.START, // 開始/終了のログを判別するための定数
    );

  const outEndLog = () =>
    // 終了ログ表示ロジック
    Logger.getInstance().info(
      'getUser end',
      LOG_POSITION.SERVICE,
      LOG_PADDING.END,
      );

  // 処理
  const user = await MyGateway.getUserData(userId).catch(() => {
    outEndLog();  // 終了ログ表示ロジックの呼び出し
    throw new MyError();
  });

  outEndLog();  // 終了ログ表示ロジックの呼び出し
  return user;
}

このコードでは以下のような問題がありました。

• エラーが発生するタイミングや、early return するタイミングでログ出力をしなければならないため、記述忘れが発生しやすい。
• 簡単な関数であっても、ログ出力のための記述が多くなり、可読性が下がっている。
• 開発者がログ出力のためのコードを書くのが面倒。
• 関数を作成するたびにログ出力を記述するので、人によってログメッセージの記述がバラついてしまうことがあった。(get user start と getUser start など)

エラー発生時のログ出力漏れの対策としては、try-finally を書くことがあげられますが、結局のところ毎回関数を記載するたびに try-finally を書くのは大変であり、他の問題にもアプローチ可能な decorator を使ってログ出力を試してみました。

decorator とは

TypeScript ver4.x の decorator は関数などに対して処理を追加する記述方法で、以下の 5 種類があります。

• Class Decorators
• Method Decorators
• Accessor Decorators
• Property Decorators
• Parameter Decorators

それぞれ、クラス・メソッド・アクセサ・プロパティ・パラメータに対して処理を追加可能です。

クラス・メソッド等の定義時に、decorator を@hogehoge という形式で記述することで、その decorator が適用されます。

decorator を利用することで、対象のクラスやメソッドに対して共通の処理を追加できます。

例えば method decorator の場合以下のように定義・利用します。

// decorator の定義
function logging(target: Object, propertyKey: string | symbol, descriptor: PropertyDescriptor) {
  const originalMethod = descriptor.value;
  // メソッドの処理を上書き
  descriptor.value = function (...args: unknown[]) {
    console.log('処理開始');
    // 元のメソッドを呼び出す
    originalMethod.apply(this, args);
    console.log('処理終了');
  }
}

class MyClass {
  // loggingというdecoratorをhelloメソッドに適用
  @logging
  hello() {
    console.log('hello');
  }
  // loggingというdecoratorをbyeメソッドに適用
  @logging
  bye() {
    console.log('bye');
  }
}

これにより、hello メソッドや bye メソッドの実行時には必ず処理開始 と処理終了 が出力されるようになります。

他の decorator の利用方法や具体例等は、公式に提示されていますので興味があればご覧ください。

今回は、メソッドに対して処理を追加するための Method Decorators を利用しました。

decorator を使ったログ出力方法の検討

Method Decorators にてログ出力を行うにあたり、以下の要件をもとに実装しました。

• decorator を適用したメソッドの開始・終了時には必ずログ出力が行われる。
• ログメッセージの形式を統一する。
• 非同期関数に対しても適用できるようにする。
• ログ出力の際には、必ずクラス名・メソッド名が出力されるようにする。

decorator を使ったログ出力の実装

NeWork の実際の実装では、以下のserviceLogging, gatewayLoggingという decorator を新規作成しました。

/**
 * @description ログ出力デコレーターファクトリーの共通処理部分,外部から呼び出す際はserviceLogging関数等を呼び出すこと
 * @param position ログ出力位置
 * @returns デコレーター
 */
function logging(position: string): MethodDecorator {
  return (
    target: Object,
    propertyKey: string | symbol,
    descriptor: PropertyDescriptor
  ) => {
    const originalMethod = descriptor.value;
    // ログ出力するクラス名を取得
    // static関数の場合はtype of targetがfunctionに、それ以外はobjectになる
    const isStatic = typeof target === "function";
    const className = isStatic ? target.name : target.constructor.name;

    // 関数呼び出し時のログ表示ロジック
    const startLog = () =>
      Logger.getInstance().info(
        `${className}.${String(propertyKey)} start.`,
        position,
        Constants.LOG_PADDING.START
      );

    // 関数終了時のログ表示ロジック
    const endLog = () =>
      Logger.getInstance().info(
        `${className}.${String(propertyKey)} end.`,
        position,
        Constants.LOG_PADDING.END
      );

    // async functionの場合、ログ出力前にawaitする
    const isAsync = descriptor.value.constructor.name === "AsyncFunction";
    if (isAsync) {
      descriptor.value = async function (...args: unknown[]) {
        startLog();
        // 仮引数の値もログ出力。ただし、オブジェクトの場合はログが煩雑になるので出力しない
        const argString = args
          .map((arg) => (typeof arg !== "object" ? util.format(arg) : "object"))
          .join(`, `);
        Logger.getInstance().debug(`args: ${argString}`);
        try {
          return await originalMethod.apply(this, args);
        } finally {
          endLog();
        }
      };
      return;
    }

    descriptor.value = function (...args: unknown[]) {
      startLog();
      // 仮引数の値もログ出力。ただし、オブジェクトの場合はログが煩雑になるので出力しない
      const argString = args
        .map((arg) => (typeof arg !== "object" ? util.format(arg) : "object"))
        .join(`, `);
      Logger.getInstance().debug(`args: ${argString}`);
      try {
        return originalMethod.apply(this, args);
      } finally {
        endLog();
      }
    };
  };
}
/**
 * @description サービスクラスのログ出力デコレーター
 * @param target クラス
 * @param propertyKey メソッド名
 * @param descriptor ディスクリプター
 * @returns なし
 */
export const serviceLogging = (
  target: Object,
  propertyKey: string | symbol,
  descriptor: PropertyDescriptor
): void => {
  // ログ出力位置をサービス用に指定して呼び出す
  logging(Constants.LOG_POSITION.SERVICES)(target, propertyKey, descriptor);
};

/**
 * @description ゲートウェイクラスのログ出力デコレーター
 * @param target クラス
 * @param propertyKey メソッド名
 * @param descriptor ディスクリプター
 * @returns なし
 */
export const gatewayLogging = (
  target: Object,
  propertyKey: string | symbol,
  descriptor: PropertyDescriptor
): void => {
  // ログ出力位置をゲートウェイ用に指定して呼び出す
  logging(Constants.LOG_POSITION.GATEWAYS)(target, propertyKey, descriptor);
};

上記で定義した decorator を使った実装例は以下です。ここでは背景の項目で記載した getUser 関数を例に書き換えています。

class MyService {
  @serviceLogging
  static async getUser(userId: string): Promise<MyUser> {
    const user = await MyGateway.getUserData(userId).catch(() => {
      throw new MyError();
    });
    return user;
  }

  @serviceLogging
  static async setUser(user: MyUser): Promise<void> {
    ・・・中略・・・
  }
}

このように記述することで getUser 関数の開始・終了時には必ずログが出力されるようになり、同じ定義を用いて各関数でログを出力できます。

実装時にハマったこと等

実装する際に困ったことや、想定外だったことを紹介します。

関数定義方法の変更

従来我々はアロー関数を利用し関数定義していたのですが、method decorator はアロー関数に対しては適用できず、関数定義を function で行うことで対応しました。

// 修正前
const async getUser = (userId:string): Promise<MyUser> => {
  ・・・中略・・・
}

// 修正後
async function getUser(userId:string): Promise<MyUser> {
  ・・・中略・・・
}

非同期・同期両方に対応

非同期関数かどうかによって、元の関数に対して await を行うかどうかや、descriptor.value に代入する関数を非同期にするかどうかを判定する必要がありました。

    // async functionの場合、ログ出力前にawaitする
    const isAsync = descriptor.value.constructor.name === "AsyncFunction";
    if (isAsync) {
      descriptor.value = async function (...args: unknown[]) {
        ・・・中略・・・
        try {
          return await originalMethod.apply(this, args);
        }
        ・・・中略・・・
      };
      return;
    }

    descriptor.value = function (...args: unknown[]) {
      ・・・中略・・・
      try {
        return originalMethod.apply(this, args);
      }
      ・・・中略・・・
    };

descriptor.value.constructor.name で関数の種類を判定しています。非同期関数の場合は AsyncFunction となります。

クラス名の取得

ログのメッセージにどのファイルの関数なのかを含めるために、関数のクラス化とクラス名を取得処理を追加しました。

各ファイルで定義していた関数を class でまとめ、default export するように修正し、既存の関数は class の static 関数として定義しました。

// 修正前
const async getUser = (userId:string): Promise<MyUser> => {
  ・・・中略・・・
}

// 修正後
class MyService {
  static async getUser(userId:string): Promise<MyUser> {
    ・・・中略・・・
  }
}

クラス名は static 関数の場合は target.name 、それ以外の場合は target.constructor.name から取得できます。

// ログ出力するクラス名を取得
// static関数の場合はtype of targetがfunctionに、それ以外はobjectになる
const isStatic = typeof target === "function";
const className = isStatic ? target.name : target.constructor.name;

ログメッセージの統一

ログメッセージについては、クラス名・メソッド名を必ず含めるようにしました。メソッド名は、propertyKey から取得できます。

Logger.getInstance().info(
        // クラス名.メソッド名 start.
        `${className}.${String(propertyKey)} start.`,
        position,
        Constants.LOG_PADDING.START
      );

また開始ログ出力後に、引数の値を出力するようにしました。

ただし引数がオブジェクトの場合は出力されるログが煩雑になるため、出力しないようにしました。もしログが必要な場合は decorator ではなく、関数内で個別にログ出力するなどの代替案で対応することとしました。

// 仮引数の値もログ出力。ただし、オブジェクトの場合はログが煩雑になるので出力しない
const argString = args
  .map((arg) => (typeof arg !== "object" ? util.format(arg) : "object"))
  .join(`, `);
Logger.getInstance().debug(`args: ${argString}`);

出来れば仮引数名も出力したいところですが、仮引数名を取得する方法が見つからなかったため、今回は実装を見送りました。

その他考慮した点

ライブラリの利用

decorator を直接利用するのではなく、logger-decorator というライブラリを利用することも検討しましたが、今回は我々独自のログ出力を行いたいため、ライブラリは利用しませんでした。

実践結果

実際に decorator を利用した結果、我々にとっての良かった点・悪かった点(苦労した点)は以下のようになりました。

良かった点

今回 decorator を適用したことで、元々の課題は解決できました。

• 関数のエラー発生時や、early return するタイミングでログ出力を意識する必要がなくなった。
• 関数の定義がシンプルになり、可読性が上がった。
• 開発者がログ出力のためのコードを書く必要がなくなった。
• ログメッセージの記述が統一された。

それだけではなく、副次的に以下のようなメリットもありました。

• ログの形式に、必ずクラス名が入るように修正したため、実際にログを見るときの可読性が上がった。
• 大きな破壊的変更をせずに適用できる方式であったため、開発速度を落とさずに無理のない範囲から順に適用できた。

コード量が多いことから、順次適用が可能だったのは特に大きなメリットでした。

悪かった点(苦労した点)

以下のような苦労点もありました。

• アロー関数では method decorator が適用できない。

  • 今回は関数定義方法を function に変更しましたが、既存のコードを大量に修正する必要がありました。この作業は単純ですが非常に作業時間がかかってしまいました。

• ログ出力の完全な自動化はできていない。

  • 関数の引数がオブジェクトの場合に中身を表示しないようにしましたが、一部、オブジェクトの内容をログに含めたい場合には結局ログ出力のためにコードを書く必要があります。

• decorator を利用すると仮引数名が表示不可となりログを見た時に arg の意味が分かりづらい。

  • （現時点において我々には）仮引数名を取得する方法が見つけられていないことから、仮引数名をログに含めることができませんでした。

これらの問題はありましたが全体としては、decorator を利用したログ出力の実装は上手くいったと言えます。

まとめ

今回 NeWork 開発チームの課題であったログ出力コードに関して、decorator を利用したログ出力の実装について紹介しました。

我々のチームでは TypeScript v4 で実験的な decorator を利用したログ出力を実装し、コードの可読性向上に貢献できました。

一方で decorator とアロー関数の相性の悪さといったような苦労した点もありました。

方式に関して、TypeScript v5 では実験的ではなく正式に decorator を利用できるようになっています。

またログ出力には log-decorator というライブラリや、何かしらのフレームワークを導入するという手段もあると思います。

この記事が、皆さんのログ出力の実装についての 1 つの参考になれば幸いです。

NeWork チームでは、今後も開発の中で課題となっていることを解決するために、さまざまな技術を試していきたいと考えています。今回紹介した内容についても、今後も改善を続けていきます。

また、NeWork はどなたでも無料でお試しできますので、もしプロダクトや使われている技術に興味を持っていただけたらぜひ触ってみてください。

最後に、2024 年 2 月現在、NeWork では一緒に開発を進めてくれる仲間を募集しています。詳細は以下のリンクをご覧ください。皆さまのご応募を心からお待ちしています！

hrmos.co

参考文献

https://www.TypeScriptlang.org/docs/handbook/decorators.html

https://bobbyhadz.com/blog/javascript-check-if-function-is-async