Go言語のAPIサーバーの冗長なエラーログを40%削減した話 #LayerXテックアドカレ

こんにちは。バクラク申請・経費精算エンジニアの@upamuneです。先週末は30kmのトレイルレースがありましたが、今週末はフルマラソンがあるので満身創痍です。

この記事はLayerXテックアドカレ2023の22日目の記事です。 私はなぜか3日分もテックアドカレに入れてしまったのですが、2回目の今回はAPIサーバーのエラーログを40%削減した話をします。

昨日は@tataneによるバクラクの Vue3 移行戦略と詰まったポイント #LayerXテックアドカレ - LayerX エンジニアブログでした。明日は@trsによる入社エントリーです！楽しみですね。

はじめに

弊社では基本的にGo言語を利用してAPIサーバーを実装しています。エラーが発生したら、調査しやすいようにエラーログを出力して調査しやすくしていますが、1つのエラーに対して複数回の冗長なエラーログが出力されるという問題がありました。

複数のエラーログにより情報が増えるのであれば問題ないのですが、この場合発生したエラーの中身だけ出力されており、 caller フィールド¹ã ã‘が違うものでした。

冗長なエラーログの原因

エラーが発生した際にエラーの詳細を出力するために、ログを出力しているのですが、スタックトレースを擬似的に出力するために、エラーをハンドリングする部分で毎回エラーログ出力してしまっていました。これが冗長なエラーログの原因です。

if err := doSomething(); err != nil {
    log.Error(err).Send() // これが冗長なエラーログの原因
    return err
}

以下のコードは上の例を示す、Go言語の擬似的なコードです。エラーハンドリングの部分で毎回エラーログを出力しています。出力されるログのcallerフィールドを参照することで、どのファイルの何行目でエラーが発生したかを特定できるようになっています。

具体的には、 Parent関数を呼び出した時に、 Grandchild 関数の fuga呼び出しでエラーが起きた場合は、 fuga の部分のエラーハンドリングと、 Child 関数の Grandchild 呼び出しの部分のエラーハンドリングと、 Parent 関数の Child 呼び出しの部分のエラーハンドリングの合計3箇所でエラーログが出力され、ログ内の caller のみが異なるため、どの行でエラーが発生したかを特定できます。

func Parent() error {
    if err := Child(); err != nil {
        // Output: {"caller":"main.go:4","level":"error","error":"an error occurred"}
        log.Error().Err(err).Send()
        return err
    }
    return nil
}

func Child() error {
    if err := Grandchild(); err != nil {
        // Output: {"caller":"main.go:13","level":"error","error":"an error occurred"}
        log.Error().Err(err).Send()
        return err
    }
    return nil
}

func Grandchild() error {
    if err := hoge(); err != nil {
        log.Error().Err(err).Send()
        return err
    }
    if err := fuga(); err != nil {
        // Output: {"caller":"main.go:26","level":"error","error":"an error occurred"}
        log.Error().Err(err).Send()
        return err
    }
    if err := piyo(); err != nil {
        log.Error().Err(err).Send()
        return err
    }
    return nil
}

このため、エラーは1回しか発生していなくても、エラーハンドリングしている部分ごとにエラーログが出力されてしまい、大げさに言うと1回エラーが発生すると10個のエラーログが出て、それぞれcallerのフィールドだけが違うという状態になっていました。

冗長なエラーログの影響

冗長なエラーログによる問題は主に以下の点があります。

• 冗長なエラーログにより、エラーログの件数が増加しログ全体の検索コストと金銭的コストが増加する
• エラーログの件数を元にアラートを設定している場合、アラートのしきい値を決めるのが難しい
• 複数のエラーログを見ないとスタックトレースを見ることができないのでエラーの原因を追いづらい

これらの問題を解決するために、冗長なエラーログを改善することにしました。

冗長なエラーログの削減方法

全体的な方針としては、スタックトレースを確認する目的で出力しているエラーログを削除して、その代わりにエラーをWrapしていきます。エラーをWrapした時にコールスタックを記録しておけるエラーハンドリングのライブラリ²ã‚’利用すれば、後からスタックトレースを出力できるためです。そのWrapされたエラーを一箇所でエラーログとして出力するようにします。

まず上で示した方針を元にした手順が以下です。

