search

rmosolgo / graphql-ruby

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

Circular dependency issue with AsyncDataloader #4745

Closed swrobel closed 9 months ago

swrobel commented 10 months ago

Describe the bug My existing schema, which works well with the classic Dataloader, fails for certain requests with AsyncDataloader

Versions

graphql version: master commit becd60008606 rails (or other framework): 7.1.2 other applicable versions (graphql-batch, etc)

GraphQL schema

Simplified schema to repro:

module Types
  class CategoryType < BaseObject
    field :id, ID, null: false

    field :offerings, [Types::OfferingType], null: false

    def offerings(selected: nil, hidden: nil)
      dataloader.with(Loaders::Category::OfferingsLoader, selected, hidden).load(object.id)
    end
  end
end
module Loaders::Offering
  class CategoryLoader < GraphQL::Dataloader::Source
    def fetch(record_ids)
      @record_ids = record_ids

      record_ids.map do |id|
        records.find do |record|
          record.offerings.any? { |offering| offering.id == id }
        end
      end
    end

    private

    def records
      @records ||= Category
        .joins(:offerings)
        .includes(:offerings)
        .where(offerings: {id: @record_ids})
        .distinct
    end
  end
end
module Types
  class OfferingType < BaseObject
    field :id, ID, null: false

    field :category, Types::CategoryType, null: true

    private

    def category
      dataloader.with(Loaders::Offering::CategoryLoader).load(object.id)
    end
  end
end
class Loaders::Category::OfferingsLoader < GraphQL::Dataloader::Source
  attr_reader :selected, :hidden

  def initialize(selected, hidden)
    @selected = selected
    @hidden = hidden
  end

  def fetch(record_ids)
    @record_ids = record_ids

    record_ids.map do |id|
      records.select { |record| record.category_id == id }
    end
  end

  private

  def records
    @records ||=
      Offering.where(category_id: @record_ids)
        .tap { |query| query.where!(selected:) unless selected.nil? }
        .tap { |query| query.where!(hidden:) unless hidden.nil? }
        .order_by_position
  end
end

GraphQL query

Simplified schema to repro:

mutation InitializeUI($input: CreateSessionInput!) {
  createSession(input: $input) {
    user {
      categories {
        id
        offerings {
          id
        }
      }
      offerings {
        id
      }
    }
  }
}
{
  "data": {
    "createSession": {
      "user": {
        "categories": [
          {
            "id": "5fe31061-9db0-4c5e-8602-4540f2ab385e",
            "offerings": [
              {
                "id": "d99c5112-854e-43a0-8e75-3c4e936eff72"
              },
              {
                "id": "2df4632a-fdb2-4775-a1bb-4d258223c091"
              },
              {
                "id": "9fac4393-f2a9-4883-91aa-ab0392e6a1da"
              }
            ]
          },
          {
            "id": "e91b2429-f4aa-44ff-9909-1f57f48afac0",
            "offerings": [
              {
                "id": "44885e32-4056-479f-b053-759c68ebb4c4"
              },
              {
                "id": "a9a9116d-d346-46bd-9d6e-96ac28c0804f"
              },
              {
                "id": "03c91409-d4b3-452b-820e-6aa69c742bd5"
              }
            ]
          }
        ],
        "offerings": [
          {
            "id": "9271ab6c-089c-4094-bc56-454d6ada98e7"
          },
          {
            "id": "409bf2cd-3bf9-44f6-9387-61456713920e"
          },
          {
            "id": "d86b33f0-5545-4b38-a072-1ba1ac0b44dd"
          },
          {
            "id": "2df4632a-fdb2-4775-a1bb-4d258223c091"
          },
          {
            "id": "6b02a1b1-0111-4a93-9d55-ccb83ee964db"
          },
          {
            "id": "8acd96b7-17d1-4576-bf53-fda7b1faf2db"
          },
          {
            "id": "0610c3bc-9725-4761-a0f2-be35835b7a8d"
          },
          {
            "id": "d99c5112-854e-43a0-8e75-3c4e936eff72"
          },
          {
            "id": "44885e32-4056-479f-b053-759c68ebb4c4"
          },
          {
            "id": "a374b451-23ea-42a3-b7d3-65e18aae7c29"
          },
          {
            "id": "a9a9116d-d346-46bd-9d6e-96ac28c0804f"
          },
          {
            "id": "a1aaba60-0ef3-4d63-a3a9-d1e926800c4d"
          },
          {
            "id": "03c91409-d4b3-452b-820e-6aa69c742bd5"
          },
          {
            "id": "eff97220-2ce1-4803-a32a-25e18e0e4bb1"
          },
          {
            "id": "df337b0b-c000-4672-a943-5c3de506cca2"
          },
          {
            "id": "9fac4393-f2a9-4883-91aa-ab0392e6a1da"
          },
          {
            "id": "991ad8a0-6b5d-4bae-bac4-4403b478b19d"
          },
          {
            "id": "59b7bf3d-0780-42c7-ad0a-7d27504e8b26"
          },
          {
            "id": "a86a4b6f-538f-4915-8df4-6fa568f7ade1"
          },
          {
            "id": "a8924cad-9981-43a5-8188-03f0dc0427e3"
          },
          {
            "id": "054a2473-5631-457d-ad6e-55185481ca9b"
          },
          {
            "id": "32b2a064-8f44-441c-a04c-8660519d40ef"
          },
          {
            "id": "4c38fcef-1a99-477b-b5b1-42ddb1465c6b"
          },
          {
            "id": "03437e1d-63f2-4af7-9d2b-b519817444bf"
          },
          {
            "id": "d44655a5-08ad-4f0f-b855-7026f2b383dd"
          },
          {
            "id": "dfdb1300-849c-443a-b8f7-d9b2581f00db"
          },
          {
            "id": "612783f9-1eff-43a3-9917-8b6de28c9ffa"
          },
          {
            "id": "012a04eb-db2f-4236-9c0e-f53baaeb55cf"
          },
          {
            "id": "efb5aa0c-5a06-433b-900d-9a01849c505d"
          },
          {
            "id": "0333dd63-a93f-442d-ba1d-196150cf1b49"
          },
          {
            "id": "c9079b40-2f1f-4a09-8b5d-bcdea11efcbd"
          },
          {
            "id": "988f9639-b6f0-456c-9621-4431a8ce070d"
          },
          {
            "id": "260e110e-34a4-4350-8c9b-d50a67be57d3"
          },
          {
            "id": "f49e8771-4f40-42d5-b792-60b0df40c606"
          },
          {
            "id": "a619ff9b-0f58-4b61-a6ac-7d1fed9cfbab"
          },
          {
            "id": "be387d8d-1044-45ff-91b4-ae646cf5d72f"
          },
          {
            "id": "0aecc5ed-576b-49fe-96bd-e5a4f96aec75"
          },
          {
            "id": "6e1144ed-24d0-4cb9-8791-9ccd6e454d54"
          },
          {
            "id": "e882da2a-edc9-4dd7-af22-9776e6b7713d"
          },
          {
            "id": "eb9f3e23-3aab-4f64-ab3e-d5b9b9a4dd72"
          }
        ]
      }
    }
  }
}

