🤖

業務システムのログメッセージの書き方

2021/03/04に公開

はじめに

以下のような手続き型のコードを例にエラー時のログに記載すべき事柄について考えます。
目標はエラーログを読んだ人がエラーの原因を理解し、何らかのアクションをとれることです。
サンプルコードはScalaです。

/**
 * 記事にコメントする
 **/
def commentOnTopic(user: User, cmd: CommentOnTopic): Result = {
    // スラッグ(URLに含まれる文字列)を元に記事を検索
    val topic = topicRepository.findById(cmd.slug)
    // 記事の作成者を検索
    val maybeAuthor: Option[User] = userRepository.findById(topic.author) // authorはユーザID
    // 作成者が見つからなかったらエラーにする
    if (maybeAuthor.isEmpty) {
      logger.error("ここに何か書く")
      throw new NotFoundException
    }
    // 以下つづく
    ...
}

Level 0. メッセージのみ記述する

    val author = maybeAuthor.getOrElse {
        logger.error("記事の作成者が見つかりませんでした。")
        throw new NotFoundException
    }

このログの問題点は、どの記事かわからないことです。

Level 1. 条件を記述する

問題は記事の作成者とされているユーザが見つからなかったことなので、該当の記事と作成者とされているユーザのIDをそれぞれ記載します。

    // 記事の作成者を検索
    val maybeAuthor: Option[User] = userRepository.findById(topic.author)
    // 作成者が見つからなかったらエラーにする
    if (maybeAuthor.isEmpty) {
      logger.error("記事の作成者が見つかりませんでした。作成者=${topic.author}、記事ID=${topic.id}")
      throw new NotFoundException
    }
    ...

Level 2. コンテキストを踏まえて条件を記述する

この処理では、記事(topic)はスラッグを検索条件にして取得します。
データベースによって自動的に採番されるIDなどとは別に、スラッグのように人間が読み取って内容を連想しやすい識別子をIDとは別に用意しているシステムも多いのではないかと思います。
システムに問題が発生した時、IDのように機械が生成した識別子よりもスラッグのような識別子を使って会話した方がステークホルダーが問題を認識しやすいことがあります。したがって、この処理では記事のスラッグもログに出力した方がよいでしょう。

/**
 * 記事にコメントする
 **/
def commentOnTopic(user: User, cmd: CommentOnTopic): Result = {
    // スラッグ(URLに含まれる文字列)を元に記事を検索
    val topic = topicRepository.findById(cmd.slug)
    // 記事の作成者を検索
    val maybeAuthor: Option[User] = userRepository.findById(topic.author)
    // 作成者が見つからなかったらエラーにする
    if (maybeAuthor.isEmpty) {
      logger.error(
          "記事の作成者が見つかりませんでした。作成者=${topic.author}、" +
          "記事ID=${topic.id}、スラッグ=${cmd.slug}"
      )
      throw new NotFoundException
    }
    ...

Level 3. コンテキストを記述する

ログには 記事の作成者が見つかりませんでした と書かれていますが、記事の作成者が見つからないことが問題の全てでしょうか?
エラーの発生原因は確かに存在すべきデータが無かったことですが、そもそも何故記事の検索を行ったのか、ということも問題の対処に影響を与えることがあります。今回の場合、システムが記事の検索を行ったのは、ユーザが記事にコメントしようとしたことが契機です。

/**
 * 記事にコメントする
 **/
def commentOnTopic(user: User, cmd: CommentOnTopic): Result = {
    // スラッグ(URLに含まれる文字列)を元に記事を検索
    val topic = topicRepository.findById(cmd.slug)
    // 記事の作成者を検索
    val maybeAuthor: Option[User] = userRepository.findById(topic.author)
    // 作成者が見つからなかったらエラーにする
    if (maybeAuthor.isEmpty) {
      logger.error(
          "記事の作成者が見つからなかったため、ユーザが記事にコメントできませんでした。" +
          "作成者=${topic.author}、記事ID=${topic.id}、スラッグ=${cmd.slug}"
      )
      throw new NotFoundException
    }
    ...

Level 4. Actionable(行動可能)なメッセージにする

エラー発生時に行うことが明確な場合は、それをエラーの読み手に指示した方が読み手がそれを考えるコストを下げることができます。
要は「だから何?」という読み手の脳の反応に応えるようにします。

/**
 * 記事にコメントする
 **/
def commentOnTopic(user: User, cmd: CommentOnTopic): Result = {
    // スラッグ(URLに含まれる文字列)を元に記事を検索
    val topic = topicRepository.findById(cmd.slug)
    // 記事の作成者を検索
    val maybeAuthor: Option[User] = userRepository.findById(topic.author)
    // 作成者が見つからなかったらエラーにする
    if (maybeAuthor.isEmpty) {
      logger.error(
          "記事の作成者が見つからなかったため、ユーザが記事にコメントできませんでした。" +
          "記事の作成処理の実装を見直し、データを修復してください。" +
          "コメントしたユーザ=${user.id}, 作成者=${topic.author}、記事ID=${topic.id}、スラッグ=${cmd.slug}"
      )
      throw new NotFoundException
    }
    ...

雑感

Level 0のログばかりあるようなシステムだと、エンティティとかリポジトリとかバリューオブジェクトとかいった説明が熱心にコメントに書かれていたとしても業務の言葉で会話できていない傾向があるかなと思います。
Level 3-4くらいのログを常に出せているシステムは、採用している実装方式がどのようなものであっても割と安心して見れることが多い気がします。

Discussion