search

rmosolgo / graphql-ruby

Ruby implementation of GraphQL
http://graphql-ruby.org
MIT License
5.37k stars 1.37k forks source link

Runtime Error Duplicate Type #1505

Closed fameoflight closed 4 years ago

fameoflight commented 6 years ago

I am seeing increasing number of runtime error Duplicate types.

I thought this mainly happened due to old api but I am using new class based API.

Has anyone else has faced this problem? It goes away after restating my dyno on heroku.

rmosolgo commented 6 years ago

weird! could you tell me more about the error you're seeing? For example, does it happen while your app is starting up, or does it happen after it's running for a while? Can you share a stack trace? (I see this error during app boot sometimes)

fameoflight commented 6 years ago

This happened few times during app boot on Heroku.

Not sure if this was related, but I was using ruby 2.5.1 but for now I have switched back to 2.4.2 to see if it's the cause. Hasn't been a problem in last 24 hours but will keep you updated.

here is the stack trace it happens when executing query 

May 14 21:50:23 goodly app[web] info app/controllers/api/graphql_controller.rb:16:in `create'
May 14 21:50:23 goodly app[web] info   
May 14 21:50:23 goodly app[web] info RuntimeError (Duplicate type definition found for name 'Company' (CompanyType, CompanyType})):
fameoflight commented 6 years ago

@rmosolgo This seems to be happening more often with the upgrade. Any ideas on what might be causing this? Any fix or workarounds?

rmosolgo commented 6 years ago

No, I don't have any ideas. The three lines you shared above, is that the whole stack trace?

fameoflight commented 6 years ago

Yep that's what I see on Heroku

fameoflight commented 6 years ago

I haven't seen this problem in my tests. So unable to get a proper repro.

nater540 commented 6 years ago

I also have started to see this issue - it appears to happen (for me at least) if you attempt to perform two introspection queries, one after another.

Stack Trace

api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] RuntimeError (Duplicate type definition found for name 'DateTime' (, })):
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32]
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:161:in `visit'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:198:in `visit_field_on_type'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:178:in `block in visit_fields'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:177:in `each'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:177:in `visit_fields'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:136:in `visit'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:198:in `visit_field_on_type'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:178:in `block in visit_fields'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:177:in `each'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:177:in `visit_fields'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:136:in `visit'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:198:in `visit_field_on_type'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:178:in `block in visit_fields'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:177:in `each'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:177:in `visit_fields'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:136:in `visit'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:117:in `block in visit'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:117:in `each'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:117:in `visit'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/traversal.rb:36:in `initialize'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema.rb:955:in `new'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema.rb:955:in `rebuild_artifacts'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema.rb:271:in `types'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/validation.rb:134:in `block in <module:Rules>'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/validation.rb:19:in `block in validate'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/validation.rb:19:in `each'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/validation.rb:19:in `reduce'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema/validation.rb:19:in `validate'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/schema.rb:232:in `define'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] graphql (1.8.0) lib/graphql/define/instance_definable.rb:226:in `define'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] app/graphql/api_schema.rb:3:in `<main>'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] bootsnap (1.3.0) lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:100:in `load'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] bootsnap (1.3.0) lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:100:in `load'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/dependencies.rb:468:in `block in load_file'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/dependencies.rb:653:in `new_constants_in'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/dependencies.rb:467:in `load_file'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/dependencies.rb:365:in `block in require_or_load'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/dependencies.rb:37:in `block in load_interlock'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/dependencies/interlock.rb:14:in `block in loading'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/concurrency/share_lock.rb:151:in `exclusive'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/dependencies/interlock.rb:13:in `loading'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/dependencies.rb:37:in `load_interlock'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/dependencies.rb:348:in `require_or_load'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/dependencies.rb:502:in `load_missing_constant'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] bootsnap (1.3.0) lib/bootsnap/load_path_cache/core_ext/active_support.rb:43:in `load_missing_constant'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/dependencies.rb:193:in `const_missing'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/dependencies.rb:534:in `load_missing_constant'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] bootsnap (1.3.0) lib/bootsnap/load_path_cache/core_ext/active_support.rb:43:in `load_missing_constant'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/dependencies.rb:193:in `const_missing'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] app/controllers/api_controller.rb:33:in `graphql'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/abstract_controller/base.rb:194:in `process_action'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_controller/metal/rendering.rb:30:in `process_action'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/abstract_controller/callbacks.rb:42:in `block in process_action'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/callbacks.rb:132:in `run_callbacks'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/abstract_controller/callbacks.rb:41:in `process_action'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_controller/metal/rescue.rb:22:in `process_action'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/notifications.rb:168:in `block in instrument'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/notifications/instrumenter.rb:23:in `instrument'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/notifications.rb:168:in `instrument'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_controller/metal/instrumentation.rb:32:in `process_action'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activerecord (5.2.0) lib/active_record/railties/controller_runtime.rb:24:in `process_action'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/abstract_controller/base.rb:134:in `process'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_controller/metal.rb:191:in `dispatch'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_controller/metal.rb:252:in `dispatch'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_dispatch/routing/route_set.rb:34:in `serve'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_dispatch/journey/router.rb:52:in `block in serve'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_dispatch/journey/router.rb:35:in `each'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_dispatch/journey/router.rb:35:in `serve'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_dispatch/routing/route_set.rb:840:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] makara (0.4.0) lib/makara/middleware.rb:16:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] app/middleware/catch_json_parse_errors.rb:12:in `_call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] app/middleware/catch_json_parse_errors.rb:7:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] rack (2.0.5) lib/rack/deflater.rb:34:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] rack (2.0.5) lib/rack/lint.rb:49:in `_call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] rack (2.0.5) lib/rack/lint.rb:37:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] rack (2.0.5) lib/rack/etag.rb:25:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activerecord (5.2.0) lib/active_record/migration.rb:559:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/callbacks.rb:98:in `run_callbacks'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_dispatch/middleware/callbacks.rb:26:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_dispatch/middleware/executor.rb:14:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] railties (5.2.0) lib/rails/rack/logger.rb:38:in `call_app'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] railties (5.2.0) lib/rails/rack/logger.rb:26:in `block in call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/tagged_logging.rb:71:in `block in tagged'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/tagged_logging.rb:28:in `tagged'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/tagged_logging.rb:71:in `tagged'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] railties (5.2.0) lib/rails/rack/logger.rb:26:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] request_store (1.4.1) lib/request_store/middleware.rb:19:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_dispatch/middleware/request_id.rb:27:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] rack (2.0.5) lib/rack/runtime.rb:22:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] actionpack (5.2.0) lib/action_dispatch/middleware/executor.rb:14:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] honeybadger (3.3.0) lib/honeybadger/rack/error_notifier.rb:33:in `block in call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] honeybadger (3.3.0) lib/honeybadger/agent.rb:337:in `with_rack_env'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] honeybadger (3.3.0) lib/honeybadger/rack/error_notifier.rb:30:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] honeybadger (3.3.0) lib/honeybadger/rack/user_feedback.rb:31:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] honeybadger (3.3.0) lib/honeybadger/rack/user_informer.rb:21:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] rack-cors (1.0.2) lib/rack/cors.rb:97:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] railties (5.2.0) lib/rails/engine.rb:524:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] puma (3.11.4) lib/puma/configuration.rb:225:in `call'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] puma (3.11.4) lib/puma/server.rb:632:in `handle_request'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] puma (3.11.4) lib/puma/server.rb:446:in `process_client'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] puma (3.11.4) lib/puma/server.rb:306:in `block in run'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] puma (3.11.4) lib/puma/thread_pool.rb:120:in `block in spawn_thread'
rmosolgo commented 6 years ago