Steps to reproduce

Change from stock Dataloader to AsyncDataloader

Expected behavior

Queries complete the same as they did before

Actual behavior

RuntimeError: Loaders::Category::OfferingsLoader#sync tried 1000 times to load pending keys (["5fe31061-9db0-4c5e-8602-4540f2ab385e"]), but they still weren't loaded. There is likely a circular dependency.

Place full backtrace here (if a Ruby exception is involved):

Click to view exception backtrace ``` warn: Async::Task [oid=0xc328] [ec=0xc33c] [pid=24436] [2023-12-21 17:41:48 -0500] | Task may have ended with unhandled exception. | RuntimeError: Loaders::Category::OfferingsLoader#sync tried 1000 times to load pending keys (["5fe31061-9db0-4c5e-8602-4540f2ab385e"]), but they still weren't loaded. There is likely a circular dependency. | → bundler/gems/graphql-ruby-becd60008606/lib/graphql/dataloader/source.rb:101 in `sync' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/dataloader/source.rb:57 in `load' | app/graphql/types/category_type.rb:8 in `offerings' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:700 in `public_send' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:700 in `block (2 levels) in resolve' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:843 in `block in with_extensions' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:879 in `block (2 levels) in run_extensions_before_resolve' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:882 in `run_extensions_before_resolve' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:879 in `block in run_extensions_before_resolve' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field_extension.rb:134 in `resolve' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:866 in `run_extensions_before_resolve' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:838 in `with_extensions' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:669 in `block in resolve' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:770 in `minimal_after_lazy' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/query.rb:372 in `after_lazy' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:667 in `resolve' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:358 in `block (2 levels) in evaluate_selection_with_resolved_keyword_args' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/tracing/trace.rb:52 in `execute_field' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:357 in `block in evaluate_selection_with_resolved_keyword_args' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:709 in `call_method_on_directives' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:354 in `evaluate_selection_with_resolved_keyword_args' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:264 in `evaluate_selection' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:214 in `block (2 levels) in evaluate_selections' | bundler/gems/graphql-ruby-becd60008606/lib/graphql/dataloader/async_dataloader.rb:65 in `block in spawn_job_task' | gems/async-2.6.5/lib/async/task.rb:160 in `block in run' | gems/async-2.6.5/lib/async/task.rb:330 in `block in schedule' Loaders::Category::OfferingsLoader#sync tried 1000 times to load pending keys (["5fe31061-9db0-4c5e-8602-4540f2ab385e"]), but they still weren't loaded. There is likely a circular dependency. app/graphql/types/category_type.rb:8:in `offerings' ```
myronmarston commented 10 months ago

I'm getting similar errors simply by upgrading from 2.1.8 to 2.1.9 (with no further changes).

rmosolgo commented 10 months ago

@myronmarston would you mind sharing any details (backtrace, loader source, usage?) about the error? That might help identify what situation causes this to happen.

rmosolgo commented 10 months ago

@swrobel, the thing that stands out to me from your example is caching @records ||= ... in the Source. That means that it will only query the database once during a query; previous calls will use the already-fetched records. I'm guessing that previously, this worked because the objects were deterministically fetched in the same round of Dataloader resolution. But with AsyncDataloader, it depends on how long things take, so it's not totally deterministic in there.

If you expand that fetch to something like: 

@records ||= begin 
  p [:fetching, @record_ids]
  # fetch records here
end

Do you see all the record_ids you expect, or just some? If you remove that caching, does it still raise this error?

(In this case, the error message's guess about what went wrong is wrong -- but under the hood, Dataloader raises this error after it waits and waits for a dependency to be resolved and it still hasn't been resolved. As far as caching is concerned, sources have their own cache -- they map load(...) arguments to their fetched objects.)

rmosolgo commented 10 months ago

I've been trying to replicate that possibility with the script below, but I can't -- instead, it returns nil for those IDs which don't have corresponding entries in @records. It's a bug, but not this bug!

Trying to replicate dataloader bug (but not)

```ruby require "bundler/inline" gemfile do gem "async" gem "graphql", "2.2.1" end class MySchema < GraphQL::Schema class CategoriesSource < GraphQL::Dataloader::Source def fetch(ids) sleep 0.1 ids.map { [ { name: "Frozen Foods", id: 1 }, { name: "Dry Goods", id: 2 } ] } end end class OfferingSource < GraphQL::Dataloader::Source def fetch(ids) @ids = ids @records ||= begin sleep 0.1 ids.map { |id| { id: id, name: "Offering #{id}" } } end @ids.map { |id| @records.find { |r| r[:id] == id } } end end class Offering < GraphQL::Schema::Object field :name, String end class Category < GraphQL::Schema::Object field :name, String field :offerings, [Offering, null: true] def offerings dataloader.with(OfferingSource).load_all((2..5).to_a) end end class Query < GraphQL::Schema::Object field :categories, [Category] def categories dataloader.with(CategoriesSource).load(:all) end field :offerings, [Offering] def offerings dataloader.with(OfferingSource).load_all((1..3).to_a) end end query(Query) use GraphQL::Dataloader::AsyncDataloader end query_str = "{ categories { name offerings { name } } offerings { name } }" pp MySchema.execute(query_str).to_h # {"data"=> # {"categories"=> # [{"name"=>"Frozen Foods", "offerings"=>[{"name"=>"Offering 2"}, {"name"=>"Offering 3"}, nil, nil]}, # {"name"=>"Dry Goods", "offerings"=>[{"name"=>"Offering 2"}, {"name"=>"Offering 3"}, nil, nil]}], # "offerings"=>[{"name"=>"Offering 1"}, {"name"=>"Offering 2"}, {"name"=>"Offering 3"}]}} ```

