こんにちは。最近は湿気にやられ気味のSREチームの高 (@nogtk) です。
先日、アプリケーションのエラー監視改善の一環として、Datadog ErrorTracking を導入しました。 厳密には、エラーログをデータソースとして扱う ErrorTracking for Logs を導入しております。長いので、以降本記事では ErrorTracking と呼んでいきます。
実際に導入するまでにやったことをご紹介したいと思います。
ErrorTracking 導入前のアプリケーション監視のやり方
導入前のアプリケーションのエラー監視としては、開発チーム単位で分担しながら以下のように行っていました。
- ログレベルが Error あるいは "error" という文言が入っているエラーログが発生した場合にそのエラーログを Slack に通知する
- 通知されたエラーログを確認し、適宜トリアージする
- 無視できるエラーログの場合は Datadog アラートにその文言を ignore する設定を追加する
1行のエラーログに対して1件のSlack通知という形で対応しているため、かなりノイジーなアラートになってしまっていることが想像できるかと思います。 アラートの ignore 設定およびログそのものを出力しないような改修も、可能な範囲で行っていましたが、完全に追従ができておらず対応不要となっているエラーが通知され続けてしまっている状況でもありました。
こういったアプリケーションエラー監視の課題を踏まえ、各エラーの可視化および柔軟な通知設定をしたいというモチベーションで、Datadog が提供するアプリケーションエラーの監視ツールである ErrorTracking を導入することにしました。
Datadog ErrorTracking 導入までにやったこと
ErrorTracking にエラーを連携するための実装追加
何はともあれまずは発生したアプリケーションエラーを ErrorTracking 上で閲覧できるようにする必要があります。
こちらに紹介がある通り、以下の情報をログに含めることで発生したエラーログが ErrorTracking へと集約されるようになります。
- error.stack (スタックトレース)
- error.message (エラーメッセージ)
- error.kind (エラークラス)
前提として、ログを構造化しておく必要があります。*1
前回のブログでログを構造化した話を紹介しました。
実は、この ErrorTracking 導入を見据えた改修だったんですね。これが伏線回収というやつです。
簡単な実装例をご紹介しておきます。以下のようにして Python の sys.exc_info() から受け取った例外情報を捻ってエラー情報を詰め直しています。
error_info = {
'error.kind': exc_info[0].__name__,
'error.message': str(exc_info[1]),
'error.stack': ",".join(traceback.format_exception(*exc_info)),
}
# 既存のログエントリとマージする
log_entries | error_info
なお、この実装は構造化ログ用にフォーマット変換をしている処理から呼ばれるようになっています。そのため例外ブロックで logger.exception(xxx) と呼び出すことによって、透過的に error.kind / message / stack が追加され、ErrorTracking へとエラー情報が連携されるようになっています。
開発チームへの説明と懸念点の吸い出し
上記の実装を追加することで、実際に発生したエラーを ErrorTracking 上で扱えることになりました。そこでまず開発環境のみにこの変更を適用させ、どんなツールなのか、操作の触り心地を実際の開発者に共有する時間を設けました。
エラー監視運用は、4つある開発チームごとに分担して行っているので、そのチーム単位で15~30分ほど時間を設け、自分から ErrorTracking の説明と、それを利用した監視運用イメージの共有を行いました。
余談ですが、この説明会はチームごとに分けて計4回実施しました。自分個人としては同じことを4回話さないといけないのですが、それでも1回の参加メンバーを絞って開催することで、広くいろんなメンバーからの声を吸い上げやすかったように思います。今後広いスコープで様々なものの導入を進めていくにあたってこの感触は大事にしたいですね。
いくつか上がった懸念について追加調査を行い、最終的には各チームのリーダー陣に対して導入することの合意を得ることで、正式導入するという運びとなりました。
エラーのロギング実装の変更
大前提として、ErrorTracking に監視ツールを載せ替えるにあたって、連携されるエラーに抜け漏れがないようにしなければなりません。そして、ErrorTracking にエラーを連携するには、前述の通り例外情報を指定のキーでロギングする必要があります。
この例外情報は Python の例外オブジェクト (sys.exc_info()) から取得する実装にしているため、例外ブロックの中で logger.error ではなく logger.exception を使ったロギングへと修正する必要があります。以前の監視運用では、単にログレベルでエラーログを抽出していたため、error メソッドと exception メソッドの使い分けがまちまちになっていました。
つまり
try: hoge_function() except Exception: logger.error(“raise fuga error”)
となっているのを以下のように書き換えてあげる必要があるということですね。
try: hoge_function() except Exception: logger.exception(“raise fuga error”)
ここはソースコードの grep と後述する Linter による検出とを合わせて修正箇所を特定し、愚直に書き換えていきました。腕力の見せどころです。
ロギングの Linter 導入
既存コードは上記の通りゴリっと書き換えることで対応していきましたが、今後追加されていくコードについても、”例外ハンドリング内のエラーロギングは exception メソッドを利用する” という原則を守らせるようにしたいです。
できれば Linter を使って CI レベルで検知できないかということを検討していたところ
というロギングに関連した flake8 のプラグインを発見しました。（言わずもがなですが、Linter は flake8 を利用しています。）
特に、この flake8-logging が提供する LOG005 ルールの
use exception() within an exception handler
これがまさに今回自分が導入したかったものにばっちりマッチしています。ということで、リポジトリにこのプラグインを導入することにより、検出したかった exception のケースで CI レベルで無事検知できるようになりました。
ここまでで、新規・既存コード両方で、 “例外ハンドリング内のエラーロギングは exception メソッドを利用する” という原則を適用でき、ErrorTracking にエラーを集約していくベースを作ることが出来ました。
アラートの作成と差し替え
最後に、ErrorTracking を活用した Datadog アラートを作成します。大別して2つのアラートをセットしました。
- ErrorTracking 由来のエラーに関するアラート
- 従来の Error ログ由来に関するアラート
ErrorTracking 由来のエラーに関するアラート
ErrorTracking から通知可能なアラートが用意されており、大別してその中で2パターンのアラートタイプを選択できます。
- New Issues
- High Impact Issues
今回はエラーの発生件数に応じて通知を行う High Impact Issues タイプのアラートを定義しています。 ErrorTracking 上で、エラー種別ごとに直近1分以内にエラーが1件以上発生した場合に通知を行う設定にしています。
従来の Error ログ由来に関するアラート
ErrorTracking 由来のアラートだけでなく、従来の Error ログ由来に関しても引き続きアラートを継続させています。ただし、”ログレベルが Error のうち、スタックトレースがないもの” という条件で抽出し、該当するエラーログがある場合はその内容を通知します。
スタックトレースは今回の変更で error.stack として、ログを送出するように修正をしたため、Datadog 上のクエリで -@error.stack:* と検索することで、 “スタックトレースがないログ” を抽出することが出来ます。
このアラートの意図は2つです。
- もし ErrorTracking に連携漏れがあるエラーログがあっても通知させたい
- ソースコード上例外は発生していないが、エラーログとして通知しておきたいユースケースがあるため、それを漏らさないようにしたい
1 については万が一のための防御策です。発見次第修正していくイメージですね。 2については、例外処理は行っていないが logger.error メソッドでエラーログを出力しているケースに対する措置です。
後者の2については
- エラーログではなく例外を送出するようにしてロギングは透過的な例外ハンドラで行うべきなのでは？
- そもそもログレベルが Error なのはあるべき姿なのか？
など、いくつか議論の余地があると思っています。今回は、まずは監視ツールの導入にスコープを絞り、その対策としてこのようなアラートを設定しておきました。ここは引き続き開発チームとあるべき姿をどう定義するか、悩んでいきたいポイントです。
実際に導入してみて
実現された点
元々のアラート量が多くノイズだった点に関しては、発砲された Datadog アラートの数で比較して、大体 1/3〜1/4 程度にまで削減 することが出来ています。開発者に行ったアンケート結果についても、7~8割の開発者から、”エラーの監視負荷が減った感触がある” という回答が得られています。
削減できた要因については以下のように考えています。
- エラークラス単位で通知がまとめられたこと
- ErrorTracking 上のエラーステータスと通知ステータスが自動で同期されるようになったこと
後者の点について少し補足します。
ErrorTracking 上では、各エラーに対してステータスを割り当てることができます。
docs.datadoghq.com
例えば、追加調査や対応が不要なエラーの場合には “IGNORED” というステータスにアサインします。するとこのエラーについては ErrorTracking から通知されるエラー対象から除外され、以降は通知されなくなります。 このように、エラーのトリアージが通知の仕様にそのまま反映されることによって、秩序を保つことができます。
その他、以下のような恩恵も得られるようになっています。
- 発生しているエラーの時系列データを閲覧できるようになったこと
- ErrorTracking 上のデータから Logs/APM へシームレスに遷移できるようになったこと
これらはわざわざ ErrorTracking を導入せずとも、自前でログをパースしてダッシュボードを作れば実現はできると思います。ですが、そういった込み入った操作を必要とせずにエラーの可視化ができるのは、今後開発者に Datadog 活用を広く進めていきたいことも加味して、導入して良かった点だと感じています。
今後の改善ポイント
減ったとはいえまだまだ通知が多い ここに尽きるかなと思います。
今回は ErrorTracking というツールの導入にスコープを絞って進めていきました。システムそのものに対する変更は最小限にとどめ、そのシステムへの観測方法を変えたというようなイメージでしょうか。一定それで改善できた課題もありますが、やはり単なるツールの導入で解消できる課題には限界があります。
途中でも言及した通り、今後は既存の実装まで踏み込んだ改修や、ログレベルの定義とそれに合わせたアラート戦略の策定など、実装と運用設計の両軸で、開発者と議論を進めていく必要性を強く感じています。
おわりに
今回は Datadog ErrorTracking を導入してみた事例をご紹介致しました。エラーログを対象にして、アプリケーションエラー監視のマネジメントを行うことができるので、既存のエラー出力のコード資産をベースにツールを導入することができます。この点が非常に導入しやすくていいなと感じました。
ひとまず導入は完了しましたが、伸びしろはまだまだたくさんあります。今回の導入で、改善を進めていく下地は整備できたと思うので、今後は開発者と一緒にエラー監視のあるべき姿を模索していく予定です！次回をお楽しみに！（と言い切っておけば未来の自分がきっとブログを書いてくれるでしょう... ）