Interesting! Thanks for reporting with a full stack trace, that's really helpful. Now let me think about it for a minute...

rmosolgo commented 6 years ago

One thing that stands out to me is this line: 

api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] app/graphql/api_schema.rb:3:in `<main>'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] bootsnap (1.3.0) lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:100:in `load'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] bootsnap (1.3.0) lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:100:in `load'
api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] activesupport (5.2.0) lib/active_support/dependencies.rb:468:in `block in load_file'

Those are lines related in loading missing constants, that is, ApiSchema didn't exist yet, so Rails went and loaded those files.

Does this usually happen at app boot, or does it happen at random times, while the app is running?

jcbpl commented 6 years ago

Might be related: I got this error this when I added an enum named TargetType to a schema that already had an object named Target:

class Graph::Enums::TargetType < GraphQL::Schema::Enum
  # ...
end

class Graph::Objects::Target < GraphQL::Schema::Object
  # ...
end

The fix was to add graphql_name 'TargetType' to the enum, presumably because 1.8 was stripping 'Type' from the generated type name.

rmosolgo commented 6 years ago

Also, taking a look at this line: 

api_1    | [4fd823c6-855e-4302-b545-c74c46017b32] puma (3.11.4) lib/puma/thread_pool.rb:120:in `block in spawn_thread'