My next guess is that there might be some kind of race condition with @pending or @fetching here, if two fibers are trying to resolve the same source at the same time:

https://github.com/rmosolgo/graphql-ruby/blob/becd60008606f5ca750e568b3367f27b464d0fd6/lib/graphql/dataloader/source.rb#L125-L145

Tomorrow I'll see if I can nail down a bug there, something about keys being removed from one of those hashes, so that @results[key] = ... never happens for it...

rmosolgo commented 10 months ago

Also, @swrobel, do you mind sharing how User.offerings fetches its offerings? (Does it use the same Dataloader source, but passing some other kind of ID?)

swrobel commented 10 months ago

do you mind sharing how User.offerings fetches its offerings? (Does it use the same Dataloader source, but passing some other kind of ID?)

This one hasn't been dataloader-ized yet:

def offerings(offering_type: nil, offering_types: nil, selected: nil, hidden: nil)
  object.offerings
    .tap { |query| query.where(offering_type: offering_type || offering_types) unless offering_type.nil? && offering_types.nil? }
    .tap { |query| query.where!(selected:) unless selected.nil? }
    .tap { |query| query.where!(hidden:) unless hidden.nil? }
    .order_by_position
end
swrobel commented 10 months ago

Do you see all the record_ids you expect, or just some?

Using the standard Dataloader, it seems to fetch them both in one go, although it prints this line 2x, which is curious:

[:fetching, ["5fe31061-9db0-4c5e-8602-4540f2ab385e", "e91b2429-f4aa-44ff-9909-1f57f48afac0"]]
[:fetching, ["5fe31061-9db0-4c5e-8602-4540f2ab385e", "e91b2429-f4aa-44ff-9909-1f57f48afac0"]]

Using AsyncDataloader, it seems to fetch them one-by-one:

[:fetching, ["5fe31061-9db0-4c5e-8602-4540f2ab385e"]]
[:fetching, ["e91b2429-f4aa-44ff-9909-1f57f48afac0"]]
  0.0s     warn: Async::Task [oid=0x6810] [ec=0x670c] [pid=75449] [2023-12-22 11:37:47 -0500]
               | Task may have ended with unhandled exception.
               |   RuntimeError: Loaders::Category::OfferingsLoader#sync tried 1000 times to load pending keys (["5fe31061-9db0-4c5e-8602-4540f2ab385e"]), but they still weren't loaded. There is likely a circular dependency.

If you remove that caching, does it still raise this error?

Yes, it does

swrobel commented 10 months ago

I'm also noticing that AsyncDataloader seems to be non-deterministic. I'm continuing my testing with caching disabled, and when I pare down the request to remove the separate query for offerings that triggers the original error:

mutation InitializeUI($input: CreateSessionInput!) {
  createSession(input: $input) {
    user {
      categories {
        id
        offerings {
          id
        }
      }
    }
  }
}

The first response is missing the offerings for the first category:

{
  "data": {
    "createSession": {
      "user": {
        "categories": [
          {
            "id": "5fe31061-9db0-4c5e-8602-4540f2ab385e",
            "offerings": []
          },
          {
            "id": "e91b2429-f4aa-44ff-9909-1f57f48afac0",
            "offerings": [
              {
                "id": "44885e32-4056-479f-b053-759c68ebb4c4"
              },
              {
                "id": "a9a9116d-d346-46bd-9d6e-96ac28c0804f"
              },
              {
                "id": "03c91409-d4b3-452b-820e-6aa69c742bd5"
              }
            ]
          }
        ]
      }
    }
  }
}

Subsequent requests give the full expected response (I have tried repeating 10x and get this same response each time after the first):

{
  "data": {
    "createSession": {
      "user": {
        "categories": [
          {
            "id": "5fe31061-9db0-4c5e-8602-4540f2ab385e",
            "offerings": [
              {
                "id": "d99c5112-854e-43a0-8e75-3c4e936eff72"
              },
              {
                "id": "2df4632a-fdb2-4775-a1bb-4d258223c091"
              },
              {
                "id": "9fac4393-f2a9-4883-91aa-ab0392e6a1da"
              }
            ]
          },
          {
            "id": "e91b2429-f4aa-44ff-9909-1f57f48afac0",
            "offerings": [
              {
                "id": "44885e32-4056-479f-b053-759c68ebb4c4"
              },
              {
                "id": "a9a9116d-d346-46bd-9d6e-96ac28c0804f"
              },
              {
                "id": "03c91409-d4b3-452b-820e-6aa69c742bd5"
              }
            ]
          }
        ]
      }
    }
  }
}
swrobel commented 10 months ago

As an aside, I'm curious what your thoughts are (if any) on AsyncDataloader vs Rails 7 load_async, which I have yet to try.

myronmarston commented 10 months ago

@myronmarston would you mind sharing any details (backtrace, loader source, usage?) about the error? That might help identify what situation causes this to happen.

Sure. I'm working on a reproduction script now.

myronmarston commented 10 months ago

@rmosolgo here's a reproduction script:

require "bundler/inline"

gemfile do
  source "https://rubygems.org"
  gem "graphql", ENV.fetch("GRAPHQL_VERSION")
end

require "graphql"
require "graphql/dataloader/source"

SCHEMA_STRING = <<~EOS
  type WidgetConnection {
    nodes: [Widget]
  }

  type Widget {
    part(size: String, index: String): String
  }

  input WidgetFilter {
    id: IDFilter
  }

  input IDFilter {
    not: IDFilter
    equal_to_any_of: [ID]
  }

  type Query {
    widgets(filter: WidgetFilter): WidgetConnection
  }
EOS

