rmosolgo
dataloader potentially leaking fibers
Describe the bug
We've had a very strange recurring error where we get FiberErrors in production (but not in other environments, likely because of the volume of traffic). These errors have the message Can't set guard page: Out of Memory. Our instance isn't actually out of memory but it seems like the puma worker is unable to spawn any new fibers.
I've been trying to figure this one out for quite a long time now with no success, but I've noticed that after a request is finished, there'll be dangling dead fibers, and these build up over time and never get garbage collected.
Large fragments and queries are more affected than small ones because it seems like the number of fibers grow by minimum whatever fiber_limit is set to on each request. Setting fiber_limit to a lower value slows the growth down as fewer fibers will be spawned, but it doesn't resolve it as it still keeps on growing forever.
I've been trying to dig into what's still referencing the fibers causing them not to be GC'd but haven't been able to find it. Using the AsyncDataloader makes the problem a lot worse, increasing the growth.
We're on rails 7.0.8.6 and we don't have isolation_context = :fiber, and we use the regular GraphQL::Dataloader, but have tried setting that isolation context and using AsyncDataloader as well, without any luck
Versions
graphql version: 2.5.11
rails (or other framework): 7.0.8.6
Steps to reproduce
# config/initializers/fiber_debug.rb
module FiberDebug
def self.setup
patch_fiber_new
patch_fiber_yield
end
def self.patch_fiber_new
Fiber.singleton_class.prepend(Module.new do
def new(*args, **kwargs, &block)
fiber = super
Rails.logger.debug("Fiber created: #{fiber.object_id} by #{caller_locations(1,1)[0].label} #{caller_locations(1,1)[0].path}:#{caller_locations(1,1)[0].lineno}")
# Print when garbage collected
ObjectSpace.define_finalizer(fiber, proc { Rails.logger.debug("Fiber finalized: #{fiber.object_id}") })
fiber
end
end)
end
def self.patch_fiber_yield
Fiber.prepend(Module.new do
def yield(*args)
Rails.logger.debug("Fiber yielding: #{self.object_id}")
super
end
def resume(*args)
Rails.logger.debug("Fiber resuming: #{self.object_id}")
super
end
end)
end
end
# Print fiber information in development
if Rails.env.development?
FiberDebug.setup
Thread.new do
loop do
alive_count = ObjectSpace.each_object(Fiber).count { it.alive? }
dead_count = ObjectSpace.each_object(Fiber).count { !it.alive? }
dead_ids = ObjectSpace.each_object(Fiber).reject(&:alive?).map { it.object_id }
fiber_count = ObjectSpace.each_object(Fiber).count
puts "Fiber count: #{fiber_count} (#{alive_count} alive, #{dead_count} dead)"
puts ObjectSpace.each_object(Fiber).filter_map { !it.alive? && it.try(:created_by) ? [1, it.try(:created_by).try(:first)] : nil }.group_by(&:last).transform_values(&:count)
sleep 10
end
end
end
Execute a query with the initializer above included and see the growing number of dead fibers. Start puma in single mode for this initializer to work, otherwise move logic to puma on_worker_boot instead
Expected behavior
Dead fibers to be garbage collected over time
here's a full reproduction on a bare rails project: https://github.com/Amnesthesia/example-app
BASE_URL=http://test.example.com/ RAILS_ENV=test bundle exec rspec ./spec/graphql/fiber_leak_spec.rb
Hey, sorry for the trouble and thanks so much for the detailed report and reproduction.
I see the reproduction app uses Ruby 3.3.0. To confirm, is that the same version you use in production? (There have definitely been some weird Fiber issues in Ruby so I want to make sure I'm checking into the right thing.)
I'll take a look soon and see if I can make any progress figuring out why those Fibers are retained.
For reference, this gem already has a test to make sure Fibers are properly dead, but it doesn't actually make sure that they aren't retained: https://github.com/rmosolgo/graphql-ruby/blob/68f160f064c50f73e221bd42d5b71e74b22a3a14/spec/graphql/dataloader_spec.rb#L1104
Extending that test to make sure that Fibers are GCed might help tracking this down.
Hey
We use 3.4.5 in prod, but we have tried this with 3.3, 3.4.1 and 3.4.5 and get the same result.
For what its worth, I notice that GraphQL::Execution::Multiplex and GraphQL::Query are still in ObjectSpace after GC as well, possible that this is related and holding onto context/dataloader/preloader referencing dead fibers?
I spent some time today trying to track this down in the replication you shared. So far, no luck.
My best clue has been iterating ObjectSpace.each_object and trying to find objects that reference a Query or Multiplex. (I used obj.keys, obj.instance_variables, and obj.constants to track references.)
each_reference implementation
def each_reference(obj)
if obj.respond_to?(:keys) && obj.respond_to?(:"[]") && (k = obj.keys)
k.each do |key|
yield(obj[key], "#{obj.class}[#{key}]")
end
end
obj.instance_variables.each do |ivar|
yield(obj.instance_variable_get(ivar), "#{obj.class}#{ivar}")
end
if obj.respond_to?(:constants) && (c = obj.constants)
c.each do |const|
yield(obj.const_get(const), "#{obj}::#{const}")
end
end
# rescue WeakRef::RefError => err
# puts obj.class
# puts err.message
# puts err.backtrace
# nil
rescue StandardError, LoadError => err
# puts obj.class
nil
end
I found that many hashes had :__graphql_current_multiplex keys pointing to a multiplex. This is definitely a smell, or a clue. GraphQL-Ruby writes this:
https://github.com/rmosolgo/graphql-ruby/blob/68f160f064c50f73e221bd42d5b71e74b22a3a14/lib/graphql/execution/interpreter.rb#L41
but attempts to clean it up here:
https://github.com/rmosolgo/graphql-ruby/blob/68f160f064c50f73e221bd42d5b71e74b22a3a14/lib/graphql/execution/interpreter.rb#L141-L142
I know child Fibers inherit storage keys from their parents. It seems like this is implemented by duplicating them; I found that adding a local change like this made fewer of those :__graphql_current_multiplex keys:
--- a/lib/graphql/dataloader.rb
+++ b/lib/graphql/dataloader.rb
@@ -99,6 +99,7 @@ module GraphQL
# This method is called when Dataloader is finished using a fiber.
# Use it to perform any cleanup, such as releasing database connections (if required manually)
def cleanup_fiber
+ Fiber[:__graphql_current_multiplex] = nil
end
But, there's still one Hash in ObjectSpace with a :__graphql_current_multiplex key.
Interestingly, when I iterate ObjectSpace again, trying to find objects which reference that hash, no matches are found. Whatever is referencing that Hash is hiding its reference to it. (Or maybe there's another kind of reference I could check which I didn't think of. I didn't do "class variables" (@@) yet.) I tried .equal?, ==, and even .key?(:__graphql_current_multiplex) and none of them found any matches.
One possible clue, possible red herring, is that there's a WeakRef in ObjectSpace which raises an error in response to .respond_to?, "Invalid Reference - probably recycled". I know that ActiveRecord uses WeakRefs in some places, but looking over the source, I didn't see any connections, so I don't think this is going anywhere.
In some sense, this is almost hunt in the wrong direction. Even if I can find what's retaining the multiplex, the question remains, what's retaining the Fibers? Maybe that's an avenue to explore tomorrow.
This morning, I started trying to reduce the replication to the minimal case. In poking around, I discovered config/initializers/fiber_debug.rb which included adding finalizers to all Fibers. I think this is causing Fibers to be retained by Ruby 😖 . Here's a script to demonstrate:
Tracking fibers with GraphQL-Ruby
require "bundler/inline"
gemfile do
gem "graphql", "~>2.4.11"
end
require "objspace"
class FiberDebugging
class << self
def object_counts
{
alive: ObjectSpace.each_object(Fiber).count { it.alive? },
dead: ObjectSpace.each_object(Fiber).count { !it.alive? },
total: ObjectSpace.each_object(Fiber).count,
query: ObjectSpace.each_object(GraphQL::Query).count,
multiplex: ObjectSpace.each_object(GraphQL::Execution::Multiplex).count,
}
end
# Executes a block with aggressive garbage collection disabled, then performs
# multiple full GC cycles until no more objects can be freed, followed by compaction.
#
# @yield [block] the block to execute during GC disabled state
# @return [Object] the result of the yielded block
def with_aggressive_gc(&block)
result = nil
GC.disable
result = yield
# Aggressive GC
size = GC.stat[:heap_live_slots]
loop do
GC.start(full_mark: true, immediate_sweep: true)
new_size = GC.stat[:heap_live_slots]
break if new_size >= size
size = new_size
end
GC.compact
result
end
end
end
if ENV["FINALIZE_FIBER"]
puts "Adding finalizer to all Fibers"
Fiber.singleton_class.prepend(Module.new do
def new(*args, **kwargs, &block)
fiber = super
# Print when garbage collected
ObjectSpace.define_finalizer(fiber, proc { puts "Fiber finalized: #{fiber.object_id}" })
fiber
end
end)
end
class MinimalSchema < GraphQL::Schema
class Query < GraphQL::Schema::Object
field :f, Int, fallback_value: 1
end
query(Query)
use GraphQL::Dataloader
end
pp FiberDebugging.object_counts
3.times do
FiberDebugging.with_aggressive_gc do
pp MinimalSchema.execute("{ __typename }").to_h
end
FiberDebugging.with_aggressive_gc do
pp MinimalSchema.execute("{ __typename }").to_h
end
end
pp FiberDebugging.object_counts
When you run it without finalizers, Fibers are cleaned up as expected:
$ ruby fiber_script.rb
{alive: 1, dead: 0, total: 1, query: 0, multiplex: 0}
{"data" => {"__typename" => "Query"}}
{"data" => {"__typename" => "Query"}}
{"data" => {"__typename" => "Query"}}
{"data" => {"__typename" => "Query"}}
{"data" => {"__typename" => "Query"}}
{"data" => {"__typename" => "Query"}}
{alive: 1, dead: 0, total: 1, query: 1, multiplex: 1}
When you run it with finalizers, the Fibers are not GCed. Instead, they're all finalized when the script exits:
$ FINALIZE_FIBER=1 ruby fiber_script.rb
Adding finalizer to all Fibers
{alive: 1, dead: 0, total: 1, query: 0, multiplex: 0}
{"data" => {"__typename" => "Query"}}
{"data" => {"__typename" => "Query"}}
{"data" => {"__typename" => "Query"}}
{"data" => {"__typename" => "Query"}}
{"data" => {"__typename" => "Query"}}
{"data" => {"__typename" => "Query"}}
{alive: 1, dead: 24, total: 25, query: 6, multiplex: 6}
Fiber finalized: 648
Fiber finalized: 656
Fiber finalized: 664
Fiber finalized: 672
Fiber finalized: 680
Fiber finalized: 688
Fiber finalized: 696
Fiber finalized: 704
Fiber finalized: 712
Fiber finalized: 720
Fiber finalized: 728
Fiber finalized: 736
Fiber finalized: 744
Fiber finalized: 752
Fiber finalized: 760
Fiber finalized: 768
Fiber finalized: 776
Fiber finalized: 784
Fiber finalized: 792
Fiber finalized: 800
Fiber finalized: 808
Fiber finalized: 816
Fiber finalized: 824
Fiber finalized: 832
This seems like a bug in Ruby -- the finalizer is preventing Fibers from being GCed.
What about multiplex: 6 and query: 6? I have known for a long time that the last-executed query is somehow retained by GraphQL-Ruby. The gem's on memory benchmarks show a bit of retained memory. I know it's just the last-executed query; it doesn't accumulate across runs so it's not really a "leak." I've never been able to find where it's retained. The first script above has query: 1: just one query retained despite running 6 of them. The second run has 6 retained -- presumably one for each non-GCed execution fiber. I'm not sure what to do next on that.
Going back to the full replication script, I'm able to "fix" it by removing the finalizer line:
@@ -13,19 +13,19 @@ module FiberDebug
Rails.logger.debug("Fiber created: #{fiber.object_id} by #{caller_locations(1,1)[0].label} #{caller_locations(1,1)[0].path}:#{caller_locations(1,1)[0].lineno}")
# Print when garbage collected
- ObjectSpace.define_finalizer(fiber, proc { Rails.logger.debug("Fiber finalized: #{fiber.object_id}") })
+ # ObjectSpace.define_finalizer(fiber, proc { Rails.logger.debug("Fiber finalized: #{fiber.object_id}") })
fiber
end
end)
end
After that, the tests "fail" as expected, for example:
1) Resolvers::Appointments Querying appointments with forced garbage collection doesnt clean up dead fibers is expected to eq {:alive => 1, :dead => 40, :total => 41}
Failure/Error: it { is_expected.to eq({ alive: 1, total: 1 + (idx * 20), dead: (idx * 20) }) }
expected: {:alive => 1, :dead => 40, :total => 41}
got: {:alive => 1, :dead => 0, :total => 1}
(compared using ==)
In your real app, does removing the finalizer fix this behavior in development?
But I think that's a red herring, because you said it runs out of memory in production, right? Do you run fiber_limit: ... in production?
@rmosolgo Wow! Thank you so much for your detailed and thorough investigation! I love that you're so active and engaged on here, it really makes it feel worthwhile taking the time to report bugs and setting up minimal repros!
Now, if removing the finalizer actually gets this working as intended, then it must be something else :| To be clear, we dont have this debugging code in production, it was only added to this repo so that we could debug it better — but if the finalizer is what caused it to be possible to write specs for it, that's really unfortunate because although the specs fail when commenting out the finalizer, you can still reproduce it if you start up puma and running queries repeatedly. Could it be something in puma holding on to the fibers?
Steps to reproduce:
- Comment out the finalizer
- Seed the database
bundle exec rails db:seed - Start rails:
bundle exec rails s -b 0.0.0.0 -p 3000 - Open
Altair - Execute a query repeatedly
- Look at the debugging output
Here's the query I'm running:
query {
appointments {
edges {
node {
id
gid
title
startTime
owner {
id
name
}
appointmentGuests {
id
user {
id
name
}
}
}
}
}
}
Here's what I see in the console:
Started POST "/graphql" for 127.0.0.1 at 2025-07-28 10:03:19 +1000
Processing by GraphqlController#execute as JSON
Parameters: {"query" => "query {\n appointments {\n edges {\n node {\n id\n gid\n title\n startTime\n owner {\n id\n name\n }\n appointmentGuests {\n id\n user {\n id\n name\n }\n }\n }\n }\n }\n}", "variables" => {}, "operationName" => nil, "graphql" => {"query" => "query {\n appointments {\n edges {\n node {\n id\n gid\n title\n startTime\n owner {\n id\n name\n }\n appointmentGuests {\n id\n user {\n id\n name\n }\n }\n }\n }\n }\n}", "variables" => {}, "operationName" => nil}}
Fiber created: 5120 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5120
Fiber created: 5128 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5128
Appointment Load (0.3ms) SELECT "appointments".* FROM "appointments" LIMIT -1 OFFSET ? /*application:Exampleapp,controller:graphql,action:execute*/ [["OFFSET", 0]]
Fiber created: 5144 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5144
User Load (9.9ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? /*application:Exampleapp,controller:graphql,action:execute*/ [["id", 21]]
↳ app/graphql/sources/association.rb:113:in 'Sources::Association#fetch_items'
Fiber resuming: 5128
Fiber created: 5152 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5152
Fiber resuming: 5128
Fiber created: 5160 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5160
Fiber resuming: 5128
Fiber created: 5168 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5168
Fiber resuming: 5128
Fiber created: 5176 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5176
Fiber resuming: 5128
Fiber created: 5184 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5184
Fiber resuming: 5128
Fiber created: 5192 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5192
Fiber resuming: 5128
Fiber created: 5200 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5200
Fiber resuming: 5128
Fiber created: 5208 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5208
Fiber resuming: 5128
Fiber created: 5216 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5216
Fiber resuming: 5128
Fiber created: 5224 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5224
Fiber resuming: 5128
Fiber created: 5232 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5232
Fiber resuming: 5128
Fiber created: 5240 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5240
Fiber resuming: 5128
Fiber created: 5248 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5248
Fiber resuming: 5128
Fiber created: 5256 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5256
Fiber resuming: 5128
Fiber created: 5264 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5264
Fiber created: 5272 by GraphQL::Dataloader#spawn_fiber /Users/amnesthesia/.asdf/installs/ruby/3.4.1/lib/ruby/gems/3.4.0/gems/graphql-2.4.17/lib/graphql/dataloader.rb:253
Fiber resuming: 5272
Completed 200 OK in 47ms (Views: 0.5ms | ActiveRecord: 10.1ms | Allocations: 11426)
Fiber count: 83 (7 alive, 76 dead)
{}
Dead fibers: 4512, 4584, 4632, 4624, 4616, 4608, 4600, 4592, 4688, 4680, 4672, 4664, 4656, 4648, 4640, 4704, 4696, 4896, 4888, 4880, 4872, 4864, 4856, 4848, 4840, 4832, 4824, 4816, 4808, 4800, 4792, 4784, 4376, 4368, 4776, 4768, 4752, 4744, 4952, 4936, 4928, 4992, 4984, 4976, 4968, 4960, 5032, 5024, 5016, 5008, 5000, 5080, 5072, 5064, 5056, 5048, 5040, 5128, 5120, 5152, 5144, 5192, 5184, 5176, 5168, 5160, 5240, 5232, 5224, 5216, 5208, 5200, 5272, 5264, 5256, 5248
Even after leaving it idle for some time, these aren't being GC'd ....
As I mentioned, in our real app we dont have the FiberDebug initializer and we don't add finalizers to the fibers — but, we do get FiberErrors regularly and our instances aren't low on memory; in fact, they're often running at around 6.5GB/16Gb. And yes, we do run fiber_limit: 5 in production, but we have only recently added this because we wanted to see if this reduces the FiberErrors.
This is what our backtrace looks like:
FiberError: can't set a guard page: Out of memory
lib/graphql/dataloader.rb:248 Fiber#resume
lib/graphql/dataloader.rb:248 GraphQL::Dataloader#run_fiber
lib/graphql/dataloader.rb:230 GraphQL::Dataloader#run
lib/graphql/execution/interpreter.rb:91 block in GraphQL::Execution::Interpreter.run_all
lib/graphql/tracing/trace.rb:64 GraphQL::Tracing::Trace#execute_multiplex
lib/graphql/fragment_cache/schema/instrumentation.rb:36 GraphQL::FragmentCache::Schema::Instrumentation::Tracer#execute_multiplex
lib/graphql/persisted_queries/compiled_queries/instrumentation.rb:37 GraphQL::PersistedQueries::CompiledQueries::Instrumentation::Tracer#execute_multiplex
lib/graphql/tracing/monitor_trace.rb:197 block in GraphQL::Tracing::AppsignalTrace#execute_multiplex
lib/graphql/tracing/appsignal_trace.rb:33 block in GraphQL::Tracing::AppsignalTrace::AppsignalMonitor#instrument
lib/appsignal/transaction.rb:632 Appsignal::Transaction#instrument
lib/appsignal/helpers/instrumentation.rb:761 Appsignal::Helpers::Instrumentation#instrument
lib/graphql/tracing/appsignal_trace.rb:32 GraphQL::Tracing::AppsignalTrace::AppsignalMonitor#instrument
lib/graphql/tracing/monitor_trace.rb:196 GraphQL::Tracing::AppsignalTrace#execute_multiplex
lib/graphql/execution/interpreter.rb:42 GraphQL::Execution::Interpreter.run_all
lib/graphql/schema.rb:1603 GraphQL::Schema.multiplex
app/graphql/extensions/schema/execution.rb:44 Extensions::Schema::Execution::ClassMethods#multiplex_authenticated
app/graphql/extensions/schema/execution.rb:122 Extensions::Schema::Execution::ClassMethods#execute_authenticated
app/controllers/graphql_controller.rb:61 GraphqlController#execute
lib/action_controller/metal/basic_implicit_render.rb:6 ActionController::BasicImplicitRender#send_action
lib/abstract_controller/base.rb:215 AbstractController::Base#process_action
lib/action_controller/metal/rendering.rb:165 ActionController::Rendering#process_action
lib/abstract_controller/callbacks.rb:234 block in AbstractController::Callbacks#process_action
lib/active_support/callbacks.rb:118 block in ActiveSupport::Callbacks#run_callbacks
app/controllers/application_controller.rb:125 block in ApplicationController#set_logging_tags
lib/semantic_logger/base.rb:190 block in SemanticLogger::Base#tagged
lib/semantic_logger/semantic_logger.rb:395 SemanticLogger.named_tagged
lib/semantic_logger/base.rb:197 SemanticLogger::Base#tagged
app/controllers/application_controller.rb:124 ApplicationController#set_logging_tags
lib/active_support/callbacks.rb:127 block in ActiveSupport::Callbacks#run_callbacks
lib/active_support/core_ext/time/zones.rb:65 Time.use_zone
app/controllers/application_controller.rb:229 ApplicationController#set_current_practice_timezone
lib/active_support/callbacks.rb:127 block in ActiveSupport::Callbacks#run_callbacks
lib/active_support/callbacks.rb:138 ActiveSupport::Callbacks#run_callbacks
lib/abstract_controller/callbacks.rb:233 AbstractController::Callbacks#process_action
lib/action_controller/metal/rescue.rb:23 ActionController::Rescue#process_action
lib/action_controller/metal/instrumentation.rb:67 block in ActionController::Instrumentation#process_action
lib/appsignal/hooks/active_support_notifications.rb:19 block in ActiveSupport::Notifications.instrument
lib/active_support/notifications/instrumenter.rb:24 ActiveSupport::Notifications::Instrumenter#instrument
lib/appsignal/hooks/active_support_notifications.rb:18 ActiveSupport::Notifications.instrument
lib/action_controller/metal/instrumentation.rb:66 ActionController::Instrumentation#process_action
lib/action_controller/metal/params_wrapper.rb:259 ActionController::ParamsWrapper#process_action
lib/searchkick/controller_runtime.rb:15 Searchkick::ControllerRuntime#process_action
lib/active_record/railties/controller_runtime.rb:27 ActiveRecord::Railties::ControllerRuntime#process_action
lib/abstract_controller/base.rb:151 AbstractController::Base#process
lib/action_view/rendering.rb:39 ActionView::Rendering#process
lib/action_controller/metal.rb:188 ActionController::Metal#dispatch
lib/action_controller/metal.rb:251 ActionController::Metal.dispatch
lib/action_dispatch/routing/route_set.rb:49 ActionDispatch::Routing::RouteSet::Dispatcher#dispatch
lib/action_dispatch/routing/route_set.rb:32 ActionDispatch::Routing::RouteSet::Dispatcher#serve
lib/action_dispatch/journey/router.rb:50 block in ActionDispatch::Journey::Router#serve
lib/action_dispatch/journey/router.rb:32 Array#each
lib/action_dispatch/journey/router.rb:32 ActionDispatch::Journey::Router#serve
lib/action_dispatch/routing/route_set.rb:852 ActionDispatch::Routing::RouteSet#call
lib/rack/attack.rb:127 Rack::Attack#call
lib/apollo_upload_server/middleware.rb:19 ApolloUploadServer::Middleware#call
lib/rack/brotli/deflater.rb:34 Rack::Brotli::Deflater#call
lib/rack/deflater.rb:44 Rack::Deflater#call
lib/apartment/elevators/generic.rb:22 block in Apartment::Elevators::Generic#call
lib/apartment/adapters/abstract_adapter.rb:89 Apartment::Adapters::AbstractAdapter#switch
/usr/local/lib/ruby/3.4.0/forwardable.rb:240 Apartment::Tenant#switch
lib/apartment/elevators/generic.rb:22 Apartment::Elevators::Generic#call
lib/apartment/rescued_apartment_middleware.rb:9 Apartment::RescuedApartmentMiddleware#call
lib/warden/manager.rb:36 block in Warden::Manager#call
lib/warden/manager.rb:34 Kernel#catch
lib/warden/manager.rb:34 Warden::Manager#call
lib/rack/tempfile_reaper.rb:15 Rack::TempfileReaper#call
lib/rack/etag.rb:27 Rack::ETag#call
lib/rack/conditional_get.rb:40 Rack::ConditionalGet#call
lib/rack/head.rb:12 Rack::Head#call
lib/action_dispatch/http/permissions_policy.rb:38 ActionDispatch::PermissionsPolicy::Middleware#call
lib/action_dispatch/http/content_security_policy.rb:39 ActionDispatch::ContentSecurityPolicy::Middleware#call
lib/action_dispatch/middleware/cookies.rb:704 ActionDispatch::Cookies#call
lib/action_dispatch/middleware/callbacks.rb:27 block in ActionDispatch::Callbacks#call
lib/active_support/callbacks.rb:99 ActiveSupport::Callbacks#run_callbacks
lib/action_dispatch/middleware/callbacks.rb:26 ActionDispatch::Callbacks#call
lib/appsignal/rack/abstract_middleware.rb:91 Appsignal::Rack::AbstractMiddleware#call_app
lib/appsignal/rack/abstract_middleware.rb:86 Appsignal::Rack::AbstractMiddleware#instrument_app_call
lib/appsignal/rack/abstract_middleware.rb:110 Appsignal::Rack::AbstractMiddleware#instrument_app_call_with_exception_handling
lib/appsignal/rack/abstract_middleware.rb:51 Appsignal::Rack::AbstractMiddleware#call
lib/action_dispatch/middleware/debug_exceptions.rb:28 ActionDispatch::DebugExceptions#call
lib/action_dispatch/middleware/show_exceptions.rb:29 ActionDispatch::ShowExceptions#call
lib/rails_semantic_logger/rack/logger.rb:45 RailsSemanticLogger::Rack::Logger#call_app
lib/rails_semantic_logger/rack/logger.rb:28 RailsSemanticLogger::Rack::Logger#call
lib/action_dispatch/middleware/remote_ip.rb:93 ActionDispatch::RemoteIp#call
lib/request_store/middleware.rb:19 RequestStore::Middleware#call
lib/action_dispatch/middleware/request_id.rb:26 ActionDispatch::RequestId#call
lib/rack/method_override.rb:24 Rack::MethodOverride#call
lib/rack/runtime.rb:22 Rack::Runtime#call
lib/active_support/cache/strategy/local_cache_middleware.rb:29 ActiveSupport::Cache::Strategy::LocalCache::Middleware#call
lib/action_dispatch/middleware/executor.rb:14 ActionDispatch::Executor#call
lib/rack/sendfile.rb:110 Rack::Sendfile#call
lib/action_dispatch/middleware/host_authorization.rb:131 ActionDispatch::HostAuthorization#call
lib/fatal_crash_middleware.rb:5 FatalCrashMiddleware#call
lib/rack/events.rb:112 Rack::Events#call
lib/rack/cors.rb:102 Rack::Cors#call
lib/action_dispatch/middleware/static.rb:23 ActionDispatch::Static#call
lib/rails/engine.rb:530 Rails::Engine#call
lib/puma/configuration.rb:279 Puma::Configuration::ConfigMiddleware#call
lib/puma/request.rb:99 block in Puma::Request#handle_request
lib/puma/thread_pool.rb:390 Puma::ThreadPool#with_force_shutdown
lib/puma/request.rb:98 Puma::Request#handle_request
lib/puma/server.rb:472 Puma::Server#process_client
lib/puma/server.rb:254 block in Puma::Server#run
lib/puma/thread_pool.rb:167 block in Puma::ThreadPool#spawn_thread
active and engaged
I'm glad you think so -- GraphQL-Ruby is pretty much my thing these days, so I'm doing my best! Like you said, it takes a long time to prepare a good bug report, especially with a reproduction -- and I really appreciate that too.
puma
It certainly could be puma, but in my past reading, I've seen more cases where ActiveRecord holds on to Fibers via connection pooling. (Admittedly those other issues used other Rails versions or isolation_level = :fiber.)
Here are some related-ish issues, with similar error messages or similar symptoms:
- https://github.com/rmosolgo/graphql-ruby/discussions/4874
- https://github.com/rmosolgo/graphql-ruby/issues/5128
- https://github.com/rmosolgo/graphql-ruby/issues/5168
I'll take a look at the reproduction again soon and see if I can find where those fibers are being retained.