Graphql-ruby: Code Reloading w/ Rails in Development

Created on 31 Mar 2017  路  37Comments  路  Source: rmosolgo/graphql-ruby

Using some of the very basic examples I'm running into an issue where query execution would hang whenever I change code in development. And even if I don't change code, on all subsequent requests I would get the error LoadError (Unable to autoload constant Types::QueryType, expected /Users/randuin/code/pw/pwpback/app/graphql/types/query_type.rb to define it):

picture Randuin
👍5

Most helpful comment

I'm not a very sophisticated debugger, here's what I did:

  • Add some puts to the controller, but discover that it _is not_ called, so the hang is _before_ the controller action.

  • Use two middlewares to prove that ActiveSupport::Reloader was hanging (I had this clue from your logs above) 

    class WhatTheHeckMiddleware 
 def initialize(app, opts = {}) 
   @app = app 
   @idx = opts[:idx]
 end 

 # Just log when this middleware starts and ends
 def call(env) 
   puts "~~ START #{@idx} ~~"
   res = @app.call(env)
   puts "~~ END #{@idx} ~~"
   res 
 end 
end 

# ... 
config.middleware.insert_before(ActiveSupport::Reloader, WhatTheHeckMiddleware, { idx: 1 })
config.middleware.insert_after(ActiveSupport::Reloader, WhatTheHeckMiddleware, { idx: 2 })
  • Replicate the hang, and observe that ~~ START 2 ~~ is not present in the log, which means that the hang is during ActiveSupport::Reloader.

  • I know that the issue is with ActiveSupport::Dependencies, so I just logged _all_ the methods on that module 馃槄 

    module ActiveSupport::Dependencies 
 methods.each do |method_name|  
 method_body = method(method_name)
 define_singleton_method(method_name) do |*args, &block| 
   puts "ActiveSupport::Dependencies.#{method_name}(#{args.join(",")} #{block ? "&block" : ""})"
   method_body.call(*args, &block)
 end 
end
  • Fortunately, the infinite loop was pretty tight, and remove_constant stood out. I spent a long time reading ActiveSupport::Dependencies, trying to understand what went wrong, but I couldn't. So I applied the Set-based monkey patch which I posted above and it worked. Out of curiosity, I inspected ActiveSupport::Dependencies.autoloaded_constants. During a hang, this Array contained duplicate entries for Types and Mutations, but I don't know why. I tried to read the source, but I couldn't make sense of it 馃槚

So in the end, I can't really _fix_ it, but I can prevent it!

https://github.com/rmosolgo/graphql-ruby/pull/665

picture rmosolgo on 8 Apr 2017
👍10

All 37 comments

I had a similar problem, so I tried to fix it in #632 . I just pushed 1.5.5 which includes the fix, could you try that version?

rmosolgo picture rmosolgo on 31 Mar 2017

I upgraded to 1.5.5, and it still hang when code changed.

cpunion picture cpunion on 3 Apr 2017

馃槚 I'm sorry to hear that. I wonder if it's the same bug or a different one. Could you help me debug a bit? It would be really helpful to me if you could capture the _entire_ terminal output from:

  • Starting the Rails server
  • Replicating the issue, until it hangs

(The _entire_ output would be helpful because, in my case, the hang was caused by a _previous_ error)

Also, could you share your Rails version?

rmosolgo picture rmosolgo on 3 Apr 2017

Some environments relation to graphql:

ruby 2.3.1p112 (2016-04-26 revision 54768) [x86_64-darwin16]
rails (5.0.1)
graphql (1.5.5)
graphiql-rails (1.4.1)

A shortest hang log:

$ bundle exec rails s -b 0.0.0.0
=> Booting Puma
=> Rails 5.0.1 application starting in development on http://0.0.0.0:3000
=> Run `rails server -h` for more startup options
Puma starting in single mode...
* Version 3.7.0 (ruby 2.3.1-p112), codename: Snowy Sagebrush
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://0.0.0.0:3000
Use Ctrl-C to stop
Started GET "/graphiql" for 127.0.0.1 at 2017-04-03 17:18:47 +0800
  ActiveRecord::SchemaMigration Load (0.3ms)  SELECT "schema_migrations".* FROM "schema_migrations"