class Application
  def initialize
    @schema = GraphQL::Schema.from_definition(SCHEMA_STRING, default_resolve: self, using: {GraphQL::Dataloader => {}})
    @schema.types.fetch("Query").fields.fetch("widgets").extras([:lookahead])
  end

  def call(parent_type, field, object, args, context)
    return [] if field.name == "nodes"

    lookahead = args[:lookahead]

    lookahead.selection("nodes").selections.each do |node|
      Arguments.to_schema_form(node.arguments, node.field) unless ENV["SKIP_ARG_CONVERSION"]
    end

    return context.dataloader.with(FieldSource).load(field)
  end

  def execute_query(query_string)
    @schema.execute(query_string)
  end

  class FieldSource < GraphQL::Dataloader::Source
    def fetch(fields)
      fields.map { nil }
    end
  end

  module Arguments
    def self.to_schema_form(args_value, args_owner)
      case args_value
      when Hash, ::GraphQL::Schema::InputObject
        arg_defns = args_owner.arguments.values

        {}.tap do |accumulator|
          args_value.each do |key, value|
            next if value.nil?

            arg_defn = arg_defns.find do |a|
              a.keyword == key
            end || raise("Cannot find an argument definition for #{key.inspect} on `#{args_owner.name}`")

            next_owner = arg_defn.type.unwrap
            accumulator[arg_defn.name] = to_schema_form(value, next_owner)
          end
        end
      when Array
        args_value.map { |arg_value| to_schema_form(arg_value, args_owner) }
      else
        args_value
      end
    end
  end
end

app = Application.new

agg_queries = 1.upto(ENV.fetch("FIELD_COUNT", "300").to_i).map do |index|
  <<~EOS
    f#{index}: widgets(filter: {id: {not: {equal_to_any_of: [null]}}}) {
      nodes {
        part(size: "LARGE", index: "#{index}")
      }
    }
  EOS
end

query = <<~QUERY
  query {
    #{agg_queries.join("\n")}
  }
QUERY

response = app.execute_query(query)
puts response.to_h.inspect

I'm on Ruby 3.2:

$ ruby -v
ruby 3.2.2 (2023-03-30 revision e51014f9c0) [arm64-darwin22]

It succeeds using graphql-2.1.8:

$ GRAPHQL_VERSION=2.1.8 ruby graphql_bug.rb
{"data"=>{"f1"=>nil, "f2"=>nil, "f3"=>nil, "f4"=>nil, "f5"=>nil, "f6"=>nil, "f7"=>nil, "f8"=>nil, "f9"=>nil, "f10"=>nil, "f11"=>nil, "f12"=>nil, "f13"=>nil, "f14"=>nil, "f15"=>nil, "f16"=>nil, "f17"=>nil, "f18"=>nil, "f19"=>nil, "f20"=>nil, "f21"=>nil, "f22"=>nil, "f23"=>nil, "f24"=>nil, "f25"=>nil, "f26"=>nil, "f27"=>nil, "f28"=>nil, "f29"=>nil, "f30"=>nil, "f31"=>nil, "f32"=>nil, "f33"=>nil, "f34"=>nil, "f35"=>nil, "f36"=>nil, "f37"=>nil, "f38"=>nil, "f39"=>nil, "f40"=>nil, "f41"=>nil, "f42"=>nil, "f43"=>nil, "f44"=>nil, "f45"=>nil, "f46"=>nil, "f47"=>nil, "f48"=>nil, "f49"=>nil, "f50"=>nil, "f51"=>nil, "f52"=>nil, "f53"=>nil, "f54"=>nil, "f55"=>nil, "f56"=>nil, "f57"=>nil, "f58"=>nil, "f59"=>nil, "f60"=>nil, "f61"=>nil, "f62"=>nil, "f63"=>nil, "f64"=>nil, "f65"=>nil, "f66"=>nil, "f67"=>nil, "f68"=>nil, "f69"=>nil, "f70"=>nil, "f71"=>nil, "f72"=>nil, "f73"=>nil, "f74"=>nil, "f75"=>nil, "f76"=>nil, "f77"=>nil, "f78"=>nil, "f79"=>nil, "f80"=>nil, "f81"=>nil, "f82"=>nil, "f83"=>nil, "f84"=>nil, "f85"=>nil, "f86"=>nil, "f87"=>nil, "f88"=>nil, "f89"=>nil, "f90"=>nil, "f91"=>nil, "f92"=>nil, "f93"=>nil, "f94"=>nil, "f95"=>nil, "f96"=>nil, "f97"=>nil, "f98"=>nil, "f99"=>nil, "f100"=>nil, "f101"=>nil, "f102"=>nil, "f103"=>nil, "f104"=>nil, "f105"=>nil, "f106"=>nil, "f107"=>nil, "f108"=>nil, "f109"=>nil, "f110"=>nil, "f111"=>nil, "f112"=>nil, "f113"=>nil, "f114"=>nil, "f115"=>nil, "f116"=>nil, "f117"=>nil, "f118"=>nil, "f119"=>nil, "f120"=>nil, "f121"=>nil, "f122"=>nil, "f123"=>nil, "f124"=>nil, "f125"=>nil, "f126"=>nil, "f127"=>nil, "f128"=>nil, "f129"=>nil, "f130"=>nil, "f131"=>nil, "f132"=>nil, "f133"=>nil, "f134"=>nil, "f135"=>nil, "f136"=>nil, "f137"=>nil, "f138"=>nil, "f139"=>nil, "f140"=>nil, "f141"=>nil, "f142"=>nil, "f143"=>nil, "f144"=>nil, "f145"=>nil, "f146"=>nil, "f147"=>nil, "f148"=>nil, "f149"=>nil, "f150"=>nil, "f151"=>nil, "f152"=>nil, "f153"=>nil, "f154"=>nil, "f155"=>nil, "f156"=>nil, "f157"=>nil, "f158"=>nil, "f159"=>nil, "f160"=>nil, "f161"=>nil, "f162"=>nil, "f163"=>nil, "f164"=>nil, "f165"=>nil, "f166"=>nil, "f167"=>nil, "f168"=>nil, "f169"=>nil, "f170"=>nil, "f171"=>nil, "f172"=>nil, "f173"=>nil, "f174"=>nil, "f175"=>nil, "f176"=>nil, "f177"=>nil, "f178"=>nil, "f179"=>nil, "f180"=>nil, "f181"=>nil, "f182"=>nil, "f183"=>nil, "f184"=>nil, "f185"=>nil, "f186"=>nil, "f187"=>nil, "f188"=>nil, "f189"=>nil, "f190"=>nil, "f191"=>nil, "f192"=>nil, "f193"=>nil, "f194"=>nil, "f195"=>nil, "f196"=>nil, "f197"=>nil, "f198"=>nil, "f199"=>nil, "f200"=>nil, "f201"=>nil, "f202"=>nil, "f203"=>nil, "f204"=>nil, "f205"=>nil, "f206"=>nil, "f207"=>nil, "f208"=>nil, "f209"=>nil, "f210"=>nil, "f211"=>nil, "f212"=>nil, "f213"=>nil, "f214"=>nil, "f215"=>nil, "f216"=>nil, "f217"=>nil, "f218"=>nil, "f219"=>nil, "f220"=>nil, "f221"=>nil, "f222"=>nil, "f223"=>nil, "f224"=>nil, "f225"=>nil, "f226"=>nil, "f227"=>nil, "f228"=>nil, "f229"=>nil, "f230"=>nil, "f231"=>nil, "f232"=>nil, "f233"=>nil, "f234"=>nil, "f235"=>nil, "f236"=>nil, "f237"=>nil, "f238"=>nil, "f239"=>nil, "f240"=>nil, "f241"=>nil, "f242"=>nil, "f243"=>nil, "f244"=>nil, "f245"=>nil, "f246"=>nil, "f247"=>nil, "f248"=>nil, "f249"=>nil, "f250"=>nil, "f251"=>nil, "f252"=>nil, "f253"=>nil, "f254"=>nil, "f255"=>nil, "f256"=>nil, "f257"=>nil, "f258"=>nil, "f259"=>nil, "f260"=>nil, "f261"=>nil, "f262"=>nil, "f263"=>nil, "f264"=>nil, "f265"=>nil, "f266"=>nil, "f267"=>nil, "f268"=>nil, "f269"=>nil, "f270"=>nil, "f271"=>nil, "f272"=>nil, "f273"=>nil, "f274"=>nil, "f275"=>nil, "f276"=>nil, "f277"=>nil, "f278"=>nil, "f279"=>nil, "f280"=>nil, "f281"=>nil, "f282"=>nil, "f283"=>nil, "f284"=>nil, "f285"=>nil, "f286"=>nil, "f287"=>nil, "f288"=>nil, "f289"=>nil, "f290"=>nil, "f291"=>nil, "f292"=>nil, "f293"=>nil, "f294"=>nil, "f295"=>nil, "f296"=>nil, "f297"=>nil, "f298"=>nil, "f299"=>nil, "f300"=>nil}}

