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

# 概要

- Rails アプリを [`ddtrace`](https://github.com/DataDog/dd-trace-rb) gem を使って Datadog の APM でいろいろ見られるようにしている環境
- 通常は発生したエラーの種類などの情報が表示されるが、今回発生したエラーは原因が不明だった
- 手がかりとなる情報を追加でDatadogに送信し、原因を特定した

# 本編

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

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/325392/1fe466b7-d525-f9e2-bf01-8bed46536191.png)

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

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/325392/a9e48633-d1e0-f18c-5319-4e215e44257f.png)

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

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/325392/fc7bd6dd-bf7e-f8f8-1580-2b651462c012.png)


![error1.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/325392/04c159cf-1bce-dc6b-7e89-f55aed649b2f.png)

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

![error2.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/325392/c0f34c0b-4f63-e452-8d92-76148859e5f5.png)

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

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/325392/59eb11ce-2dd6-59ef-1914-a94d4a2276cc.png)

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

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

https://docs.datadoghq.com/ja/tracing/trace_collection/automatic_instrumentation/dd_libraries/ruby_v1/#enriching-traces-from-nested-methods

こんな感じ。

```rb
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)
```

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

![error3.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/325392/2bc4f78f-52ba-1746-8bdf-f5ff0069c3c0.png)

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

最終的に、[`rescue_from`](https://railsguides.jp/action_controller_overview.html#rescue-from) で例外をキャッチしている場所を見つけて、先ほどと同様に `set_tag` で追加の情報をDatadogに送ることで、ようやくどんなエラーが発生しているか特定できました。CSRFトークンのエラーでした。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/325392/a6e93959-f0d2-a869-418a-5e5792be5f01.png)

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

https://github.com/rails/rails/blob/c692e75d96f572f3fe518f06bec0dfd12b548429/actionpack/lib/action_dispatch/middleware/exception_wrapper.rb#L21

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

https://www.rubydoc.info/gems/ddtrace/Datadog%2FTracing%2FSpan:set_error

![error4.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/325392/5812aad9-fb84-02d5-87d7-7f259667959d.png)

また、今回のエラー調査には使用しませんでしたが、エラーが起きている場所を絞り込むための方法として、[スパン](https://docs.datadoghq.com/ja/tracing/glossary/#spans) を手動で作成するのもよく使います。

https://docs.datadoghq.com/ja/tracing/trace_collection/automatic_instrumentation/dd_libraries/ruby_v1/#manual-instrumentation

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

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

# まとめ

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