Stack Level Too Deep When NullStore

[LRFalk01]

I'm running into an issue that is kind of difficult to explain. I have a mutation that enters an infinite loop as outlined in the given stack-trace snippet. When I run a query selecting the same thing, it works fine even when caching against a NullStore. The mutation works when caching is enabled. I'm not super sure how to give more detail here. I'm happy to give more information if I'm able. As a test, I went ahead and updated my version of the GQL lib to latest, and this is sell reproducible. I've also as a test reverted #116 and the issue goes away.

 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/schema/instrumentation.rb:37:in `execute_multiplex'",
 "/graphql-batch-0.6.0/lib/graphql/batch/setup_multiplex.rb:24:in `execute_multiplex'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:38:in `run_all'",
 "/graphql-2.3.14/lib/graphql/query.rb:243:in `result'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/fragment.rb:88:in `final_value'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/fragment.rb:60:in `with_final_value?'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/cacher.rb:66:in `select'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/cacher.rb:66:in `select_valid_fragments'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/cacher.rb:46:in `batched_persist'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/cacher.rb:37:in `call'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/schema/instrumentation.rb:18:in `after_query'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/schema/instrumentation.rb:31:in `execute_query'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:70:in `block (3 levels) in run_all'",
 "/graphql-2.3.14/lib/graphql/dataloader/null_dataloader.rb:19:in `append_job'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:58:in `block (2 levels) in run_all'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:54:in `each'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:54:in `each_with_index'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:54:in `block in run_all'",
 "/graphql-2.3.14/lib/graphql/tracing/trace.rb:40:in `execute_multiplex'",
 "/graphql-2.3.14/lib/graphql/backtrace/trace.rb:47:in `execute_multiplex'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/schema/instrumentation.rb:37:in `execute_multiplex'",
 "/graphql-batch-0.6.0/lib/graphql/batch/setup_multiplex.rb:24:in `execute_multiplex'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:38:in `run_all'",
 "/graphql-2.3.14/lib/graphql/query.rb:243:in `result'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/fragment.rb:88:in `final_value'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/fragment.rb:60:in `with_final_value?'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/cacher.rb:66:in `select'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/cacher.rb:66:in `select_valid_fragments'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/cacher.rb:46:in `batched_persist'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/cacher.rb:37:in `call'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/schema/instrumentation.rb:18:in `after_query'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/schema/instrumentation.rb:31:in `execute_query'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:70:in `block (3 levels) in run_all'",
 "/graphql-2.3.14/lib/graphql/dataloader/null_dataloader.rb:19:in `append_job'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:58:in `block (2 levels) in run_all'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:54:in `each'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:54:in `each_with_index'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:54:in `block in run_all'",
 "/graphql-2.3.14/lib/graphql/tracing/trace.rb:40:in `execute_multiplex'",
 "/graphql-2.3.14/lib/graphql/backtrace/trace.rb:47:in `execute_multiplex'",
 "/graphql-fragment_cache-1.20.5/lib/graphql/fragment_cache/schema/instrumentation.rb:37:in `execute_multiplex'",

[DmitryTsepelev]

Hey hey, before we proceed, could you please try to update to the latest version of the gem (1.22.0) and send me the updated stacktrace? 🙂

Another thing to be sure: do you have compiled queries turned on?

[LRFalk01]

Here is the stacktrace snippet while running on 1.22.0. We are not using graphql-ruby-persisted_queries/compiled queries.

 "/graphql-2.3.14/lib/graphql/query.rb:243:in `result'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/fragment.rb:100:in `final_value'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/fragment.rb:72:in `with_final_value?'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/cacher.rb:66:in `select'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/cacher.rb:66:in `select_valid_fragments'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/cacher.rb:46:in `batched_persist'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/cacher.rb:37:in `call'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/schema/instrumentation.rb:18:in `after_query'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/schema/instrumentation.rb:31:in `execute_query'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:70:in `block (3 levels) in run_all'",
 "/graphql-2.3.14/lib/graphql/dataloader/null_dataloader.rb:19:in `append_job'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:58:in `block (2 levels) in run_all'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:54:in `each'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:54:in `each_with_index'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:54:in `block in run_all'",
 "/graphql-2.3.14/lib/graphql/tracing/trace.rb:40:in `execute_multiplex'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/schema/instrumentation.rb:37:in `execute_multiplex'",
 "/graphql-batch-0.6.0/lib/graphql/batch/setup_multiplex.rb:24:in `execute_multiplex'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:38:in `run_all'",
 "/graphql-2.3.14/lib/graphql/query.rb:243:in `result'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/fragment.rb:100:in `final_value'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/fragment.rb:72:in `with_final_value?'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/cacher.rb:66:in `select'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/cacher.rb:66:in `select_valid_fragments'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/cacher.rb:46:in `batched_persist'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/cacher.rb:37:in `call'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/schema/instrumentation.rb:18:in `after_query'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/schema/instrumentation.rb:31:in `execute_query'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:70:in `block (3 levels) in run_all'",
 "/graphql-2.3.14/lib/graphql/dataloader/null_dataloader.rb:19:in `append_job'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:58:in `block (2 levels) in run_all'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:54:in `each'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:54:in `each_with_index'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:54:in `block in run_all'",
 "/graphql-2.3.14/lib/graphql/tracing/trace.rb:40:in `execute_multiplex'",
 "/graphql-fragment_cache-1.22.0/lib/graphql/fragment_cache/schema/instrumentation.rb:37:in `execute_multiplex'",
 "/graphql-batch-0.6.0/lib/graphql/batch/setup_multiplex.rb:24:in `execute_multiplex'",
 "/graphql-2.3.14/lib/graphql/execution/interpreter.rb:38:in `run_all'",
 "/graphql-2.3.14/lib/graphql/query.rb:243:in `result'",

