Graphql-ruby: GraphQL::Execution error not being handled correctly inside graphql-batch

[thornomad]

I'm not sure if this is any issue with graphql-ruby or graphql-batch, but I will start here.

When an error is raised from inside a RecordLoader#perform method, it doesn't seem that GraphQL::ExecutionError is able to handle its _magic_ correctly. Instead, I am getting a standard error response (and not the pretty GraphQL compliant one).

here is my (simplified) setup and working example as expected

class ApiSchema < GraphQL::Schema
  use GraphQL::Execution::Interpreter
  use GraphQL::Execution::Errors

  authorization(:pundit)
  mutation(Types::MutationType)
  query(Types::QueryType)

  use GraphQL::Batch

  ApiSchema.rescue_from(ActiveRecord::RecordNotFound) do |*rescue_args|
    raise GraphQL::ExecutionError, 'I rescued from error this safely!'
  end
end

class Types::CustomerType < Types::BaseObject
  field :person, Types::PersonType, null: true
  def person
    raise ActiveRecord::RecordNotFound, 'Hi there'
    # Loaders::RecordLoader.for(Person).load(object.person_id)
  end
end
 ```
<img width="472" alt="image" src="https://user-images.githubusercontent.com/124717/66426513-d6ea8180-e9c6-11e9-8ee3-658196d03b6e.png">

The raised error was `rescue_from` and the resulting `GraphQL::ExecutionError` is being displayed correctly.   Expected behavior.

## same error raised inside of the batch perform method

However, when this same error is raised _inside of the_ `RecordLoader`, the `GraphQL::ExecutionError` is *not* sending output the same way.

```ruby
class Types::CustomerType < Types::BaseObject
  field :person, Types::PersonType, null: true
  def person
    Loaders::RecordLoader.for(Person).load(object.person_id)
  end
end

class Loaders::RecordLoader < GraphQL::Batch::Loader
  def initialize(model)
    @model = model
  end

  def perform(ids)
    raise ActiveRecord::RecordNotFound, 'Hi there!'  #just raise any error ...
  end
end

It seems the rescue_from bit is still working as expected, but the resulting GraphQL::ExecutionError is not getting handled the same way. I am not sure why!

thanks for your help!

PS - I'm just using RecordNotFound as an example (doesn't matter what type of error is being thrown). Also, if this is a problem with graphql-batch I can re-post it there.

[rmosolgo]

Thanks for reporting this! I think it's a bug in GraphQL-Ruby. Any error during execution should be captured like you expect.

Could you please share the full stack trace of that uncaught error? That would tell me what codepath within execution isn't properly rescuing errors. (Apparently I overlooked a spot!)

[thornomad]

Sure thing, so error_handler:15 is right here:

   14       ApiSchema.rescue_from(ActiveRecord::RecordNotFound) do |*rescue_args|
>  15         raise GraphQL::ExecutionError, 'I rescued from this error safely!'
   16       end

And this is the full backtrace.