It fails on 2.1.9:

$ GRAPHQL_VERSION=2.1.9 ruby graphql_bug.rb
/Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/dataloader/source.rb:100:in `sync': Application::FieldSource#sync tried 1000 times to load pending keys ([#<GraphQL::Schema::Field Query.widgets(...): WidgetConnection>]), but they still weren't loaded. There is likely a circular dependency. (RuntimeError)
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/dataloader/source.rb:57:in `load'
        from graphql_bug.rb:49:in `call'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/schema/build_from_definition.rb:457:in `resolve_field_widgets'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/schema/field.rb:698:in `public_send'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/schema/field.rb:698:in `block (2 levels) in resolve'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/schema/field.rb:843:in `block in with_extensions'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/schema/field.rb:879:in `block (2 levels) in run_extensions_before_resolve'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/schema/field.rb:882:in `run_extensions_before_resolve'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/schema/field.rb:879:in `block in run_extensions_before_resolve'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/schema/field_extension.rb:134:in `resolve'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/schema/field.rb:866:in `run_extensions_before_resolve'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/schema/field.rb:838:in `with_extensions'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/schema/field.rb:669:in `block in resolve'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/execution/interpreter/runtime.rb:770:in `minimal_after_lazy'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/query.rb:372:in `after_lazy'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/schema/field.rb:667:in `resolve'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/execution/interpreter/runtime.rb:358:in `block (2 levels) in evaluate_selection_with_resolved_keyword_args'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/tracing/trace.rb:51:in `execute_field'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/execution/interpreter/runtime.rb:357:in `block in evaluate_selection_with_resolved_keyword_args'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/execution/interpreter/runtime.rb:709:in `call_method_on_directives'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/execution/interpreter/runtime.rb:354:in `evaluate_selection_with_resolved_keyword_args'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/execution/interpreter/runtime.rb:331:in `block in evaluate_selection_with_args'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/execution/interpreter/runtime.rb:830:in `after_lazy'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/execution/interpreter/runtime.rb:279:in `evaluate_selection_with_args'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/execution/interpreter/runtime.rb:273:in `block in evaluate_selection'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/execution/interpreter/arguments_cache.rb:51:in `block in dataload_for'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/schema/member/has_arguments.rb:300:in `block (3 levels) in coerce_arguments'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/dataloader.rb:261:in `block in spawn_job_fiber'
        from /Users/myron/.rvm/gems/ruby-3.2.2/gems/graphql-2.1.9/lib/graphql/dataloader.rb:229:in `block in spawn_fiber'

The high number of fields seems to have an effect; if I lower the number the problem goes away:

$ GRAPHQL_VERSION=2.1.9 FIELD_COUNT=200 ruby graphql_bug.rb
{"data"=>{"f1"=>nil, "f2"=>nil, "f3"=>nil, "f4"=>nil, "f5"=>nil, "f6"=>nil, "f7"=>nil, "f8"=>nil, "f9"=>nil, "f10"=>nil, "f11"=>nil, "f12"=>nil, "f13"=>nil, "f14"=>nil, "f15"=>nil, "f16"=>nil, "f17"=>nil, "f18"=>nil, "f19"=>nil, "f20"=>nil, "f21"=>nil, "f22"=>nil, "f23"=>nil, "f24"=>nil, "f25"=>nil, "f26"=>nil, "f27"=>nil, "f28"=>nil, "f29"=>nil, "f30"=>nil, "f31"=>nil, "f32"=>nil, "f33"=>nil, "f34"=>nil, "f35"=>nil, "f36"=>nil, "f37"=>nil, "f38"=>nil, "f39"=>nil, "f40"=>nil, "f41"=>nil, "f42"=>nil, "f43"=>nil, "f44"=>nil, "f45"=>nil, "f46"=>nil, "f47"=>nil, "f48"=>nil, "f49"=>nil, "f50"=>nil, "f51"=>nil, "f52"=>nil, "f53"=>nil, "f54"=>nil, "f55"=>nil, "f56"=>nil, "f57"=>nil, "f58"=>nil, "f59"=>nil, "f60"=>nil, "f61"=>nil, "f62"=>nil, "f63"=>nil, "f64"=>nil, "f65"=>nil, "f66"=>nil, "f67"=>nil, "f68"=>nil, "f69"=>nil, "f70"=>nil, "f71"=>nil, "f72"=>nil, "f73"=>nil, "f74"=>nil, "f75"=>nil, "f76"=>nil, "f77"=>nil, "f78"=>nil, "f79"=>nil, "f80"=>nil, "f81"=>nil, "f82"=>nil, "f83"=>nil, "f84"=>nil, "f85"=>nil, "f86"=>nil, "f87"=>nil, "f88"=>nil, "f89"=>nil, "f90"=>nil, "f91"=>nil, "f92"=>nil, "f93"=>nil, "f94"=>nil, "f95"=>nil, "f96"=>nil, "f97"=>nil, "f98"=>nil, "f99"=>nil, "f100"=>nil, "f101"=>nil, "f102"=>nil, "f103"=>nil, "f104"=>nil, "f105"=>nil, "f106"=>nil, "f107"=>nil, "f108"=>nil, "f109"=>nil, "f110"=>nil, "f111"=>nil, "f112"=>nil, "f113"=>nil, "f114"=>nil, "f115"=>nil, "f116"=>nil, "f117"=>nil, "f118"=>nil, "f119"=>nil, "f120"=>nil, "f121"=>nil, "f122"=>nil, "f123"=>nil, "f124"=>nil, "f125"=>nil, "f126"=>nil, "f127"=>nil, "f128"=>nil, "f129"=>nil, "f130"=>nil, "f131"=>nil, "f132"=>nil, "f133"=>nil, "f134"=>nil, "f135"=>nil, "f136"=>nil, "f137"=>nil, "f138"=>nil, "f139"=>nil, "f140"=>nil, "f141"=>nil, "f142"=>nil, "f143"=>nil, "f144"=>nil, "f145"=>nil, "f146"=>nil, "f147"=>nil, "f148"=>nil, "f149"=>nil, "f150"=>nil, "f151"=>nil, "f152"=>nil, "f153"=>nil, "f154"=>nil, "f155"=>nil, "f156"=>nil, "f157"=>nil, "f158"=>nil, "f159"=>nil, "f160"=>nil, "f161"=>nil, "f162"=>nil, "f163"=>nil, "f164"=>nil, "f165"=>nil, "f166"=>nil, "f167"=>nil, "f168"=>nil, "f169"=>nil, "f170"=>nil, "f171"=>nil, "f172"=>nil, "f173"=>nil, "f174"=>nil, "f175"=>nil, "f176"=>nil, "f177"=>nil, "f178"=>nil, "f179"=>nil, "f180"=>nil, "f181"=>nil, "f182"=>nil, "f183"=>nil, "f184"=>nil, "f185"=>nil, "f186"=>nil, "f187"=>nil, "f188"=>nil, "f189"=>nil, "f190"=>nil, "f191"=>nil, "f192"=>nil, "f193"=>nil, "f194"=>nil, "f195"=>nil, "f196"=>nil, "f197"=>nil, "f198"=>nil, "f199"=>nil, "f200"=>nil}}

Also, the Arguments.to_schema_form call seems to matter a great deal even though it's just transforming a data structure in memory and discarding it; if I skip that, the problem goes away, which is pretty mystifying:

$ GRAPHQL_VERSION=2.1.9 SKIP_ARG_CONVERSION=1 ruby graphql_bug.rb
{"data"=>{"f1"=>nil, "f2"=>nil, "f3"=>nil, "f4"=>nil, "f5"=>nil, "f6"=>nil, "f7"=>nil, "f8"=>nil, "f9"=>nil, "f10"=>nil, "f11"=>nil, "f12"=>nil, "f13"=>nil, "f14"=>nil, "f15"=>nil, "f16"=>nil, "f17"=>nil, "f18"=>nil, "f19"=>nil, "f20"=>nil, "f21"=>nil, "f22"=>nil, "f23"=>nil, "f24"=>nil, "f25"=>nil, "f26"=>nil, "f27"=>nil, "f28"=>nil, "f29"=>nil, "f30"=>nil, "f31"=>nil, "f32"=>nil, "f33"=>nil, "f34"=>nil, "f35"=>nil, "f36"=>nil, "f37"=>nil, "f38"=>nil, "f39"=>nil, "f40"=>nil, "f41"=>nil, "f42"=>nil, "f43"=>nil, "f44"=>nil, "f45"=>nil, "f46"=>nil, "f47"=>nil, "f48"=>nil, "f49"=>nil, "f50"=>nil, "f51"=>nil, "f52"=>nil, "f53"=>nil, "f54"=>nil, "f55"=>nil, "f56"=>nil, "f57"=>nil, "f58"=>nil, "f59"=>nil, "f60"=>nil, "f61"=>nil, "f62"=>nil, "f63"=>nil, "f64"=>nil, "f65"=>nil, "f66"=>nil, "f67"=>nil, "f68"=>nil, "f69"=>nil, "f70"=>nil, "f71"=>nil, "f72"=>nil, "f73"=>nil, "f74"=>nil, "f75"=>nil, "f76"=>nil, "f77"=>nil, "f78"=>nil, "f79"=>nil, "f80"=>nil, "f81"=>nil, "f82"=>nil, "f83"=>nil, "f84"=>nil, "f85"=>nil, "f86"=>nil, "f87"=>nil, "f88"=>nil, "f89"=>nil, "f90"=>nil, "f91"=>nil, "f92"=>nil, "f93"=>nil, "f94"=>nil, "f95"=>nil, "f96"=>nil, "f97"=>nil, "f98"=>nil, "f99"=>nil, "f100"=>nil, "f101"=>nil, "f102"=>nil, "f103"=>nil, "f104"=>nil, "f105"=>nil, "f106"=>nil, "f107"=>nil, "f108"=>nil, "f109"=>nil, "f110"=>nil, "f111"=>nil, "f112"=>nil, "f113"=>nil, "f114"=>nil, "f115"=>nil, "f116"=>nil, "f117"=>nil, "f118"=>nil, "f119"=>nil, "f120"=>nil, "f121"=>nil, "f122"=>nil, "f123"=>nil, "f124"=>nil, "f125"=>nil, "f126"=>nil, "f127"=>nil, "f128"=>nil, "f129"=>nil, "f130"=>nil, "f131"=>nil, "f132"=>nil, "f133"=>nil, "f134"=>nil, "f135"=>nil, "f136"=>nil, "f137"=>nil, "f138"=>nil, "f139"=>nil, "f140"=>nil, "f141"=>nil, "f142"=>nil, "f143"=>nil, "f144"=>nil, "f145"=>nil, "f146"=>nil, "f147"=>nil, "f148"=>nil, "f149"=>nil, "f150"=>nil, "f151"=>nil, "f152"=>nil, "f153"=>nil, "f154"=>nil, "f155"=>nil, "f156"=>nil, "f157"=>nil, "f158"=>nil, "f159"=>nil, "f160"=>nil, "f161"=>nil, "f162"=>nil, "f163"=>nil, "f164"=>nil, "f165"=>nil, "f166"=>nil, "f167"=>nil, "f168"=>nil, "f169"=>nil, "f170"=>nil, "f171"=>nil, "f172"=>nil, "f173"=>nil, "f174"=>nil, "f175"=>nil, "f176"=>nil, "f177"=>nil, "f178"=>nil, "f179"=>nil, "f180"=>nil, "f181"=>nil, "f182"=>nil, "f183"=>nil, "f184"=>nil, "f185"=>nil, "f186"=>nil, "f187"=>nil, "f188"=>nil, "f189"=>nil, "f190"=>nil, "f191"=>nil, "f192"=>nil, "f193"=>nil, "f194"=>nil, "f195"=>nil, "f196"=>nil, "f197"=>nil, "f198"=>nil, "f199"=>nil, "f200"=>nil, "f201"=>nil, "f202"=>nil, "f203"=>nil, "f204"=>nil, "f205"=>nil, "f206"=>nil, "f207"=>nil, "f208"=>nil, "f209"=>nil, "f210"=>nil, "f211"=>nil, "f212"=>nil, "f213"=>nil, "f214"=>nil, "f215"=>nil, "f216"=>nil, "f217"=>nil, "f218"=>nil, "f219"=>nil, "f220"=>nil, "f221"=>nil, "f222"=>nil, "f223"=>nil, "f224"=>nil, "f225"=>nil, "f226"=>nil, "f227"=>nil, "f228"=>nil, "f229"=>nil, "f230"=>nil, "f231"=>nil, "f232"=>nil, "f233"=>nil, "f234"=>nil, "f235"=>nil, "f236"=>nil, "f237"=>nil, "f238"=>nil, "f239"=>nil, "f240"=>nil, "f241"=>nil, "f242"=>nil, "f243"=>nil, "f244"=>nil, "f245"=>nil, "f246"=>nil, "f247"=>nil, "f248"=>nil, "f249"=>nil, "f250"=>nil, "f251"=>nil, "f252"=>nil, "f253"=>nil, "f254"=>nil, "f255"=>nil, "f256"=>nil, "f257"=>nil, "f258"=>nil, "f259"=>nil, "f260"=>nil, "f261"=>nil, "f262"=>nil, "f263"=>nil, "f264"=>nil, "f265"=>nil, "f266"=>nil, "f267"=>nil, "f268"=>nil, "f269"=>nil, "f270"=>nil, "f271"=>nil, "f272"=>nil, "f273"=>nil, "f274"=>nil, "f275"=>nil, "f276"=>nil, "f277"=>nil, "f278"=>nil, "f279"=>nil, "f280"=>nil, "f281"=>nil, "f282"=>nil, "f283"=>nil, "f284"=>nil, "f285"=>nil, "f286"=>nil, "f287"=>nil, "f288"=>nil, "f289"=>nil, "f290"=>nil, "f291"=>nil, "f292"=>nil, "f293"=>nil, "f294"=>nil, "f295"=>nil, "f296"=>nil, "f297"=>nil, "f298"=>nil, "f299"=>nil, "f300"=>nil}}
rmosolgo commented 10 months ago

@myronmarston 😻 digging in, thanks!

rmosolgo commented 10 months ago

Regarding Arguments.to_schema_form, it's the node.arguments call that triggers it; if you remove the Arguments.to_schema_form call, but retain node.arguments:

- Arguments.to_schema_form(node.arguments, node.field)
+ node.arguments

It still fails. I think this is because node.arguments eventually calls the Dataloader to run (because building Arguments objects may call dataloader sources in prepare: ... procs, etc).

Not that that fixes anything, but it's a clue... 🕵️ ...

rmosolgo commented 10 months ago

@swrobel, now I realize I don't understand how User.categories is fetched. Does that go through Dataloader? I see CategoryLoader above but it looks like it would take an offering_id...

swrobel commented 10 months ago

now I realize I don't understand how User.categories is fetched. Does that go through Dataloader?

No, no Dataloader. It's just a simple field:

field :categories, [Types::CategoryType], null: false
rmosolgo commented 10 months ago

although it prints this line 2x, which is curious:

@swrobel, @myronmarston found the same thing in 2.1.9 and reported it here: #4747. I'm going to get that worked out in #4748 then circle back here.

rmosolgo commented 10 months ago

I think these may both be due to the switch to .transfer-based Fiber handling. It has an unexpected (and maybe buggy?) result, which I wrote up here: https://github.com/rmosolgo/graphql-ruby/pull/4748#issuecomment-1868340432 and reported/asked about here: https://bugs.ruby-lang.org/issues/20081

rmosolgo commented 9 months ago

I just released GraphQL-Ruby 2.2.2 which, besides addressing #4747 (Fiber#transfer), also changes a bit how input objects are resolved.

@swrobel, when you get a chance, could you try that version? The spec which replicated #4747 passes on 2.2.2, but I'm not sure if that's exactly the same situation you were encountering here (since you were using AsyncDataloader, and that one was reported on "normal" Dataloader).

myronmarston commented 9 months ago

@rmosolgo I've confirmed that both 2.2.2 and 2.1.10 fix this issue for me. Thanks for the quick turn around on this!

swrobel commented 9 months ago

when you get a chance, could you try that version?

Using 2.2.2 with AsyncDataloader, it succeeds sporadically, but most requests fail with the circular dependency error.

mutation InitializeUI($input: CreateSessionInput!) {
  createSession(input: $input) {
    user {
      categories {
        id
        offerings {
          id
        }
      }
      offerings {
        id
      }
    }
  }
}

Paring it down to this smaller request, it succeeds every other time, and fails every other time with the circular dependency error (this seems to be consistent over dozens of the exact same request).

mutation InitializeUI($input: CreateSessionInput!) {
  createSession(input: $input) {
    user {
      categories {
        id
        offerings {
          id
        }
      }
    }
  }
}
Click to view exception backtrace ``` warn: Async::Task [oid=0xb798] [ec=0xb7ac] [pid=81838] [2023-12-28 08:44:59 -0800] | Task may have ended with unhandled exception. | RuntimeError: Loaders::Category::OfferingsLoader#sync tried 1000 times to load pending keys (["e91b2429-f4aa-44ff-9909-1f57f48afac0"]), but they still weren't loaded. There is likely a circular dependency. | → vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/dataloader/source.rb:101 in `sync' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/dataloader/source.rb:57 in `load' | app/graphql/types/category_type.rb:9 in `offerings' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/schema/field.rb:700 in `public_send' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/schema/field.rb:700 in `block (2 levels) in resolve' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/schema/field.rb:843 in `block in with_extensions' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/schema/field.rb:879 in `block (2 levels) in run_extensions_before_resolve' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/schema/field.rb:882 in `run_extensions_before_resolve' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/schema/field.rb:879 in `block in run_extensions_before_resolve' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/schema/field_extension.rb:134 in `resolve' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/schema/field.rb:866 in `run_extensions_before_resolve' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/schema/field.rb:838 in `with_extensions' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/schema/field.rb:669 in `block in resolve' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/execution/interpreter/runtime.rb:770 in `minimal_after_lazy' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/query.rb:372 in `after_lazy' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/schema/field.rb:667 in `resolve' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/execution/interpreter/runtime.rb:358 in `block (2 levels) in evaluate_selection_with_resolved_keyword_args' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/tracing/trace.rb:52 in `execute_field' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/execution/interpreter/runtime.rb:357 in `block in evaluate_selection_with_resolved_keyword_args' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/execution/interpreter/runtime.rb:709 in `call_method_on_directives' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/execution/interpreter/runtime.rb:354 in `evaluate_selection_with_resolved_keyword_args' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/execution/interpreter/runtime.rb:264 in `evaluate_selection' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/execution/interpreter/runtime.rb:214 in `block (2 levels) in evaluate_selections' | vendor/bundle/ruby/3.2.0/gems/graphql-2.2.2/lib/graphql/dataloader/async_dataloader.rb:65 in `block in spawn_job_task' | vendor/bundle/ruby/3.2.0/gems/async-2.6.5/lib/async/task.rb:160 in `block in run' | vendor/bundle/ruby/3.2.0/gems/async-2.6.5/lib/async/task.rb:330 in `block in schedule' ```
rmosolgo commented 9 months ago

