GraphQL Rubyで定義したスキーマの実行中に起きたエラーをいい感じに通知するようにしたので、それを紹介します。

Problem

GraphQL Rubyで定義したスキーマのフィールドのresolve中にエラーが起きた場合、Rubyレベルのバックトレースはあまり当てになりません。 Rubyレベルのバックトレースには、リクエストされたクエリのフィールド名などは出てきません。そのためどのようなクエリが実行された結果エラーが起きたのか、という情報は見えません。

Solution

これを解決するためにGraphQL RubyのTracerを使い、Sentryのextra contextとしてGraphQL RubyレベルでのバックトレースをSentryに送るようにしました。

これによって、次のクエリに対して、次のバックトレースがSentryに送られるようになりました。

GraphQL Query (url fieldの評価中にエラーが発生する):

query {
  notes(first: 10) {
    edges {
      node {
        url
      }
    }
  }
}

送られたバックトレース:

5:9: Note.url
4:7: NoteEdge.node
3:5: NoteConnection.edges
3:5: NoteConnection.edges
2:3: Query.notes
1:1: query

Implementation

まず、次のTracerを用意します。

class ErrorContextTracer
  KEY = 'ErrorContextTracer-lock'

  def self.trace(key, data, &block)
    block.call
  rescue => ex
    if key == 'execute_field' && !RequestStore.exist?(KEY)
      backtrace = data[:context].backtrace.to_a.join("\n")
      Raven.extra_context(graphql_backtrace: backtrace)
      RequestStore.write(KEY, 42) # Write dummy value to avoid to overriding the context with parent tracer.
    end
    raise ex
  end
end

そして、スキーマ定義内でこれを使うように指定します。

class MySchema < GraphQL::Schema
  tracer ErrorContextTracer

  # ...
end

これだけで先に挙げたバックトレースがSentryに送られるようになります。

なおこのコードを実行するにはsentry-raven gemとrequest_store gemが必要です。とはいえ、Sentry以外のツールを使っている場合にも同様のことは行えるでしょう。

Alternative Solution

上記Tracerの中ではdata[:context].backtrace.to_a.join("\n")としていますが、初期実装ではdata[:context].backtraceをそのままextra contextにセットしていました。その場合は、次のようなバックトレースがSentryに送られます。

Loc  | Field                | Object                                                               | Arguments                                                                                    | Result
5:9  | Note.url             | #<Note id: 1252, title: "Hello", content: "Hello, Kibela", user_i... | {}                                                                                           | nil
4:7  | NoteEdge.node        | #<GraphQL::Relay::Edge (nil => #<Note id: 1252, title: "Hello", cont | {}                                                                                           | {}
3:5  | NoteConnection.edges | #<GraphQL::Relay::Edge (nil => #<Note id: 1252, title: "Hello", cont | {}                                                                                           | {}
3:5  | NoteConnection.edges | #<GraphQL::Relay::Connection @parent=nil @arguments={:first=>10, :or | {}                                                                                           | []
2:3  | Query.notes          | nil                                                                  | {"first"=>10, "orderBy"=>{:field=>"CONTENT_UPDATED_AT", :direction=>"DESC"}, "active"=>true} | {}
1:1  | query                | nil                                                                  | {}                                                                                           | {}

この方が明らかに情報量が多く、便利なように見えます。

ところがこのバックトレースはSentryにフィルタリングされてしまったのでボツとなりました。個人情報が含まれないようにするフィルタに引っかかっていたようです。おそらくObjectやArgumentsの中に個人情報と判断される情報が入ってしまっていたのでしょう。

pockestrap

Programmer's memo

GraphQL Rubyで起きたエラーをSentryにいい感じに通知する

Problem

Solution

Implementation

Alternative Solution

Links