Puma raises WARNING: Detected 1 Thread(s) started in app boot with preload_app and workers

[swistak]

Steps to reproduce

• Uncomment the preload_app and workers commands.
• Start server.

RAILS_ENV=production pumactl start
[20350] Puma starting in cluster mode...
[20350] * Version 3.12.1 (ruby 2.6.3-p62), codename: Llamas in Pajamas
[20350] * Min threads: 5, max threads: 5
[20350] * Environment: production
[20350] * Process workers: 2
[20350] * Preloading application
[20350] * Listening on tcp://0.0.0.0:3000
[20350] ! WARNING: Detected 1 Thread(s) started in app boot:
[20350] ! #<Thread:0x0000000005156350@/home/swistak/.rvm/gems/ruby-2.6.3/gems/activerecord-6.0.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:335 sleep> - /home/swistak/.rvm/gems/ruby-2.6.3/gems/activerecord-6.0.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:337:in `sleep'
[20350] Use Ctrl-C to stop
[20350] - Worker 0 (pid: 20357) booted, phase: 0
[20350] - Worker 1 (pid: 20367) booted, phase: 0

Expected behavior

Lack of warning, unless it's really dangerous. Is there a way to avoid that warning? If not possibly a documentation should mention that when you enable combination of those options (which config file recommends), you will get that warning

Actual behavior

No idea if this warning is dengerous or not, but probably should not happen with the default configuration.

It seems that connection pool is only creating a new thread in a production environment, does not happen in development.

System configuration

Rails version: 6.0.0pre

Ruby version: 2.6.3-p62

Puma version: 3.12.1

[chebyte]

I have the same problem, any update?

[rails-bot]

This issue has been automatically marked as stale because it has not been commented on for at least three months.
The resources of the Rails team are limited, and so we are asking for your help.
If you can still reproduce this error on the 6-0-stable branch or on master, please reply with all of the information you have about it in order to keep the issue open.
Thank you for all your contributions.

[h0jeZvgoxFepBQ2C]

Related: #25259

[jrochkind]

Does anyone have more info about this?

You still get this error under ActiveRecord 6.0.3.3 and puma 4.3.5, if you have puma configured with heroku's recommendations. (multiple processes with preload, also on_worker_boot { ActiveRecord::Base.establish_connection }, don't know if that's relevant).

<Thread:0x000055c7aaa0ac68@/app/vendor/bundle/ruby/2.6.0/gems/activerecord-6.0.3.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:334 sleep> - /app/vendor/bundle/ruby/2.6.0/gems/activerecord-6.0.3.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:337:in `sleep'

puma is warning that a thread is started BEFORE fork happens, so may not exist where expected in forked process. It looks like the thread started is meant to be a "reaper" thread, eliminating abandoned connections from the connection pool.

It may not be running in all of your puma processes, meaning some of them may not be reaping abandoned connections. Maybe this isn't a problem, but definitely isn't as intended. Perhaps this should be re-opened?

Paging @schneems (hope you don't mind, let me know if you do), since this happens under the recommended heroku puma configuration (which is where I noticed it), and heroku may want to take account.

[schneems]

The warning is a bit...premature. It was added to puma on the assumption that the developer wouldn't realize that the thread was also running in each fork. But there are cases where we legitimately want a background thread running in the main worker process. I'm not sure how to square those two things. Basically: There's nothing inherently wrong with having threads running in your worker process, but it might not do what some people think. It's a messaging problem.

[jrochkind]

Oh! Thanks for the clarification. OK, it's a false positive.

I misunderstood, and thought it was warning that the thread would NOT be running in each fork -- I knew we wanted it to be. But in fact it IS running in each fork, and the puma warning is wrongly assuming it should not be.

OK, thanks @schneems , now this explanation is here for anyone else that finds it!

[schneems]

Actually there was a typo in my response it should have been:

the thread was not running in each fork.

I think the reason this works:

[20350] ! #<Thread:0x0000000005156350@/home/swistak/.rvm/gems/ruby-2.6.3/gems/activerecord-6.0.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:335 sleep> - /home/swistak/.rvm/gems/ruby-2.6.3/gems/activerecord-6.0.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:337:in `sleep'

Is that ActiveRecord is semi-fork aware. Basically you cannot fork a connection, it's a file descriptor that is tied to the process. If you change the process, you no longer have the same connection. Also you wouldn't want multiple processes to be reading/writing from the same connection anyway. Back in Rails 4.x days, people used to have to manually call to reconnect after fork, but now days if active record sees that the connection to your database isn't good anymore due to forking it will reconnect.