[DmitryTsepelev]

Is it only one mutation? Maybe there's something specific inside?

I tried to reproduce it in specs, but failed 🤷‍♂️

[zzeniou86]

Hello @DmitryTsepelev! We are facing the same issue, and we are able to reproduce a similar backtrace, which results in stack level too deep (SystemStackError). Here's the snippet of the backtrace (we are on 1.22):

graphql (2.5.6) lib/graphql/execution/interpreter.rb:42:in `run_all'
graphql (2.5.6) lib/graphql/query.rb:281:in `result'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/fragment.rb:100:in `final_value'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/fragment.rb:72:in `with_final_value?'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/cacher.rb:66:in `select'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/cacher.rb:66:in `select_valid_fragments'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/cacher.rb:46:in `batched_persist'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/cacher.rb:37:in `call'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/schema/instrumentation.rb:18:in `after_query'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/schema/instrumentation.rb:31:in `execute_query'
graphql (2.5.6) lib/graphql/execution/interpreter.rb:79:in `block (3 levels) in run_all'
graphql (2.5.6) lib/graphql/dataloader/null_dataloader.rb:19:in `append_job'
graphql (2.5.6) lib/graphql/execution/interpreter.rb:67:in `block (2 levels) in run_all'
graphql (2.5.6) lib/graphql/execution/interpreter.rb:61:in `each'
graphql (2.5.6) lib/graphql/execution/interpreter.rb:61:in `each_with_index'
graphql (2.5.6) lib/graphql/execution/interpreter.rb:61:in `block in run_all'
graphql (2.5.6) lib/graphql/tracing/trace.rb:64:in `execute_multiplex'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/schema/instrumentation.rb:36:in `execute_multiplex'
graphql-batch (0.6.0) lib/graphql/batch/setup_multiplex.rb:24:in `execute_multiplex'
graphql (2.5.6) lib/graphql/schema/timeout.rb:68:in `execute_multiplex'
graphql (2.5.6) lib/graphql/execution/interpreter.rb:42:in `run_all'
graphql (2.5.6) lib/graphql/query.rb:281:in `result'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/fragment.rb:100:in `final_value'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/fragment.rb:72:in `with_final_value?'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/cacher.rb:66:in `select'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/cacher.rb:66:in `select_valid_fragments'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/cacher.rb:46:in `batched_persist'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/cacher.rb:37:in `call'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/schema/instrumentation.rb:18:in `after_query'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/schema/instrumentation.rb:31:in `execute_query'
graphql (2.5.6) lib/graphql/execution/interpreter.rb:79:in `block (3 levels) in run_all'
graphql (2.5.6) lib/graphql/dataloader/null_dataloader.rb:19:in `append_job'
graphql (2.5.6) lib/graphql/execution/interpreter.rb:67:in `block (2 levels) in run_all'
graphql (2.5.6) lib/graphql/execution/interpreter.rb:61:in `each'
graphql (2.5.6) lib/graphql/execution/interpreter.rb:61:in `each_with_index'
graphql (2.5.6) lib/graphql/execution/interpreter.rb:61:in `block in run_all'
graphql (2.5.6) lib/graphql/tracing/trace.rb:64:in `execute_multiplex'
graphql-ruby-fragment_cache (845c826e92b8) lib/graphql/fragment_cache/schema/instrumentation.rb:36:in `execute_multiplex'
graphql-batch (0.6.0) lib/graphql/batch/setup_multiplex.rb:24:in `execute_multiplex'
graphql (2.5.6) lib/graphql/schema/timeout.rb:68:in `execute_multiplex'
graphql (2.5.6) lib/graphql/execution/interpreter.rb:42:in `run_all'

We've noticed this line:

graphql (2.5.6) lib/graphql/dataloader/null_dataloader.rb:19:in `append_job'

If we add use GraphQL::Dataloader to the schema, then the issue is gone. I believe you should be able to reproduce it in the specs by not using Dataloader (or explicitly use the NullDataloader). Reverting the https://github.com/DmitryTsepelev/graphql-ruby-fragment_cache/pull/116 also works. Perhaps the new Tracer module is not taking NullDataloader into account?

FYI, We are using the graphql-batch gem instead of Dataloader, but even so, we are applying caching to a field that does not use batching. We also don't use graphql-ruby-persisted_queries.

We are considering reverting https://github.com/DmitryTsepelev/graphql-ruby-fragment_cache/pull/116 as a fix, but it would be great if we can fix the new tracer module.

Excellent job with this project by the way!

[zzeniou86]

Also, this is happening only on mutations.