ユニファ開発者ブログ

ユニファ株式会社プロダクトデベロップメント本部メンバーによるブログです。

Slackに飛んでくる本番エラー通知、8割が「空メッセージ」だった話

Ruby 業務効率化 開発体制

皆さんこんにちは。バックエンドエンジニアの八木です。

今回は、社内のエラー監視・Slack通知の運用改善について書きます。

「エラー通知が多すぎて、正直誰も見ていない」というのは、規模の大きいシステムを運用しているとどこかで一度は経験する課題ではないでしょうか。今回はその状態から、通知の中身を疑い、実際に効果を測定するところまで取り組んだ内容を共有します。

目次

  1. きっかけはslack通知が多すぎて感じた危機感
  2. 原因は「例外はあるのに、messageフィールドが空だった」こと
  3. 「見える化」した結果、埋もれていた本物のバグが見つかった
  4. あえて直さなかったものもある
  5. まとめ

きっかけはslack通知が多すぎて感じた危機感

私たちのチームで担当しているプロダクトでは、本番環境で例外が発生するとSlackにアラートが飛ぶ仕組みを運用しています。ただ、ある時期から「エラー通知が多すぎて、正直言うと見逃している部分もある」という状態になってきました。

ある月は1,336件のアラートが飛んできていて、そのうち1,071件、実に80.2%が、例外の種類もメッセージも記録されていない「空メッセージ」の通知でした。「何かエラーが出ているので、ログを見て確認してね！」という通知だけが飛んできている状態です。slackを見ただけではエラーの中身が分からないので、結局元のログを毎度確認しにいくしかない。

これらのほとんどは不要なエラー通知で、そうでないものは大体既存の小さなバグだというのがわかっていたのですが、とはいえやはり１時間に何度も不要な通知が鳴ると気が散りますし、本当に必要なアラート通知があったときに見逃すリスクがありますよね。

原因は「例外はあるのに、messageフィールドが空だった」こと

調べていくと、原因はログの整形処理にありました。私たちはJSON形式の構造化ログを使っていて、通常のログにはmessageフィールドにテキストが入りますが、例外発生時は例外オブジェクトの情報がexceptionという別フィールドに構造化されて入る作りになっていました。

ここで問題だったのは、明示的にmessageを渡さずに例外だけをログ出力したケースです。この場合、messageフィールドは空のまま、詳細はexceptionフィールド側にしか入りません。ところがSlackへの通知はmessageフィールドの内容を本文として使う実装だったため、「例外は確かに発生しているのに、通知の本文は空」という状態になっていたのです。

疑似コードにするとこんなイメージです。

# Before: message が空なら、そのまま空で通知してしまう
def format_log(log)
  log_hash = base_format(log)     # message, exception などを含むHash
  log_hash
end

# After: message が空で exception 情報がある場合は、そこから本文を組み立てる
def format_log(log)
  log_hash = base_format(log)
  if log_hash[:message].blank? && log_hash[:exception]
    log_hash[:message] = build_message_from_exception(log_hash[:exception])
  end
  log_hash
end

あわせて、原因調査の過程で「外部サービスを呼んだ際に、想定内の例外が地味に多い」ことも分かりました。これらは本来保守サービス側の不具合ではないので、あらかじめ想定済みの例外クラスをリスト化しておき、それらだけログレベルを一段階下げて、そもそもSlack通知の対象から外すという対応もあわせて行いました。

疑似コード

# 想定内の例外は warn にして、通知対象から外す
EXPECTED_NOT_FOUND_EXCEPTIONS = [SomeExternalClient::NotFoundError, ...].freeze

def log_level_for(exception)
  EXPECTED_NOT_FOUND_EXCEPTIONS.include?(exception.class) ? :warn : :error
end

この2つの対応で、劇的な効果が出ました。

リリース直後の月は空メッセージの割合が80.2%→4.8%まで下がり、その次の月には0.0%、件数にして0件になりました。リリース日を境に切り替わりがきれいに出ていたので、原因の特定と修正の効果には確信が持てました。

「見える化」した結果、埋もれていた本物のバグが見つかった

ここからが本題です。ノイズがなくなったことで、これまで空メッセージの裏に隠れていた「本当に対応が必要なエラー」が、初めて可視化できるようになりました。

可視化された月には、9種類のエラーがランキングとして並びました。最も件数が多かったものは、その月のエラー全体の実に50.1%を占めていて、2番目に多かったものと合わせると約7割に達していました。

中身を精査すると、上位に来ていたエラーの多くには共通点がありました。大体は、「想定外の入力やデータへの対応漏れ」です。たとえば、外部サービスから返ってくるはずのデータが実は空だったケースをチェックしないまま参照してしまっていたり、本来ありえないはずのリクエストパラメータがバリデーションをすり抜けて後段の処理に届いてしまっていたり。こういった「ガード節の書き漏らし」は、どんなシステムでも起こりうる典型的なパターンだと思います。

疑似コード（とても初歩的なバグなのがわかります）

# Before
def process(job)
  target_ids = job.targets.map(&:id)
  ...
end

# After
def process(job)
  return if job.targets.blank?
  target_ids = job.targets.map(&:id)
  ...
end

このパターンに該当するエラーを優先度順に5件ほど修正したところ、対応を見送ったものも含めたその月の全エラー件数のうち、81.2%（件数にして628件）まで改善の見込みが立つ計算になりました。

残りは、次に紹介する「あえて直さなかったもの」です。

あえて直さなかったものもある

一方で、可視化された中には「あえて直さない」と判断したものもあります。

外部サービス側の一時的な障害に起因するもの、BOT等で自動化された不正アクセス・スキャン由来と思われるノイズなどです。

これらは通知として飛んでくることに意味があるものなので、すべてのエラーを機械的に潰しにいくのではなく、「これは本当に自分たちのコードの問題か」を都度切り分けて判断することも、対応の一部だと考えています。

まとめ

今回のケースでは、まず通知の「ノイズ」を取り除いたことで、初めて「本当に必要なエラー」が見える状態になり、そこから優先順位をつけて対応する、という当たり前の改善サイクルがようやく回せるようになりました。

運用保守においては大事な仕組みなので、これからも改善を頑張っていきたいと思います。

ユニファでは一緒に働く仲間を募集しています！

jobs.unifa-e.com