Yeah, the fix on 2.2.2 was just for "normal" Dataloader. (Edit: I take it back, the improvement to run_isolated affected both implementations.) I did just release 2.2.3 with a fix for dangling live Fibers. Does that version fail the same way?

Could you share an example value for $input? I think the next thing to do is nail down a reproduction for this bug.

swrobel commented 9 months ago

I did just release 2.2.3 with a fix for dangling live Fibers. Does that version fail the same way?

Same behavior in 2.2.3

Could you share an example value for $input?

{"input": {"refreshToken": "8f2b217b-ae3b-4b53-aa19-611bb4512666:85d1287c-74ef-495c-9449-001b88fb416f"}}

It's either a refreshToken or jwt (using the former for these tests because they're longer-lived)

rmosolgo commented 9 months ago

I started to work on a replication script locally, and along the way, found another case where AsyncDataloader was running too many fetches: https://github.com/rmosolgo/graphql-ruby/commit/d1a2760bfc8e5c1066908d7029e8ca1a1f46e147

I have been trying and trying to find an approach that both allows I/O to run before circling around to Source#fetch calls, but also works for deeply-nested, isolated dataloader calls as reported in the other issue. The underlying problem is that I don't have a way for controlling which fibers might run when one fiber yields to async's event loop. As a result, if I wait for I/O in a field, then the next Fiber that runs may be one from a different dataloader call (async has only one event loop, and Ruby has only one Fiber scheduler).