Full backtrace
--------------

 - app/graphql/api_schema/error_handler.rb:15:in `block in <module:ErrorHandler>'
 - graphql (1.9.12) lib/graphql/execution/errors.rb:53:in `rescue in with_error_handling'
 - graphql (1.9.12) lib/graphql/execution/errors.rb:40:in `with_error_handling'
 - graphql (1.9.12) lib/graphql/execution/errors.rb:32:in `trace'
 - graphql (1.9.12) lib/graphql/tracing.rb:78:in `call_tracers'
 - graphql (1.9.12) lib/graphql/tracing.rb:62:in `trace'
 - graphql (1.9.12) lib/graphql/execution/interpreter/runtime.rb:405:in `block in after_lazy'
 - graphql (1.9.12) lib/graphql/execution/lazy.rb:41:in `value'
 - graphql (1.9.12) lib/graphql/execution/interpreter/resolve.rb:37:in `resolve'
 - graphql (1.9.12) lib/graphql/execution/interpreter/resolve.rb:11:in `resolve_all'
 - graphql (1.9.12) lib/graphql/execution/interpreter.rb:94:in `block in sync_lazies'
 - graphql (1.9.12) lib/graphql/tracing.rb:62:in `block in trace'
 - graphql (1.9.12) lib/graphql/tracing.rb:78:in `block (2 levels) in call_tracers'
 - graphql (1.9.12) lib/graphql/tracing.rb:76:in `call_tracers'
 - graphql (1.9.12) lib/graphql/tracing.rb:78:in `block in call_tracers'
 - graphql (1.9.12) lib/graphql/execution/errors.rb:34:in `trace'
 - graphql (1.9.12) lib/graphql/tracing.rb:78:in `call_tracers'
 - graphql (1.9.12) lib/graphql/tracing.rb:62:in `trace'
 - graphql (1.9.12) lib/graphql/execution/interpreter.rb:93:in `sync_lazies'
 - graphql (1.9.12) lib/graphql/execution/interpreter.rb:51:in `finish_multiplex'
 - graphql (1.9.12) lib/graphql/execution/multiplex.rb:88:in `run_as_multiplex'
 - graphql (1.9.12) lib/graphql/execution/multiplex.rb:62:in `block (2 levels) in run_queries'
 - graphql (1.9.12) lib/graphql/execution/multiplex.rb:186:in `block in instrument_and_analyze'
 - graphql (1.9.12) lib/graphql/execution/instrumentation.rb:29:in `block (2 levels) in apply_instrumenters'
 - graphql (1.9.12) lib/graphql/execution/instrumentation.rb:46:in `block (2 levels) in each_query_call_hooks'
 - graphql (1.9.12) lib/graphql/execution/instrumentation.rb:41:in `each_query_call_hooks'
 - graphql (1.9.12) lib/graphql/execution/instrumentation.rb:45:in `block in each_query_call_hooks'
 - graphql (1.9.12) lib/graphql/execution/instrumentation.rb:72:in `call_hooks'
 - graphql (1.9.12) lib/graphql/execution/instrumentation.rb:44:in `each_query_call_hooks'
 - graphql (1.9.12) lib/graphql/execution/instrumentation.rb:27:in `block in apply_instrumenters'
 - graphql (1.9.12) lib/graphql/execution/instrumentation.rb:72:in `call_hooks'
 - graphql (1.9.12) lib/graphql/execution/instrumentation.rb:26:in `apply_instrumenters'
 - graphql (1.9.12) lib/graphql/execution/multiplex.rb:174:in `instrument_and_analyze'
 - graphql (1.9.12) lib/graphql/execution/multiplex.rb:61:in `block in run_queries'
 - graphql (1.9.12) lib/graphql/tracing.rb:62:in `block in trace'
 - graphql (1.9.12) lib/graphql/tracing.rb:78:in `block (2 levels) in call_tracers'
 - graphql (1.9.12) lib/graphql/tracing.rb:76:in `call_tracers'
 - graphql (1.9.12) lib/graphql/tracing.rb:78:in `block in call_tracers'
 - graphql (1.9.12) lib/graphql/execution/errors.rb:34:in `trace'
 - graphql (1.9.12) lib/graphql/tracing.rb:78:in `call_tracers'
 - graphql (1.9.12) lib/graphql/tracing.rb:62:in `trace'
 - graphql (1.9.12) lib/graphql/execution/multiplex.rb:59:in `run_queries'
 - graphql (1.9.12) lib/graphql/execution/multiplex.rb:49:in `run_all'
 - graphql (1.9.12) lib/graphql/schema.rb:392:in `block in multiplex'
 - graphql (1.9.12) lib/graphql/schema.rb:1279:in `with_definition_error_check'
 - graphql (1.9.12) lib/graphql/schema.rb:391:in `multiplex'
 - graphql (1.9.12) lib/graphql/schema.rb:368:in `execute'
 - /Users/damon/.rubies/ruby-2.6.3/lib/ruby/2.6.0/forwardable.rb:230:in `execute'
 - app/controllers/graphql_controller.rb:17:in `execute'
 - actionpack (5.2.3) lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
 - actionpack (5.2.3) lib/abstract_controller/base.rb:194:in `process_action'
 - actionpack (5.2.3) lib/action_controller/metal/rendering.rb:30:in `process_action'
 - actionpack (5.2.3) lib/abstract_controller/callbacks.rb:42:in `block in process_action'
 - activesupport (5.2.3) lib/active_support/callbacks.rb:109:in `block in run_callbacks'
 - app/controllers/api/v2/api_controller.rb:63:in `set_current_user'
 - activesupport (5.2.3) lib/active_support/callbacks.rb:118:in `block in run_callbacks'
 - sentry-raven (2.7.3) lib/raven/integrations/rails/controller_transaction.rb:7:in `block in included'
 - activesupport (5.2.3) lib/active_support/callbacks.rb:118:in `block in run_callbacks'
 - activesupport (5.2.3) lib/active_support/callbacks.rb:136:in `run_callbacks'
 - actionpack (5.2.3) lib/abstract_controller/callbacks.rb:41:in `process_action'
 - actionpack (5.2.3) lib/action_controller/metal/rescue.rb:22:in `process_action'
 - actionpack (5.2.3) lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
 - activesupport (5.2.3) lib/active_support/notifications.rb:168:in `block in instrument'
 - activesupport (5.2.3) lib/active_support/notifications/instrumenter.rb:23:in `instrument'
 - activesupport (5.2.3) lib/active_support/notifications.rb:168:in `instrument'
 - actionpack (5.2.3) lib/action_controller/metal/instrumentation.rb:32:in `process_action'
 - actionpack (5.2.3) lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
 - activerecord (5.2.3) lib/active_record/railties/controller_runtime.rb:24:in `process_action'
 - actionpack (5.2.3) lib/abstract_controller/base.rb:134:in `process'
 - actionpack (5.2.3) lib/action_controller/metal.rb:191:in `dispatch'
 - actionpack (5.2.3) lib/action_controller/metal.rb:252:in `dispatch'
 - actionpack (5.2.3) lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
 - actionpack (5.2.3) lib/action_dispatch/routing/route_set.rb:34:in `serve'
 - actionpack (5.2.3) lib/action_dispatch/journey/router.rb:52:in `block in serve'
 - actionpack (5.2.3) lib/action_dispatch/journey/router.rb:35:in `serve'
 - actionpack (5.2.3) lib/action_dispatch/routing/route_set.rb:840:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/action_dispatch/routing/route_set.rb:14:in `block in call'
 - skylight-core (3.1.5) lib/skylight/core/fanout.rb:25:in `instrument'
 - skylight-core (3.1.5) lib/skylight/core/probes/action_dispatch/routing/route_set.rb:13:in `call'
 - rack (2.0.7) lib/rack/etag.rb:25:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - rack (2.0.7) lib/rack/conditional_get.rb:38:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - rack (2.0.7) lib/rack/head.rb:12:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - activerecord (5.2.3) lib/active_record/migration.rb:559:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - actionpack (5.2.3) lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
 - activesupport (5.2.3) lib/active_support/callbacks.rb:98:in `run_callbacks'
 - actionpack (5.2.3) lib/action_dispatch/middleware/callbacks.rb:26:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - actionpack (5.2.3) lib/action_dispatch/middleware/executor.rb:14:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - better_errors (2.1.1) lib/better_errors/middleware.rb:84:in `protected_app_call'
 - better_errors (2.1.1) lib/better_errors/middleware.rb:79:in `better_errors_call'
 - better_errors (2.1.1) lib/better_errors/middleware.rb:57:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - actionpack (5.2.3) lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - actionpack (5.2.3) lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - railties (5.2.3) lib/rails/rack/logger.rb:38:in `call_app'
 - railties (5.2.3) lib/rails/rack/logger.rb:26:in `block in call'
 - activesupport (5.2.3) lib/active_support/tagged_logging.rb:71:in `block in tagged'
 - activesupport (5.2.3) lib/active_support/tagged_logging.rb:28:in `tagged'
 - activesupport (5.2.3) lib/active_support/tagged_logging.rb:71:in `tagged'
 - railties (5.2.3) lib/rails/rack/logger.rb:26:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - actionpack (5.2.3) lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - request_store (1.4.1) lib/request_store/middleware.rb:19:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - actionpack (5.2.3) lib/action_dispatch/middleware/request_id.rb:27:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/action_dispatch/request_id.rb:12:in `call'
 - rack (2.0.7) lib/rack/runtime.rb:22:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - activesupport (5.2.3) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - actionpack (5.2.3) lib/action_dispatch/middleware/executor.rb:14:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - actionpack (5.2.3) lib/action_dispatch/middleware/static.rb:127:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - rack (2.0.7) lib/rack/sendfile.rb:111:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - rack-cors (1.0.3) lib/rack/cors.rb:95:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - hirefire-resource (0.4.2) lib/hirefire/middleware.rb:41:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - sentry-raven (2.7.3) lib/raven/integrations/rack.rb:51:in `call'
 - skylight-core (3.1.5) lib/skylight/core/probes/middleware.rb:26:in `call'
 - railties (5.2.3) lib/rails/engine.rb:524:in `call'
 - puma (3.11.0) lib/puma/configuration.rb:225:in `call'
 - puma (3.11.0) lib/puma/server.rb:624:in `handle_request'
 - puma (3.11.0) lib/puma/server.rb:438:in `process_client'
 - puma (3.11.0) lib/puma/server.rb:302:in `block in run'
 - puma (3.11.0) lib/puma/thread_pool.rb:120:in `block in spawn_thread'

[rmosolgo]

Thanks, that's really helpful! It looks like I missed a spot in my earlier work. After I merge #2525, you can use a patched version from master:

gem "graphql", github: "rmosolgo/graphql-ruby", ref: "master" 

And it'll release in the next version. Please let me know if you run into any trouble after upgrading!

[thornomad]

Fix confirmed! Seems to have resolved it. Thank you.

[nbcraft]

Thank you I was experiencing the same problem, new version fixed it 👍