1. Wrapされたエラーのスタックトレースを出力できるように設定
2. Wrapされたエラーに対応できてない部分を見つけて修正
3. エラーをWrapするように修正
4. 冗長なエラーログを削除

1. Wrapされたエラーのスタックトレースを出力できるように設定

弊社で利用しているロギングライブラリはrs/zerologを使っているので、このライブラリでエラーのスタックトレースを出力できるように設定するところから始めました。この修正を行うと、エラーからスタックトレースを出力することができます。

Event.Stack を利用すると、渡された error を設定した ErrorStackMarshaler を元に stack フィールドに追加してくれるためです。

zerolog.ErrorStackMarshalerに設定する関数は、エラーをWrapしているライブラリに合わせて実装します。zerologが実装しているpkg/errors向けの実装が参考になります。

2. Wrapされたエラーに対応できてない部分を見つけて修正

エラーをWrapしていく前に、まずエラーをWrapしても問題ないように修正していきました。具体的にはエラーを直接 == で比較していたり、Type Assertionによってエラーを変換している部分を修正しました。

該当部分を頑張って見つけるのは限界があるので、polyfloyd/go-errorlintを利用して、該当部分をあぶり出しました。それほど数は無かったので以下のように手動で置換していきました。

• エラーを直接 == で比較している部分 → errors.Isを利用して比較するように修正
• エラーをType Assertionによって変換している部分 → errors.As を利用して変換するように修正

この修正を行って、エラーをWrapしても問題ないコードベースになりました。

3. エラーをWrapするように修正

エラーをWrapしても問題ないようになったので、あとは return err している部分を return errors.Wrap(err) に修正しました。 ³

ここを綺麗にやる良い方法を思いつかなかったので、エラーハンドリングのパターンを検索して一括置換していきました。これによって、ほとんどのケースでエラーをWrapすることができました。

4. 冗長なエラーログを削除

最後にエラーをWrapして、Wrapした際に記録されるコールスタックを元にログに stack フィールドが追加されるようになったので、冗長なエラーログが必要なくなったので削除していきました。これは log.Error(err).Send() を検索して一括で削除するだけでした。

また、冗長なエラーログが今後増えることが無いようにPR作成時にCI（GitHub Actions）で実行される semgrep を利用して、冗長なエラーログを禁止するルールを作成してCIで発見するようにしています。以下のようなルールを設定しています。

rules:
  - id: meaningless-error-log
    patterns:
      - pattern-either:
          - pattern: $X.Error($ERR).Send()
    message: "冗長なエラーログを出力しないでください"
    languages: [ go ]
    severity: ERROR

エラーのWrap忘れにも気づくことができるようにtomarrell/wrapcheckのlinterを有効にしています。

改善した結果

上の手法で段階的にエラーハンドリングを改善して、冗長なエラーログを削除した結果、エラーログを40%削減することができました。

これによって、1つのエラーにより大量のエラーログが発生することがなくなり、エラーのスタックトレースを見たい場合でも1つのエラーログ⁴を見れば良いだけになり、余計な手間も削減することができました。

おわりに

今回は、エラーがWrapされてないコードベースを安全に変更していき、結果として冗長なエラーログを削減していく過程を紹介しました。

Wrapされたエラーハンドリングを正しく行えてない箇所を見つけるためにも、今後Wrapされてないエラーを発見するためにもlinterが活躍しました。linterのおかげで安全にコード変更を行っていくことができるのでありがたいですね。

ちなみに、この取り組みはチームの改善デーで実施されました。毎月、改善したいと思っているけどなかなか取り組めてないことに対して丸一日かけて取り組むことができるので楽しいです。次の改善デーは何をしようかなと思いを馳せています。

---

LayerXオフィスでカジュアルにドリンクを飲む会を企画しました。こちらも是非ご覧ください！

jobs.layerx.co.jp

---

1. callerフィールドにはログ呼び出し元のファイル名、行数が記録されています↩
2. 例えばpkg/errors, morikuni/failure, cockroachdb/errorsなど↩
3. ここでの errors は pkg/errors ではなく、弊社の独自実装である morikuni/failure ã‚’Wrapしたライブラリです↩
4. 今回修正したAPIサーバーはgqlgenを利用したGraphQLのAPIサーバーだったため、 ResponseMiddleware 内でエラーログ出力するようにしました↩