Basically: Booting a connection pool reaper before we fork doesn't buy anyone anything. After fork, the connection won't be valid. So, in that sense, it's a good warning. However, due to Acitve Record's fork-aware connection code, the problem is mitigated (i believe) in the forks.

[jrochkind]

Ah, ok, I had it right the first time, doh!

OK, if the thread is NOT running in every fork....

Ah, but ActiveRecord will restart the reaper in each fork anyway, so it doesn't matter?

Then it is maybe kinda sorta a bug, although one with no negative consequences except the confusing warning maybe. But you say say "Booting a connection pool reaper before we fork doesn't buy anyone anything" -- ok, so why is the connection pool reaper being booted before the fork? Would there be a refactor that would keep it from being booted pre-fork, have it booted on-demand when it's actually needed, and avoid the confusing warning?

But still good to know the warning can be safely ignored, because AR should be smart enough to restart the reaper in each fork anyway -- although i'm sort of taking your word for it!

[nateberkopec]

@schneems I'm not sure if I agree this is safe. There is one reaper per pool, not one reaper per connection:

rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb

Line 402 in 5699122

@reaper = Reaper.new(self, db_config.reaping_frequency)

[nateberkopec]

I think this is unlikely to be a problem, because the reaper is almost always sleeping, but there could still be an issue if the reaper is reaping when the process forks.

[jrochkind]

@nateberkopec or anyone else, understand AR enough to have an idea of how/if this could be corrected?

I actually HAVE looked at the Reaper code before and blogged about it, but not in a while.

If the Reaper were created only on first database connection instead of on boot, would that resolve it? Or does first database connection happen before fork anyway, so it would still be created too early and result in a warning?

I myself remain not entirely confident that every forked process even gets a Reaper -- how sure are we that the forked processes will notice they don't have a Reaper and start one up? Can anyone identify the code that would be responsible for this?

Since the Reaper is only handling pathological/unexpected/error cases, you might not notice if a forked process didn't have one; it wouldn't be there taking care of the error conditions it's supposed to take care of, but someone might have a hard time diagnosing any problems that arose as related to threads and pre-forks and the reaper. This stuff is confusing enough, that I"m not totally sure I trust anyone's idea of what's probably going on without really tracing it in the code, which is tricky.

[nateberkopec]

I think this should be re-opened. It should be fixed using whatever mechanism is used to close the connection pool before fork.

[jrochkind]

Nice thanks. It may just be be auto-closed by the bot again if no activity though.

I haven't had much luck figuring out how to intervene in the code here, it's not the simplest part of AR. I think there are two parts:

1. Making sure the reaper thread gets gracefully shut down before fork, probably as Nate says "using whatever mechanism is used to close the connection pool before fork."

2. Making sure the reaper thread gets started in each process post-fork. Perhaps whatever mechanism already re-opens connections after fork will already automatically lead to a reaper thread getting re-created, but it's not clear to me at the moment.

If someone has some hints or useful orientation into the codebase, even if you don't have time to get a PR over the finish line, leaving them here might help me or someone else get it together.

[matthewd]

The pool isn't closed before fork; the pool is discarded (in the forked process) after fork.

There is one reaper per pool

Yup.. and there's one [or more, with multi-DB stuff involved] pool per forked process -> reaper[s] per forked process.

rails/activerecord/lib/active_record/connection_adapters/pool_config.rb

Lines 43 to 47 in b5b078c

	def pool
	ActiveSupport::ForkTracker.check!
	@pool || synchronize { @pool ||= ConnectionAdapters::ConnectionPool.new(self) }
	end

Puma is warning that something could go wrong if the owner of the thread isn't implemented correctly, but provides no way for us to indicate that yes, we do know what we're doing. Alternative suggestions welcome, but right now I really don't see a problem to solve here.

[jrochkind]

Ah, I see, thanks, that confirms what @schneems was saying all along.

Is there any way to manually shut down the reaper? If so, I guess it would be possible to have puma do so before fork, maybe the puma before_fork hook would be used? And then new reaper would automatically be created by usual post-fork connection pool re-creation?

What with puma being the rails default web server, would it make sense to at least document this in puma and/or generate it into default rails puma configs? Either just to avoid the warning in logs, or arguably even to reduce chance of bugs by tidying things up explicitly.

[nateberkopec]

The pool isn't closed before fork; the pool is discarded (in the forked process) after fork