Are you using puma with many threads?

rmosolgo commented 6 years ago

(I wonder if the application boots, without loading ApiSchema, and then two threads both start loading those constants, but encounter a race condition, both trying to load the same types. But I'm not sure about that, because I think active_support/dependencies has mutexes to prevent that ...)

nater540 commented 6 years ago

@rmosolgo

Does this usually happen at app boot, or does it happen at random times, while the app is running?

Random times. I can generally perform one or two queries before this happens, although running the introspection query will instantly generate the error.

Initial startup log

api_1    | Puma starting in single mode...
api_1    | * Version 3.11.4 (ruby 2.4.4-p296), codename: Love Song
api_1    | * Min threads: 5, max threads: 5
api_1    | * Environment: development
api_1    | ** [Honeybadger] Initializing Honeybadger Error Tracker for Ruby. Ship it! version=3.3.0 framework=rails level=1 pid=7
api_1    | ** [Honeybadger] Development mode is enabled. Data will not be reported until you deploy your app. level=2 pid=7
api_1    | * Listening on tcp://0.0.0.0:3000
api_1    | Use Ctrl-C to stop

(also answers your threading question)

Here is the entire API schema file

GraphQL::Relay::ConnectionType.default_nodes_field = true

class ApiSchema < GraphQL::Schema
  query(Types::QueryType)
  mutation(Types::MutationType)

  max_depth(8)
  max_complexity(220)
  authorization(:pundit)

  instrument(:field, AssociationPreloadInstrumentation.new)

  use(GraphQL::Batch)

  rescue_from(ActiveRecord::RecordInvalid) do |error|
    'Some data could not be saved'
  end

  rescue_from(ActiveRecord::StatementInvalid) do |error|
    Honeybadger.notify(error)
    'An error has occurred and support has been notified. Thank you for your continued patience.'
  end

  rescue_from(ActiveRecord::RecordNotFound) do |error|
    'Could not find the record'
  end

  rescue_from(ActiveRecord::RecordNotUnique) do |error|
    'Some data could not be saved'
  end

  rescue_from(ActiveRecord::Rollback) do |error|
    'Some data could not be saved'
  end

  def self.id_from_object(object, type, ctx)
    GraphQL::Schema::UniqueWithinType.encode(
      type_definition.name,
      object.id,
      separator: '---'
    )
  end

  def self.object_from_id(node_id, ctx)
    type_name, object_id = GraphQL::Schema::UniqueWithinType.decode(
      node_id,
      separator: '---'
    )
    RecordLoader.for(type_name).load(object_id)
  end

  def self.resolve_type(type, obj, ctx)
    type_name = obj.class.name.split('::').last
    ApiSchema.types[type_name]
  end
end

# The following line will enable graphql-ruby to provide real values for reverse-direction has*Page checks.
# This will become the default behavior in a future graphql-ruby version.
# (But it is not the default behavior now because it has performance implications.)
# @see https://github.com/rmosolgo/graphql-ruby/pull/960
#
GraphQL::Relay::ConnectionType.bidirectional_pagination = true

GraphQL::Relay::BaseConnection.register_connection_implementation(
  ActiveRecord::Relation, GraphQL::Relay::RelationConnection
)

Side note, I just updated this to the class based style a few minutes ago and the error still occurs.

@jcbpl

The fix was to add graphql_name 'TargetType' to the enum, presumably because 1.8 was stripping 'Type' from the generated type name.

As of now I've only upgraded the schema to a class, but I wonder if this is still happening. Thanks for the advice, I'll go poke around and see what I can discover.

nater540 commented 6 years ago

@jcbpl

Tried using graphql_name as you suggested, unfortunately GraphQL still fails; however at least the error message makes slightly more sense!

RuntimeError (Duplicate type definition found for name 'DateTimeType' (Types::DateTime, Types::DateTime}))

