【Datadog APM】謎の500エラーとの戦い【ddtrace】

概要

• Rails アプリを ddtrace gem を使って Datadog の APM でいろいろ見られるようにしている環境
• 通常は発生したエラーの種類などの情報が表示されるが、今回発生したエラーは原因が不明だった
• 手がかりとなる情報を追加でDatadogに送信し、原因を特定した

本編

ある日、Datadogのダッシュボードを見ると、なにやらエラーが増えていることに気づきました。

リクエストをエラー数順でソートすると、resource name が POST 500 となっているリクエストが一番多くエラーになっていることがわかりました。

APM で env:production status:error resource_name:"POST 500" で検索すると、該当するリクエストが表示されました。

出てきたトレースのうち一つを見てみると、 Missing error message and stack trace となっていて、どこでどんなエラーが発生したのか不明でした。

どのエンドポイントで起きているかはわかっているのでそこから原因を推測しようとしましたが、GraphQL のエンドポイントに POST したときに発生したことしかわかりませんでした。

このままだと原因の特定に必要な情報が足りないので、手がかりとなる情報を追加してみることにしました。

公式ドキュメントによると、 set_tag で情報を追加できるとのことなので、「どのページでリクエストが送信されたか」「どんな GraphQL クエリが POST されたか」などの情報を追加してみました。

こんな感じ。

Datadog::Tracing.active_span&.set_tag('graphql.query', params[:query])
Datadog::Tracing.active_span&.set_tag('graphql.operation_name', params[:operationName])
Datadog::Tracing.active_span&.set_tag('http.request.referer', request.referer)

これにより、追加の情報が得られました。ですが、様々なページやクエリで同じエラーが発生していたため、特定のページやクエリに問題があるわけではなさそうです。

そこからさらに試行錯誤を行い、「Controller の before_action で発生している可能性が高い」ということが判明しました。

最終的に、rescue_from で例外をキャッチしている場所を見つけて、先ほどと同様に set_tag で追加の情報をDatadogに送ることで、ようやくどんなエラーが発生しているか特定できました。CSRFトークンのエラーでした。

Rails のデフォルトだと CSRF トークンのエラーは 422 返すようになっていますが、今回の Rails アプリではエラーごとの処理をカスタマイズするためにいろいろやっていて、それが原因で適切なエラーが返せていない状態になっていました。

適切なエラーを返すように修正しつつ、 Datadog でちゃんとエラー情報が見れるように set_error で例外を渡してあげることで、Datadog でエラーの情報が見れるようになりました。

また、今回のエラー調査には使用しませんでしたが、エラーが起きている場所を絞り込むための方法として、スパン を手動で作成するのもよく使います。

エラーの調査に詰まったら、怪しそうな処理それぞれを以下のように囲んで、どのスパンで発生しているか絞り込んでいくのもおすすめです。

Datadog::Tracing.trace(name, **options) do |span, trace|
  # ここに書いた処理が1つの span として扱われる
end

まとめ

• ddtrace で基本エラーの情報がわかるが、エラーの情報がDatadogに送られない場合もある
• set_tag や set_error などで、足りない情報を追加することで、原因が特定できる
• 手動でスパンを作成してエラー発生個所を絞り込むのも有用