After reworking the flow inside dataloader itself, and getting nowhere (at least, not getting everything working right...), my next try will be to implement async I/O by modifying source calls themselves. In that case, GraphQL fields wouldn't ever run in the background but sources would. I'll try that soon and follow up here.

rmosolgo commented 9 months ago

Right off the bat, limiting async to Source#fetch worked great: https://github.com/rmosolgo/graphql-ruby/pull/4757

But it means that I/O in GraphQL fields won't be async -- it'd have to be refactored into sources for that to work. But given the limitations of Fiber described above, I don't think it can be done better.

Maybe another approach, eg, concurrent-ruby, would work at a high level, but I that would introduce multi-Thread considerations...

swrobel commented 9 months ago

Thanks for the update, but it's a bummer to hear about the dead ends you've hit with the fiber scheduler. Have you gotten ioquatix's input? I know he's been supportive of your efforts.

rmosolgo commented 9 months ago

Yes, we've definitely been working together. He graciously reviewed the tickets I opened on the Ruby bug tracker (unfortunately, not in favor of changing the semantics of Fiber#transfer) and reviewed the reproduction of the previous "dangling Fiber" issue on the async gem (https://github.com/socketry/async/issues/295). But I couldn't find a solution that worked for GraphQL-Ruby, mainly because it has nested calls to dataloader.run, and each of those needs an isolated event loop. (I think, if I could run isolated event loops, then the unpredictable return of Fiber.transfer would be ok...)

rmosolgo commented 9 months ago

Btw @swrobel, would you mind giving your app a try on the branch in #4757? If I'm right about the source of AsyncDataloader's trouble, then that branch should work for you (but I never did get my replication script to fail the same way...).

swrobel commented 9 months ago

That branch worked! Thanks!

rmosolgo commented 9 months ago

Thanks for giving it a try -- glad to hear it. I really think the conditions for this error are gone. It wasn't actually a circular dependency, but rather, a Source was trying 1000 times to be resolved but it still wasn't resolved. This was due to the unpredictable scheduling of Fibers, where yielding might go right back to the source itself without trying other fibers. (And as previously described, I couldn't find a way of controlling that flow better :S). So, I've reduced the scope where the fiber scheduler is applied, so that there won't be as many open, unrelated fibers to choose between. I'm going to call this closed 😅