For reference, this is the DateTimeType in its entire glory

class Types::DateTime < Types::BaseScalar
  graphql_name 'DateTimeType'
  description 'An ISO-8601 encoded UTC date string.'

  def self.coerce_input(input_value, context)
    Time.iso8601(input_value).gmtime
  end

  def self.coerce_result(ruby_value, context)
    ruby_value.utc.iso8601
  end
end

I have a sneaking suspicion that @rmosolgo is on the right track with this issue (at least in my case) being a race condition - I just wish debugging Ruby inside a Docker container wasn't the equivalent of pulling your own teeth without anesthetic :grimacing:

rmosolgo commented 6 years ago

I see in the startup log:

Development mode is enabled.

Is this in development, or after deploying?

(I think @fameoflight 's issue was in production, on heroku)

nater540 commented 6 years ago

@rmosolgo

Is this in development, or after deploying?

Development; I have not pushed these changes to k8s - want to get rid of this error before I test 1.8 on production.

fameoflight commented 6 years ago

I also see this in development.

And yes I am using puma with multiple threads on prod and development.

nater540 commented 6 years ago

Deployed the 1.8 branch that has been crashing in development to a beta endpoint and it appears fine -- same docker image, puma config, etc.

NAME                   READY     STATUS    RESTARTS   AGE
api-684466ddf8-f4bw9   1/1       Running   0          2d
api-684466ddf8-hfsd8   1/1       Running   0          2d
api-684466ddf8-lxpcj   1/1       Running   0          2d

@fameoflight - do you have a development stack trace?

@rmosolgo - any chance you've had an epiphany on what might be the cause?

buffpojken commented 6 years ago

Seeing this as well.

fameoflight commented 6 years ago

@rmosolgo I can share my sentry stack trace in private let me know if it would be helpful

fameoflight commented 6 years ago 
RuntimeError: Duplicate type definition found for name 'User' (User::GraphqlType, User::GraphqlType})
  from graphql/schema/traversal.rb:161:in `visit'
  from graphql/schema/traversal.rb:198:in `visit_field_on_type'
  from graphql/schema/traversal.rb:178:in `block in visit_fields'
  from graphql/schema/traversal.rb:177:in `each'
  from graphql/schema/traversal.rb:177:in `visit_fields'
  from graphql/schema/traversal.rb:136:in `visit'
  from graphql/schema/traversal.rb:198:in `visit_field_on_type'
  from graphql/schema/traversal.rb:178:in `block in visit_fields'
  from graphql/schema/traversal.rb:177:in `each'
  from graphql/schema/traversal.rb:177:in `visit_fields'
  from graphql/schema/traversal.rb:136:in `visit'
  from graphql/schema/traversal.rb:198:in `visit_field_on_type'
  from graphql/schema/traversal.rb:178:in `block in visit_fields'
  from graphql/schema/traversal.rb:177:in `each'
  from graphql/schema/traversal.rb:177:in `visit_fields'
  from graphql/schema/traversal.rb:136:in `visit'
  from graphql/schema/traversal.rb:198:in `visit_field_on_type'
  from graphql/schema/traversal.rb:178:in `block in visit_fields'
  from graphql/schema/traversal.rb:177:in `each'
  from graphql/schema/traversal.rb:177:in `visit_fields'
  from graphql/schema/traversal.rb:136:in `visit'
  from graphql/schema/traversal.rb:198:in `visit_field_on_type'
  from graphql/schema/traversal.rb:178:in `block in visit_fields'
  from graphql/schema/traversal.rb:177:in `each'
  from graphql/schema/traversal.rb:177:in `visit_fields'
  from graphql/schema/traversal.rb:136:in `visit'
  from graphql/schema/traversal.rb:117:in `block in visit'
  from graphql/schema/traversal.rb:117:in `each'
  from graphql/schema/traversal.rb:117:in `visit'
  from graphql/schema/traversal.rb:36:in `initialize'
  from graphql/schema.rb:955:in `new'
  from graphql/schema.rb:955:in `rebuild_artifacts'
  from graphql/schema.rb:270:in `types'
  from graphql/schema/possible_types.rb:16:in `initialize'
  from graphql/schema.rb:180:in `new'
  from graphql/schema.rb:180:in `initialize_copy'
  from graphql/define/instance_definable.rb:129:in `initialize_dup'
  from graphql/define/instance_definable.rb:129:in `dup'
  from graphql/define/instance_definable.rb:129:in `redefine'
  from graphql/schema.rb:719:in `to_graphql'
  from graphql/schema/member/accepts_definition.rb:120:in `to_graphql'
  from graphql/schema.rb:668:in `graphql_definition'
  from forwardable.rb:223:in `execute'
  from app/controllers/api/internal/graphql_controller.rb:16:in `create'
  from action_controller/metal/basic_implicit_render.rb:6:in `send_action'
  from abstract_controller/base.rb:194:in `process_action'
  from action_controller/metal/rendering.rb:30:in `process_action'
  from abstract_controller/callbacks.rb:42:in `block in process_action'
  from active_support/callbacks.rb:109:in `block in run_callbacks'
  from raven/integrations/rails/controller_transaction.rb:7:in `block in included'
  from active_support/callbacks.rb:118:in `instance_exec'
  from active_support/callbacks.rb:118:in `block in run_callbacks'
  from active_support/callbacks.rb:136:in `run_callbacks'
  from abstract_controller/callbacks.rb:41:in `process_action'
  from action_controller/metal/rescue.rb:22:in `process_action'
  from action_controller/metal/instrumentation.rb:34:in `block in process_action'
  from active_support/notifications.rb:168:in `block in instrument'
  from active_support/notifications/instrumenter.rb:23:in `instrument'
  from active_support/notifications.rb:168:in `instrument'
  from action_controller/metal/instrumentation.rb:32:in `process_action'
  from action_controller/metal/params_wrapper.rb:256:in `process_action'
  from active_record/railties/controller_runtime.rb:24:in `process_action'
  from abstract_controller/base.rb:134:in `process'
  from action_view/rendering.rb:32:in `process'
  from action_controller/metal.rb:191:in `dispatch'
  from action_controller/metal.rb:252:in `dispatch'
  from action_dispatch/routing/route_set.rb:52:in `dispatch'
  from action_dispatch/routing/route_set.rb:34:in `serve'
  from action_dispatch/journey/router.rb:52:in `block in serve'
  from action_dispatch/journey/router.rb:35:in `each'
  from action_dispatch/journey/router.rb:35:in `serve'
  from action_dispatch/routing/route_set.rb:840:in `call'
  from omniauth/strategy.rb:190:in `call!'
  from omniauth/strategy.rb:168:in `call'
  from omniauth/builder.rb:63:in `call'
  from rack/throttle/limiter.rb:35:in `call'
  from rack/deflater.rb:34:in `call'
  from warden/manager.rb:36:in `block in call'
  from warden/manager.rb:35:in `catch'
  from warden/manager.rb:35:in `call'
  from rack/tempfile_reaper.rb:15:in `call'
  from rack/etag.rb:25:in `call'
  from rack/conditional_get.rb:38:in `call'
  from rack/head.rb:12:in `call'
  from action_dispatch/http/content_security_policy.rb:18:in `call'
  from rack/session/abstract/id.rb:232:in `context'
  from rack/session/abstract/id.rb:226:in `call'
  from action_dispatch/middleware/cookies.rb:670:in `call'
  from action_dispatch/middleware/callbacks.rb:28:in `block in call'
  from active_support/callbacks.rb:98:in `run_callbacks'
  from action_dispatch/middleware/callbacks.rb:26:in `call'
  from action_dispatch/middleware/debug_exceptions.rb:61:in `call'
  from action_dispatch/middleware/show_exceptions.rb:33:in `call'
  from lograge/rails_ext/rack/logger.rb:15:in `call_app'
  from rails/rack/logger.rb:28:in `call'
  from action_dispatch/middleware/remote_ip.rb:81:in `call'
  from request_store/middleware.rb:19:in `call'
  from rack/timeout/core.rb:123:in `block in call'
  from rack/timeout/support/timeout.rb:19:in `timeout'
  from rack/timeout/core.rb:122:in `call'
  from action_dispatch/middleware/request_id.rb:27:in `call'
  from rack/method_override.rb:22:in `call'
  from rack/runtime.rb:22:in `call'
  from rack/timeout/core.rb:123:in `block in call'
  from rack/timeout/support/timeout.rb:19:in `timeout'
  from rack/timeout/core.rb:122:in `call'
  from active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
  from action_dispatch/middleware/executor.rb:14:in `call'
  from action_dispatch/middleware/static.rb:127:in `call'
  from rack/sendfile.rb:111:in `call'
  from rack/cors.rb:97:in `call'
  from raven/integrations/rack.rb:51:in `call'
  from rails/engine.rb:524:in `call'
  from puma/configuration.rb:225:in `call'
  from puma/server.rb:632:in `handle_request'
  from puma/server.rb:446:in `process_client'
  from puma/server.rb:306:in `block in run'
  from puma/thread_pool.rb:120:in `block in spawn_thread'
rmosolgo commented 6 years ago

If anyone wants to debug this in development, here's one approach you can take. Add this initializer:

https://gist.github.com/rmosolgo/4eba313cb21189d952152ce3f1a6135a

Then restart rails, replicate the error, and share the log. Maybe it will give some clue to how constants are being loaded.

rmosolgo commented 6 years ago

By the way, I was working this out with @nater540 over email and got to the root of the problem.

In this particular case, there was an initializer which made a reference to one of the GraphQL types. Later, after the GraphQL type was reloaded, there was a conflict, because on one side, the stale type (from the initializer) was being used in the schema, but elsewhere, the newly-reloaded type was being used. Since those classes are different Ruby objects, they can't be used for the same GraphQL type.

The solution was to move the initializer code into my_schema.rb, so that it would be re-evalutated whenever the schema was reloaded.

If you want to do similar debugging, see my previous comment: https://github.com/rmosolgo/graphql-ruby/issues/1505#issuecomment-398783287

adventCloud commented 6 years ago

@rmosolgo I also encountered this same issue. I have been battling this for quite a while and I am out of ideas. I created a class called mutation and another called query and I give those to the schema. Since I will have multiple models in my backend, I decided to structure my mutations the same way so I broke them into files.

Now I have something like this. https://gist.github.com/adventCloud/1b7171c484f4ccb23188971febfacfca

This happens randomly and only restarting the server seems to fix it, sometimes. Sometimes it says there are duplicate PostInput definitions, other times its UserInput, Other times Its QueryType, and sometimes its a fix of a few.

I get the same traceback. It hits traversal.rb

What would you suggest I do to debug this issue further? I tried your initializer you advised to use, but it only runs on server start, or rails console. but when it breaks, nothing gets logged. I also checked all my initializer files, and there is no references to Graphql types.

rmosolgo commented 6 years ago

Did you try the debug suggestion in https://github.com/rmosolgo/graphql-ruby/issues/1505#issuecomment-398783287 ?

adventCloud commented 6 years ago

I did but I only get output on server restart or on rails console and I don’t see any graphql constants

justisb commented 6 years ago

I recently refactored my project to the 1.8 Class Syntax and have been running into the same issue in production as well. It semi-randomly occurs to pretty much any GraphQL type, with errors like these:

RuntimeError: Duplicate type definition found for name 'Restaurant' at 'Field User.adminRestaurants's return type' (GraphType::RestaurantType, GraphType::RestaurantType)

RuntimeError: Duplicate type definition found for name 'Photo' at 'Field MenuItem.photos's return type' (GraphType::PhotoType, GraphType::PhotoType)

... seemingly all other types

Some attempted solutions so far:

  1. Add /app/graphql directory to eager_load_paths in application.rb

Seemingly no effect.

  1. Refactor all GraphQL Types referenced in field definitions from classes to strings that are constantized later on

Alongside this solution I tried patching the BuildType#parse_type method with alternate Object.get_const vs .constantize method calls for handling the string types- neither seemed to have an effect.

  1. Refactor all Types under an alternate namespace (e.g., GraphType:: rather than Types::)

Seemingly no effect (same errors with a different module name).

  1. Remove Traversal#visit prev_type equality check

I just deployed this hack to get the random errors to stop. I'm expecting there to be some side-effect, such as a memory leak or something.

Any other suggestions would be appreciated.

justisb commented 6 years ago

Over the last six hours and ~90k user sessions since disabling the duplicate type error I have not really seen any adverse effects. I'll dive deeper into the cause of the error next weekend, if nobody else has any additional insights by then.

fameoflight commented 6 years ago

@justisb any way you can share a small repo or gist of your changes?

@rmosolgo wondering if you have any opinions for fixes posted by @justisb

justisb commented 6 years ago

Here's the fork of graphql-ruby I'm running currently, I don't really think this is a fix so much as it's masking the symptoms though: https://github.com/rmosolgo/graphql-ruby/compare/master...justisb:parse-type-three

rmosolgo commented 6 years ago

Disabling that error might work, but it means that the same graphql type is represented by more than one Ruby object, so it could result in some pretty weird behaviors if those Ruby objects are different at all.

Again, if anyone wants to debug in development, my recommendation is here: https://github.com/rmosolgo/graphql-ruby/issues/1505#issuecomment-398783287

justisb commented 6 years ago

I haven't been able to reproduce the issue in development, it only occurs in production (Rails on Puma on Heroku).

rmosolgo commented 6 years ago

😖

bessey commented 6 years ago

Joining the Party, we went from 1.7.X > 1.8.5 and ever since have occasional batches of exceptions

rmosolgo commented 6 years ago

Also Heroku?

justisb commented 6 years ago

Perhaps a compromise for now could be changing prev_type.equal? from a strict equality to only checking if the type names are the same. And/or logging a "proceed at your own risk" warning rather than throwing an exception.

FWIW since disabling the error I haven't seen any unusual exceptions and the memory curves for each of my instances has been normal. Though I agree it's still indicative that something strange is going on, particularly since it's so infrequent/random. Perhaps some threading related issue.

bessey commented 6 years ago

@rmosolgo no, AWS EC2 + Nginx + Passenger Enterprise.

Things worth noting: I have only converted one type to the 1.8 syntax, and that type just so happens to be the only type causing issues. (Edit, actually I've also upgraded the schema itself to be 1.8)

Example failure https://gist.github.com/bessey/9ea70d8a9127c28adf680524c4ec28ef

It also happens on a single machine in a fleet of I think 4-8, and a restart alleviates the problem (till it comes back).

The passenger instances are configured for multithreaded, so definitely room for race condition induced bugs there.

All signs point to something around constant loading.

rmosolgo commented 6 years ago

one type to the 1.8 syntax, and ... I've also upgraded the schema itself to be 1.8

Interesting!

Thanks for sharing that backtrace. Here's one clue that stood out to me: 

  from graphql/schema.rb:729:in `to_graphql'
  from graphql/schema/member/accepts_definition.rb:120:in `to_graphql'
  from graphql/schema.rb:677:in `graphql_definition'
