Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Code Reloading w/ Rails in Development #651

Closed
Randuin opened this issue Mar 31, 2017 · 38 comments
Closed

Code Reloading w/ Rails in Development #651

Randuin opened this issue Mar 31, 2017 · 38 comments

Comments

@Randuin
Copy link

Randuin commented Mar 31, 2017

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):

@rmosolgo
Copy link
Owner

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?

@cpunion
Copy link
Contributor

cpunion commented Apr 3, 2017

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

@rmosolgo
Copy link
Owner

rmosolgo commented Apr 3, 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?

@cpunion
Copy link
Contributor

cpunion commented Apr 3, 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
Copy link
Contributor

cpunion commented Apr 3, 2017

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

@rmosolgo
Copy link
Owner

rmosolgo commented Apr 3, 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!

@cpunion
Copy link
Contributor

cpunion commented Apr 3, 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
Copy link
Contributor

cpunion commented Apr 3, 2017

Great! thanks. (restarted tens today 😄 )

@rmosolgo
Copy link
Owner

rmosolgo commented Apr 3, 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?

@cpunion
Copy link
Contributor

cpunion commented Apr 4, 2017

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

Steps:

  1. checkout the second commit: cpunion/reproduce_graphql_hang@e94dc76, 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 cpunion/reproduce_graphql_hang@7049332, 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
Copy link
Contributor

cpunion commented Apr 4, 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
Copy link
Contributor

cpunion commented Apr 4, 2017

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

@rmosolgo
Copy link
Owner

rmosolgo commented Apr 4, 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

@gauravtiwari
Copy link
Contributor

@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.

@aflatter
Copy link

aflatter commented Apr 7, 2017

Same here. Havent spent any time debugging it yet.

@rmosolgo
Copy link
Owner

rmosolgo commented Apr 8, 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!

@cpunion
Copy link
Contributor

cpunion commented Apr 8, 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?

@rmosolgo
Copy link
Owner

rmosolgo commented Apr 8, 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!

#665

@cpunion
Copy link
Contributor

cpunion commented Apr 8, 2017

Thank you. I have benefited from your thorough explanation.

@cpunion
Copy link
Contributor

cpunion commented Apr 13, 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.

@rmosolgo
Copy link
Owner

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 rmosolgo reopened this Apr 19, 2017
@qrush
Copy link
Contributor

qrush commented Jul 12, 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

@rmosolgo
Copy link
Owner

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

@rmosolgo
Copy link
Owner

rmosolgo commented Nov 12, 2017

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)

@ghost
Copy link

ghost commented Jan 10, 2018

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!!!!

@Willianvdv
Copy link
Contributor

@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 #651 (comment)?

@qrush
Copy link
Contributor

qrush commented Jan 10, 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. 💯

@Willianvdv
Copy link
Contributor

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

@ghost
Copy link

ghost commented Jan 10, 2018

@qrush, the class based schemas fix my problem?

@ghost
Copy link

ghost commented Jan 10, 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.

@rmosolgo
Copy link
Owner

😅 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

@ghost
Copy link

ghost commented Jan 12, 2018

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

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

@benkimball
Copy link
Contributor

benkimball commented Feb 21, 2018

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.

@ghost
Copy link

ghost commented Feb 21, 2018

@rmosolgo seeing rails/rails#31803, can we remove this workaround? From wich Rails version? 5.2?

@cpunion
Copy link
Contributor

cpunion commented Mar 2, 2018

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

@rmosolgo
Copy link
Owner

Fixed on latest rails 🎉

@michelson
Copy link

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
Copy link

Hi @rmosolgo , I'm currently using:
graphiql-rails (1.8.0)
graphql (1.13.16)

And the backend still hangs when I update the code.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

9 participants