Thanks, I never knew how that actually worked. Obviously this all makes sense when you realize the entire pool is discarded, not the connections.

rails/activerecord/lib/active_record/connection_adapters/pool_config.rb

Line 43 in b5b078c

def pool

Makes it all pretty clear.

If there was a GVL switch some time during when the reaper was running, I think the Reaper's mutex would be toast, but that doesn't matter because the reaper and it's mutex itself will be marked for GC after fork and never used again (because register_pool, which creates reaper threads, only runs once during pool creation). The reaper thread owns no other objects or file descriptors, so I guess there's no possible way it can cause a deadlock after fork.

[matthewd]

it would be possible to have puma do so before fork

The application could be actively using the pool inside the pre-fork process, though -- either because Puma isn't the only thing running in that main process (in which case you'll presumably get a warning for that/those threads too), or because Puma is itself an adjunct to the main show (which is ultimately the same thing, but implies a different command started us / someone else's code owns the main thread), or just because they accessed the database during app boot [in which case it's likely safe to preemptively disconnect, but you can't be sure that's what's going on].

Active Record is obliged to work in other circumstances too, so it's always required to be resilient to arbitrary forks; I'd argue that introducing extra special-case handling for Puma pre-fork increases the number of code paths leading to that point, and thus increases the chance of bugs in each. (Also, "make sure everyone's web server config explicitly disconnects the DB prior to every fork" is an old-timey superstition that we've worked hard to ensure is reliably unnecessary.)

My suggestion would be that Puma only warns if it owns the main thread (I haven't looked at whether it already checks that), and provides a way (e.g. a magic thread-local variable name) for thread owners to flag that they are explicitly fork-safe.

[nateberkopec]

Puma only warns if it owns the main thread (I haven't looked at whether it already checks that)

We don't, although in this case I'm sure that we were.

provides a way (e.g. a magic thread-local variable name) for thread owners to flag that they are explicitly fork-safe

I'm OK with that and it would be super easy for us to implement.

[matthewd]

@nateberkopec there's an edge case where a mid-reap reaper may have the pool locked, and the post-fork process will itself attempt to synchronize the pool in discard... but that's safe because a ruby mutex will unlock if its owning thread is MIA:

m = Mutex.new
t = Thread.new { m.synchronize { puts "grabbed lock"; sleep 10; puts "sleep done" } }
Thread.pass

fork { m.synchronize { puts "instant output" } }
m.synchronize { puts "still delayed" }
t.join

[jrochkind]

Also, "make sure everyone's web server config explicitly disconnects the DB prior to every fork" is an old-timey superstition

I wasn't suggesting disconnecting the DB, but just stopping the reaper thread. But your points probably still hold -- if there is something pre-fork that is meant to be able to continue doing AR stuff, a missing reaper thread would be unfortunate. So okay, wow this stuff is complicated, sorry if I've been muddying the waters.

Incidentally, @schneems, the heroku docs are still recommending:

on_worker_boot do
  # Valid on Rails 4.1+ using the `config/database.yml` method of setting `pool` size
  ActiveRecord::Base.establish_connection
end

Based on this conversation, I'm not sure if this is actually necessary, or "old-timey superstition", but just ignore me if this is still good advice after all.

[nateberkopec]

provides a way (e.g. a magic thread-local variable name) for thread owners to flag that they are explicitly fork-safe

I'll open a PR to start the discussion here later today.

[nateberkopec]

I've created #40399 as a resolution. Once the thread-local is decided, we'll add to Puma.

[eugeneius]

This will be resolved once #40399 and puma/puma#2475 are released.

[nateberkopec]

For Puma, we plan a 5.1 release with this change somtime around the end of Nov/start of Dec. https://github.com/puma/puma/milestone/12

[schneems]

Hello from 4 years ago. One pattern that I have developed on buildpacks is to never introduce a warning without a way to disable it via configuration. I don't think we want to completely disable this warning, but it would be nice if app developers and other libraries that know they're running in Puma could tell us "I know what I'm doing, nothing to see here"

To that end, maybe we could add an API. Something like Puma.thread_is_safe_for_fork(thread) where if you register a thread with it, then puma assumes you know what you're doing and doesn't emit the warning.

Puma.thread_is_safe_for_fork(thread) if defined?(::Puma) && ::Puma.responds_to?(:thread_is_safe_for_fork)

[matthewd]

@schneems is that not what the above PRs did?

[schneems]

Yes. I was not paying full attention when I wrote that message.