from /home/usr.local/ruby251/lib/ruby/2.5.0/forwardable.rb:223:in `multiplex'

Schema.graphql_definition was called, and instead of finding a cached @graphql_definition, it's re-converting everything using the .to_graphql method. 🤔 It could be that two threads are doing that work at the same time an-- wait, but wouldn't they find the same classes ...

Well, one thing you could try is to eagerly cause the schema to run that transformation, for example at the end of your schema file, call .graphql_definition on it: 

class MySchema < GraphQL::Schema 
  # ... 
end 

# This processes the schema members and makes some caches on the schema, 
# maybe it's subject to a race condition? 
# So eagerly warm that cache at load time: 
MySchema.graphql_definition

That way, by the time that the server starts handling requests, that work will be done already. Want to give it a spin?

fameoflight commented 6 years ago

Tests pass giving it a try on prod now at www.goodlyapp.com

bessey commented 6 years ago

We're trialing this in production now. I'll keep you posted, though we've been running 1.8 for about a week now and the bug has only manifested twice, so expect radio silence for a bit wether or not its fixed.

In the meantime since this hasn't thus far affected more than one server at a time, I'm thinking of adding GraphQL::Schema::Printer.print_schema(schema) to our PingController, so that bad servers get taken out of the pool automatically by our load balancer's health check mechanism.

bessey commented 6 years ago

We've had no problems since adding the MySchema.graphql_definition code, so I think its safe to say that dramatically shrunk if not stopped the edge case occurring.

A question for others experiencing the bug: is anyone still having troubles who is all in on the 1.8 syntax? I'm assuming the edge case involves a mix of 1.8 + pre-1.8 syntax in a single schema, though I have no proof.

justisb commented 6 years ago

@bessey I did a hard cut from the old syntax fully to the 1.8 syntax, so no mixed usage, and started experiencing the error.

I haven't tried the pre-warming .graphql_definition fix yet.

nater540 commented 6 years ago

Just started experiencing this issue again; unfortunately it is starting to occur on production and not just development like before (at least for me) Backtrace available here => https://pastebin.com/2x8FS4vR

Update Just deployed the graphql_definition suggestion that @rmosolgo made above, so fingers crossed that fixes the issue.

fameoflight commented 6 years ago

@rmosolgo I have been using graphql_definition haven't experienced a single problem for one week. So I think I will be good for now.

I am not sure if I had to remove bootsnap as well. So if you are still having problem try removing bootsnap.

such commented 6 years ago

For what it's worth, this issue appeared for me when I switched from ruby 2.3.1 to 2.5.1. This confirms @fameoflight experience.

fameoflight commented 6 years ago

@such you will still see them in Ruby 2.3.1 was less frequently. You should try the workaround hasn't been a problem for us at Goodly (www.goodlyapp.com) for past 2 weeks.

justisb commented 6 years ago

Another similar update- after implementing the Schema.graphql_definition traversal warmup trick, we're also no longer experiencing any mismatched/duplicate type errors.

jonleighton commented 6 years ago

We've also experienced this issue at the company I work for. It's a pretty severe bug -- it put one of our production containers into a state where all GraphQL requests experienced an exception.

We're implementing the Schema.graphql_definition workaround, and will report back if that doesn't work.

I took a bit of a look through the code. It seems pretty clear that the code which Schema.graphql_definition is not thread-safe in lots of ways. For example, the @rebuilding_artifacts boolean here is obviously not thread-safe and could cause an exception if two thread call into that method at the same time (one thread sets the boolean to true, then when the other thread calls the method, the exception is raised):

https://github.com/rmosolgo/graphql-ruby/blob/368e68a3979c8a7453f6a7466ff80d401fbede68/lib/graphql/schema.rb#L1031-L1048

However, the actual error discussed here is in traversal.rb. It happens when the previously-defined type name doesn't match the type definition we're currently visiting. I didn't manage to figure out exactly why this happens, but some things I noticed were:

It would likely be hard to make all this code thread-safe. I think it would be a sensible solution for GraphQL::Railtie to ensure that the schema definition is generated up-front when Rails' eager-loading occurs. (Which is effectively what we're doing with the workaround that has been suggested, except it's also happening when eager-loading is not used too.)

rmosolgo commented 6 years ago

Thanks for the write-up! I was also thinking a thread-safety issue.

@jonleighton in the case of:

if I do MySchema.types["MyType"] == MyTypeDefinition I get a false

is MyTypeDefinition a class? If so, you could try: 

MySchema.types["MyType"] == MyTypeDefinition.graphql_definition

.graphql_definition converts the (new-style) class to a (legacy-style) GraphQL::ObjectType instance. (Actually, it returns the cached value of that conversion.)

My guess is that, since the cache of .graphql_definition on each type is not threadsafe, that each type class is being converted on each thread, then those values don't match.

Sometime this year, I want to refactor the legacy-style type objects out of the system, so that's how I plan to solve this problem.

I think we never noticed it at GitHub because of how we use GraphQL-Client. It forces the schema to be eagerly loaded, like you mentioned using a Railtie to do.

bbugh commented 5 years ago

We were just having this issue with a new production launch, every time we'd restart the server a few minutes later we'd have calamitous uprising of 500 errors. Pushed the warmup workaround and it hasn't been a problem since. Maybe this could be automated somehow until the thread safety issue is resolved?