Processing by GraphiQL::Rails::EditorsController#show as HTML
  Parameters: {"graphql_path"=>"/graphql"}
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/graphiql-rails-1.4.1/app/views/graphiql/rails/editors/show.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/graphiql-rails-1.4.1/app/views/graphiql/rails/editors/show.html.erb (535.0ms)
Completed 200 OK in 594ms (Views: 575.4ms | ActiveRecord: 0.0ms)


Started POST "/graphql" for 127.0.0.1 at 2017-04-03 17:18:48 +0800
Processing by GraphqlController#execute as */*
  Parameters: {"query"=>"\n  query IntrospectionQuery {\n    __schema {\n      queryType { name }\n      mutationType { name }\n      subscriptionType { name }\n      types {\n        ...FullType\n      }\n      directives {\n        name\n        description\n        locations\n        args {\n          ...InputValue\n        }\n      }\n    }\n  }\n\n  fragment FullType on __Type {\n    kind\n    name\n    description\n    fields(includeDeprecated: true) {\n      name\n      description\n      args {\n        ...InputValue\n      }\n      type {\n        ...TypeRef\n      }\n      isDeprecated\n      deprecationReason\n    }\n    inputFields {\n      ...InputValue\n    }\n    interfaces {\n      ...TypeRef\n    }\n    enumValues(includeDeprecated: true) {\n      name\n      description\n      isDeprecated\n      deprecationReason\n    }\n    possibleTypes {\n      ...TypeRef\n    }\n  }\n\n  fragment InputValue on __InputValue {\n    name\n    description\n    type { ...TypeRef }\n    defaultValue\n  }\n\n  fragment TypeRef on __Type {\n    kind\n    name\n    ofType {\n      kind\n      name\n      ofType {\n        kind\n        name\n        ofType {\n          kind\n          name\n          ofType {\n            kind\n            name\n            ofType {\n              kind\n              name\n              ofType {\n                kind\n                name\n                ofType {\n                  kind\n                  name\n                }\n              }\n            }\n          }\n        }\n      }\n    }\n  }\n", "graphql"=>{"query"=>"\n  query IntrospectionQuery {\n    __schema {\n      queryType { name }\n      mutationType { name }\n      subscriptionType { name }\n      types {\n        ...FullType\n      }\n      directives {\n        name\n        description\n        locations\n        args {\n          ...InputValue\n        }\n      }\n    }\n  }\n\n  fragment FullType on __Type {\n    kind\n    name\n    description\n    fields(includeDeprecated: true) {\n      name\n      description\n      args {\n        ...InputValue\n      }\n      type {\n        ...TypeRef\n      }\n      isDeprecated\n      deprecationReason\n    }\n    inputFields {\n      ...InputValue\n    }\n    interfaces {\n      ...TypeRef\n    }\n    enumValues(includeDeprecated: true) {\n      name\n      description\n      isDeprecated\n      deprecationReason\n    }\n    possibleTypes {\n      ...TypeRef\n    }\n  }\n\n  fragment InputValue on __InputValue {\n    name\n    description\n    type { ...TypeRef }\n    defaultValue\n  }\n\n  fragment TypeRef on __Type {\n    kind\n    name\n    ofType {\n      kind\n      name\n      ofType {\n        kind\n        name\n        ofType {\n          kind\n          name\n          ofType {\n            kind\n            name\n            ofType {\n              kind\n              name\n              ofType {\n                kind\n                name\n                ofType {\n                  kind\n                  name\n                }\n              }\n            }\n          }\n        }\n      }\n    }\n  }\n"}}
  User Load (0.3ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = ? ORDER BY "users"."id" ASC LIMIT ?  [["id", 1], ["LIMIT", 1]]
Completed 500 Internal Server Error in 132ms (ActiveRecord: 2.8ms)



GraphQL::Schema::InvalidTypeError (Mutation is invalid: field "createShared" type must return GraphQL::BaseType, not NilClass (nil)):

app/graphql/api_schema.rb:1:in `<top (required)>'
app/controllers/graphql_controller.rb:21:in `execute'
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.1/lib/action_dispatch/middleware/templates/rescues/diagnostics.html.erb within rescues/layout
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.1/lib/action_dispatch/middleware/templates/rescues/_source.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.1/lib/action_dispatch/middleware/templates/rescues/_source.html.erb (4.5ms)
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.1/lib/action_dispatch/middleware/templates/rescues/_trace.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.1/lib/action_dispatch/middleware/templates/rescues/_trace.html.erb (2.3ms)
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.1/lib/action_dispatch/middleware/templates/rescues/_request_and_response.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.1/lib/action_dispatch/middleware/templates/rescues/_request_and_response.html.erb (1.3ms)
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.1/lib/action_dispatch/middleware/templates/rescues/diagnostics.html.erb within rescues/layout (119.6ms)
Started GET "/graphiql" for 127.0.0.1 at 2017-04-03 17:27:06 +0800
^CExiting

Then it hung. I run dtruss to watch what is it doing, the dtruss log at: https://gist.github.com/cpunion/10ef55375362cde05126b32dd6cd4d62, seems it dead loop to load some modules.

It's not same with @Randuin 's issue.

cpunion picture cpunion on 3 Apr 2017

I try to reproduce @Randuin 's issue, and now it didn't hang, just report LoadError.

cpunion picture cpunion on 3 Apr 2017

Thanks, that's really helpful! I think the cause may be similar: an error during the .define { ... } call. But Schema#define is a bit special since it's eagerly evaluated. Let me take a look at that!

rmosolgo picture rmosolgo on 3 Apr 2017

Oh, hung again. I added resolve to a scalar type to reproduce the issue above, then I remove it and reload graphiql, it hung again.

cpunion picture cpunion on 3 Apr 2017

Great! thanks. (restarted tens today 馃槃 )

cpunion picture cpunion on 3 Apr 2017

Hmm... I tried a simple case to reproduce the error you posted above:

Types::MutationType = GraphQL::ObjectType.define do
  name "Mutation"
  field :invalid do
    type(nil)
  end
end

But it didn't cause the server to hang. I was able to modify the Ruby file & successfully re-send the query.

Could you share the source of your schema and one of the files that has a validation error?

rmosolgo picture rmosolgo on 4 Apr 2017

I created a repo to reproduce https://github.com/cpunion/reproduce_graphql_hang

Steps:

  1. checkout the second commit: https://github.com/cpunion/reproduce_graphql_hang/commit/e94dc76831d838b9acd019b7529f1863bba98b1f, it has some wrong code.
  2. Run bundle install, and rails s
  3. Open http://localhost:3000/graphiql in browser
  4. Now you can see the error below:
rails s -b 0.0.0.0 -p 3333
=> Booting Puma
=> Rails 5.0.2 application starting in development on http://0.0.0.0:3333
=> Run `rails server -h` for more startup options
Puma starting in single mode...
* Version 3.8.2 (ruby 2.3.1-p112), codename: Sassy Salamander
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://0.0.0.0:3333
Use Ctrl-C to stop
Started GET "/graphiql" for 127.0.0.1 at 2017-04-04 11:40:41 +0800
Processing by GraphiQL::Rails::EditorsController#show as HTML
  Parameters: {"graphql_path"=>"/graphql"}
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/graphiql-rails-1.4.1/app/views/graphiql/rails/editors/show.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/graphiql-rails-1.4.1/app/views/graphiql/rails/editors/show.html.erb (266.8ms)
Completed 200 OK in 291ms (Views: 278.3ms | ActiveRecord: 0.0ms)


Started POST "/graphql" for 127.0.0.1 at 2017-04-04 11:40:42 +0800
Processing by GraphqlController#execute as */*
  Parameters: {"query"=>"\n  query IntrospectionQuery {\n    __schema {\n      queryType { name }\n      mutationType { name }\n      subscriptionType { name }\n      types {\n        ...FullType\n      }\n      directives {\n        name\n        description\n        locations\n        args {\n          ...InputValue\n        }\n      }\n    }\n  }\n\n  fragment FullType on __Type {\n    kind\n    name\n    description\n    fields(includeDeprecated: true) {\n      name\n      description\n      args {\n        ...InputValue\n      }\n      type {\n        ...TypeRef\n      }\n      isDeprecated\n      deprecationReason\n    }\n    inputFields {\n      ...InputValue\n    }\n    interfaces {\n      ...TypeRef\n    }\n    enumValues(includeDeprecated: true) {\n      name\n      description\n      isDeprecated\n      deprecationReason\n    }\n    possibleTypes {\n      ...TypeRef\n    }\n  }\n\n  fragment InputValue on __InputValue {\n    name\n    description\n    type { ...TypeRef }\n    defaultValue\n  }\n\n  fragment TypeRef on __Type {\n    kind\n    name\n    ofType {\n      kind\n      name\n      ofType {\n        kind\n        name\n        ofType {\n          kind\n          name\n          ofType {\n            kind\n            name\n            ofType {\n              kind\n              name\n              ofType {\n                kind\n                name\n                ofType {\n                  kind\n                  name\n                }\n              }\n            }\n          }\n        }\n      }\n    }\n  }\n", "graphql"=>{"query"=>"\n  query IntrospectionQuery {\n    __schema {\n      queryType { name }\n      mutationType { name }\n      subscriptionType { name }\n      types {\n        ...FullType\n      }\n      directives {\n        name\n        description\n        locations\n        args {\n          ...InputValue\n        }\n      }\n    }\n  }\n\n  fragment FullType on __Type {\n    kind\n    name\n    description\n    fields(includeDeprecated: true) {\n      name\n      description\n      args {\n        ...InputValue\n      }\n      type {\n        ...TypeRef\n      }\n      isDeprecated\n      deprecationReason\n    }\n    inputFields {\n      ...InputValue\n    }\n    interfaces {\n      ...TypeRef\n    }\n    enumValues(includeDeprecated: true) {\n      name\n      description\n      isDeprecated\n      deprecationReason\n    }\n    possibleTypes {\n      ...TypeRef\n    }\n  }\n\n  fragment InputValue on __InputValue {\n    name\n    description\n    type { ...TypeRef }\n    defaultValue\n  }\n\n  fragment TypeRef on __Type {\n    kind\n    name\n    ofType {\n      kind\n      name\n      ofType {\n        kind\n        name\n        ofType {\n          kind\n          name\n          ofType {\n            kind\n            name\n            ofType {\n              kind\n              name\n              ofType {\n                kind\n                name\n                ofType {\n                  kind\n                  name\n                }\n              }\n            }\n          }\n        }\n      }\n    }\n  }\n"}}
Completed 500 Internal Server Error in 10ms (ActiveRecord: 0.0ms)



GraphQL::Schema::InvalidTypeError (Mutation is invalid: field "createPost" type must return GraphQL::BaseType, not NilClass (nil)):

app/graphql/reproduce_graphql_hang_schema.rb:1:in `<top (required)>'
app/controllers/graphql_controller.rb:9:in `execute'
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/diagnostics.html.erb within rescues/layout
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_source.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_source.html.erb (3.8ms)
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_trace.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_trace.html.erb (1.6ms)
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_request_and_response.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_request_and_response.html.erb (1.3ms)
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/diagnostics.html.erb within rescues/layout (70.0ms)
  1. Refresh browser, and see another error log:
Started GET "/graphiql" for 127.0.0.1 at 2017-04-04 11:40:51 +0800
Processing by GraphiQL::Rails::EditorsController#show as HTML
  Parameters: {"graphql_path"=>"/graphql"}
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/graphiql-rails-1.4.1/app/views/graphiql/rails/editors/show.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/graphiql-rails-1.4.1/app/views/graphiql/rails/editors/show.html.erb (9.7ms)
Completed 200 OK in 21ms (Views: 17.7ms | ActiveRecord: 0.0ms)


Started POST "/graphql" for 127.0.0.1 at 2017-04-04 11:40:52 +0800
Processing by GraphqlController#execute as */*
  Parameters: {"query"=>"\n  query IntrospectionQuery {\n    __schema {\n      queryType { name }\n      mutationType { name }\n      subscriptionType { name }\n      types {\n        ...FullType\n      }\n      directives {\n        name\n        description\n        locations\n        args {\n          ...InputValue\n        }\n      }\n    }\n  }\n\n  fragment FullType on __Type {\n    kind\n    name\n    description\n    fields(includeDeprecated: true) {\n      name\n      description\n      args {\n        ...InputValue\n      }\n      type {\n        ...TypeRef\n      }\n      isDeprecated\n      deprecationReason\n    }\n    inputFields {\n      ...InputValue\n    }\n    interfaces {\n      ...TypeRef\n    }\n    enumValues(includeDeprecated: true) {\n      name\n      description\n      isDeprecated\n      deprecationReason\n    }\n    possibleTypes {\n      ...TypeRef\n    }\n  }\n\n  fragment InputValue on __InputValue {\n    name\n    description\n    type { ...TypeRef }\n    defaultValue\n  }\n\n  fragment TypeRef on __Type {\n    kind\n    name\n    ofType {\n      kind\n      name\n      ofType {\n        kind\n        name\n        ofType {\n          kind\n          name\n          ofType {\n            kind\n            name\n            ofType {\n              kind\n              name\n              ofType {\n                kind\n                name\n                ofType {\n                  kind\n                  name\n                }\n              }\n            }\n          }\n        }\n      }\n    }\n  }\n", "graphql"=>{"query"=>"\n  query IntrospectionQuery {\n    __schema {\n      queryType { name }\n      mutationType { name }\n      subscriptionType { name }\n      types {\n        ...FullType\n      }\n      directives {\n        name\n        description\n        locations\n        args {\n          ...InputValue\n        }\n      }\n    }\n  }\n\n  fragment FullType on __Type {\n    kind\n    name\n    description\n    fields(includeDeprecated: true) {\n      name\n      description\n      args {\n        ...InputValue\n      }\n      type {\n        ...TypeRef\n      }\n      isDeprecated\n      deprecationReason\n    }\n    inputFields {\n      ...InputValue\n    }\n    interfaces {\n      ...TypeRef\n    }\n    enumValues(includeDeprecated: true) {\n      name\n      description\n      isDeprecated\n      deprecationReason\n    }\n    possibleTypes {\n      ...TypeRef\n    }\n  }\n\n  fragment InputValue on __InputValue {\n    name\n    description\n    type { ...TypeRef }\n    defaultValue\n  }\n\n  fragment TypeRef on __Type {\n    kind\n    name\n    ofType {\n      kind\n      name\n      ofType {\n        kind\n        name\n        ofType {\n          kind\n          name\n          ofType {\n            kind\n            name\n            ofType {\n              kind\n              name\n              ofType {\n                kind\n                name\n                ofType {\n                  kind\n                  name\n                }\n              }\n            }\n          }\n        }\n      }\n    }\n  }\n"}}
Completed 500 Internal Server Error in 3ms (ActiveRecord: 0.0ms)



LoadError (Unable to autoload constant Types::QueryType, expected /Users/lijie/test/rails/reproduce_graphql_hang/app/graphql/types/query_type.rb to define it):

app/graphql/reproduce_graphql_hang_schema.rb:2:in `block in <top (required)>'
app/graphql/reproduce_graphql_hang_schema.rb:1:in `<top (required)>'
app/controllers/graphql_controller.rb:9:in `execute'
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/diagnostics.html.erb within rescues/layout
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_source.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_source.html.erb (3.7ms)
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_trace.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_trace.html.erb (2.3ms)
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_request_and_response.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_request_and_response.html.erb (1.0ms)
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/diagnostics.html.erb within rescues/layout (68.2ms)
  1. Checkout the 3rd commit https://github.com/cpunion/reproduce_graphql_hang/commit/704933267efad6b4ba5e23b31ce6ad820e4e4f53, it fixed the code.
  2. Refresh the browser, and now server hung:
Started GET "/graphiql" for 127.0.0.1 at 2017-04-04 11:41:03 +0800
^CExiting
cpunion picture cpunion on 4 Apr 2017

@rmosolgo I tried your code, also reproduced, just test with above steps. Refresh twice, fix code (change nil to types.Int) and refresh again, then it hung.

cpunion picture cpunion on 4 Apr 2017

The simplest steps: just refresh once then fix code and refresh again.

cpunion picture cpunion on 4 Apr 2017

Thanks, I can replicate it locally now, I'm looking into it!

It seems like it never even makes it to the controller body, somehow it's getting stuck in Rails constant loading, hmmm

rmosolgo picture rmosolgo on 4 Apr 2017

@rmosolgo Can confirm ^^. Like you said it doesn't even reach to controller body, log shows post to /graphql and just hangs there, sometimes it executes, but often times need to restart the server.

gauravtiwari picture gauravtiwari on 7 Apr 2017

Same here. Havent spent any time debugging it yet.

aflatter picture aflatter on 7 Apr 2017

What an adventure! It looks like ActiveSupport::Dependencies prevents cycles when _loading_ constants, but not when _unloading_ them. I was able to get the test case above passing with this, you could add it in development: 

# config/application.rb


if Rails.env.development?
  # This isn't threadsafe -- it will work on single-threaded development servers only.
  ALREADY_REMOVED = Set.new

  module ActiveSupport::Dependencies
    class << self
      alias :old_remove_constant :remove_constant

      def remove_constant(const_name)
        if ALREADY_REMOVED.include?(const_name)
          # pass
        else
          ALREADY_REMOVED.add(const_name)
          old_remove_constant(const_name)
        end
      end
    end
  end

  class UnloadCyclesMiddleware
    def initialize(app, opts = {})
      @app = app
    end

    def call(env)
      ALREADY_REMOVED.clear
      @app.call(env)
    end
  end
end 

# ... 

module MyApp
  class Application < Rails::Application
    # ...
    config.middleware.insert_before(ActionDispatch::Reloader, UnloadCyclesMiddleware)
  end
end

Now, to find a _real_ fix!

rmosolgo picture rmosolgo on 8 Apr 2017

Great! You save me. Thanks!

How did you find the reason for this kind of problems? I tried, but no idea. I don't know how to trace what is it working when it hang, is there a tool/command to find the stack of threads?

cpunion picture cpunion on 8 Apr 2017

I'm not a very sophisticated debugger, here's what I did:

  • Add some puts to the controller, but discover that it _is not_ called, so the hang is _before_ the controller action.

  • Use two middlewares to prove that ActiveSupport::Reloader was hanging (I had this clue from your logs above) 

    class WhatTheHeckMiddleware 
 def initialize(app, opts = {}) 
   @app = app 
   @idx = opts[:idx]
 end 

 # Just log when this middleware starts and ends
 def call(env) 
   puts "~~ START #{@idx} ~~"
   res = @app.call(env)
   puts "~~ END #{@idx} ~~"
   res 
 end 
end 

# ... 
config.middleware.insert_before(ActiveSupport::Reloader, WhatTheHeckMiddleware, { idx: 1 })
config.middleware.insert_after(ActiveSupport::Reloader, WhatTheHeckMiddleware, { idx: 2 })
  • Replicate the hang, and observe that ~~ START 2 ~~ is not present in the log, which means that the hang is during ActiveSupport::Reloader.

  • I know that the issue is with ActiveSupport::Dependencies, so I just logged _all_ the methods on that module 馃槄 

    module ActiveSupport::Dependencies 
 methods.each do |method_name|  
 method_body = method(method_name)
 define_singleton_method(method_name) do |*args, &block| 
   puts "ActiveSupport::Dependencies.#{method_name}(#{args.join(",")} #{block ? "&block" : ""})"
   method_body.call(*args, &block)
 end 
end
  • Fortunately, the infinite loop was pretty tight, and remove_constant stood out. I spent a long time reading ActiveSupport::Dependencies, trying to understand what went wrong, but I couldn't. So I applied the Set-based monkey patch which I posted above and it worked. Out of curiosity, I inspected ActiveSupport::Dependencies.autoloaded_constants. During a hang, this Array contained duplicate entries for Types and Mutations, but I don't know why. I tried to read the source, but I couldn't make sense of it 馃槚

So in the end, I can't really _fix_ it, but I can prevent it!

https://github.com/rmosolgo/graphql-ruby/pull/665

rmosolgo picture rmosolgo on 8 Apr 2017
👍10

Thank you. I have benefited from your thorough explanation.

cpunion picture cpunion on 8 Apr 2017

Hung again just now:(

I upgraded to v1.5.6 and it works fine, until a syntax errors:

SyntaxError (/Users/lijie/api/app/graphql/types/commentable_type.rb:8: syntax error, unexpected end-of-input, expecting keyword_end):

app/graphql/types/commentable_type.rb:8: syntax error, unexpected end-of-input, expecting keyword_end
app/graphql/types/shared_type.rb:4:in `block in <top (required)>'
app/graphql/api_schema.rb:1:in `<top (required)>'
app/controllers/graphql_controller.rb:20:in `execute'
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/diagnostics.html.erb within rescues/layout
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_source.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_source.html.erb (5.1ms)
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_trace.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_trace.html.erb (1.9ms)
  Rendering /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_request_and_response.html.erb
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/_request_and_response.html.erb (1.4ms)
  Rendered /Users/lijie/.rvm/gems/ruby-2.3.1/gems/actionpack-5.0.2/lib/action_dispatch/middleware/templates/rescues/diagnostics.html.erb within rescues/layout (84.8ms)
Started POST "/graphql" for 127.0.0.1 at 2017-04-13 15:13:52 +0800

Seems the dtruss log is same as above. My commentable_type.rb defines an InterfaceType, uses in shared_type.rb with interfaces [Types::CommentableType]. Easy to reproduce in my project.

cpunion picture cpunion on 13 Apr 2017

It's basically the same problem, but in this case, GraphQL's involvement is coincidental.

It would be nice to see if it can be reduced, then we could open a bug with Rails (or, if we can't, maybe we can find something else to fix here 馃槅 )

rmosolgo picture rmosolgo on 19 Apr 2017

I just ran into this here and was quite surprised. Maybe it's the way that GraphQL DSL is set up? Do we need to use define to create types? Maybe if we just used some standard Ruby modules it might make Rails happier. For instance:

# app/graphql/types/query_type.rb
module Types::QueryType
  extend GraphQL::ObjectType

  name "Query"
  description "The query root of this schema"

  # Add root-level fields here.
  # They will be entry points for queries on your schema.

  field :post do
    type Types::PostType
    argument :id, !types.ID
    description "Find a Post by ID"
    resolve ->(obj, args, ctx) { Post.find_by_id(args["id"]) }
  end
end
qrush picture qrush on 12 Jul 2017
👍4

Hoping to make a change like that soon! Discussion at #820

rmosolgo picture rmosolgo on 12 Jul 2017
👍1

I forked the reproduction repo above and migrated it to the new class-based API and it still hangs

https://github.com/rmosolgo/reproduce_graphql_hang/tree/6258d993d3b690bf3925fdbba229560dfb8ffdb5

But I really want to fix this, so ... not giving up yet :S :S :S

(edit: posted the wrong SHA)

rmosolgo picture rmosolgo on 12 Nov 2017

Is there a way to fix this for development only? Working with this problem is crazy and I'm loosing my mind. Please...

Everytime I need to kill and restart the server!!!!

ghost picture ghost on 10 Jan 2018
😕3

@johnunclesam we know this is an issue for some users and we can image the frustration if you have to restart your server for every change. Have you tried the workaround as proposed in https://github.com/rmosolgo/graphql-ruby/issues/651#issuecomment-292718619?

Willianvdv picture Willianvdv on 10 Jan 2018

Caching up here, seeing that #1037 was merged, and there's a doc for class based schemas:

https://github.com/rmosolgo/graphql-ruby/blob/1fa7a2a4/guides/schema/class_based_api.md

I'll give this a shot too, looking great. 馃挴

qrush picture qrush on 10 Jan 2018

@qrush note that class based schema isn't released yet, there might be some sharp edges!

Willianvdv picture Willianvdv on 10 Jan 2018
👍2

@qrush, the class based schemas fix my problem?

ghost picture ghost on 10 Jan 2018

Have you tried the workaround as proposed in #651 (comment)?

@Willianvdv I tried now. Bad results:

  • WITHOUT workaround: if I modify some code to throw an error, the error shows up, I undo the changes and now it works but hang-up, crash, freeze again the process!!

  • WITH that workaround: I modify the same code to throw the error, the error shows up, I undo the changes and now the changes are not anymore detected. I got the error at every query, like I never undo the changes to throw that error.

All of this is frustrating.

ghost picture ghost on 10 Jan 2018

馃槄 I finally spent some more time investigating this, TL;DR: 

# config/initializers/autoloaded_constants_patch.rb
if Rails.env.development?
  # Work around a constant unloading issue, see: 
  # https://github.com/rails/rails/issues/31694
  # https://github.com/rmosolgo/graphql-ruby/issues/651
  # Use this modified Array class instead of Set 
  # because Set doesn't implement some methods 
  # required by ActiveSupport::Dependencies
  class UniqueArray < Array
    def <<(other)
      if include?(other)
        self
      else
        super(other)
      end
    end
  end
  ActiveSupport::Dependencies.autoloaded_constants = UniqueArray.new
end

Can someone give a try with that workaround and let me know what you find?

I followed the same steps which I described above, and found basically the same result. But I spent more time with ActiveSupport::Dependencies, and I was able to replicate the issue in a stand-alone Rails app: https://github.com/rmosolgo/constant-loading-issue

rmosolgo picture rmosolgo on 12 Jan 2018
👍4 ❤2

@rmosolgo you are GOD. This workaround now works! AMAZIIIIIIIINGGGG!!!!!! Thanks!

We'll wait for a Rails team feedback now. Thanks again.

ghost picture ghost on 13 Jan 2018
🎉2

Thank you very much for this patch. I had an infinite loop problem caused by a syntax error in one of my types (UserType) that was being incorrectly reported as a problem with Types::MutationType, and which would hang my development Rails server after one request, but this workaround solves the hang. I still had to fix my syntax error, of course.

benkimball picture benkimball on 21 Feb 2018

@rmosolgo seeing https://github.com/rails/rails/pull/31803, can we remove this workaround? From wich Rails version? 5.2?

ghost picture ghost on 21 Feb 2018

@johnunclesam I upgraded to 5.1.5 and seems it be fixed. I think it fixed in 5.2.0-rc1.

cpunion picture cpunion on 2 Mar 2018

Fixed on latest rails 馃帀

rmosolgo picture rmosolgo on 26 Apr 2018

Hi @rmosolgo , In which version this is supposed to be fixed?. we are using rails 5.1.6 and server it's still hanging when code in backend is updated.

michelson picture michelson on 16 Oct 2018
Was this page helpful?
0 / 5 - 0 ratings

Related issues

jturkel picture jturkel  路  3Comments
pareeohnos picture pareeohnos  路  3Comments
theodorton picture theodorton  路  3Comments
sayduck-daniel picture sayduck-daniel  路  3Comments
jtippett picture jtippett  路  3Comments