"Detected 1 Thread(s) started in app boot" on puma 3.4.0

[oboxodo]

Ruby 2.2.4, Rails 4.2.6.

Recently upgraded from Puma 2.15.3 to 3.4.0 and puma_worker_killer 0.0.4 to 0.0.6. I'm also using puma-heroku 1.0.0 plugin as the config I had was basically the same as that plugin's.

I have: MAX_THREADS=2 and WEB_CONCURRENCY=2

$ cat Procfile
web: bundle exec puma -C config/puma.rb
worker: bundle exec rake jobs:work

$ cat config/puma.rb
plugin "heroku"

$ cat config/initializers/puma_worker_killer.rb
# See https://blog.codeship.com/debugging-a-memory-leak-on-heroku/
# This is obviously not a real solution but buys us time.
if ENV["PUMA_WORKERS_RESTART_FREQUENCY"]
  require "puma_worker_killer"
  # `PUMA_WORKERS_RESTART_FREQUENCY` must be an integer number of hours.
  PumaWorkerKiller.enable_rolling_restart ENV["PUMA_WORKERS_RESTART_FREQUENCY"].to_i * 3600
end

And logs look like this in my staging env:

2016-05-04T20:56:15.967077+00:00 heroku[web.1]: Starting process with command `bundle exec puma -C config/puma.rb`
2016-05-04T20:56:19.876836+00:00 app[web.1]: [3] Puma starting in cluster mode...
2016-05-04T20:56:19.876909+00:00 app[web.1]: [3] * Version 3.4.0 (ruby 2.2.4-p230), codename: Owl Bowl Brawl
2016-05-04T20:56:19.876960+00:00 app[web.1]: [3] * Min threads: 2, max threads: 2
2016-05-04T20:56:19.877010+00:00 app[web.1]: [3] * Environment: production
2016-05-04T20:56:19.877053+00:00 app[web.1]: [3] * Process workers: 2
2016-05-04T20:56:19.877202+00:00 app[web.1]: [3] * Preloading application
2016-05-04T20:56:24.926386+00:00 app[web.1]: [SKYLIGHT] [0.10.3] Skylight agent enabled
2016-05-04T20:56:24.945590+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:24 +0000 web.1 (3)] INFO : Starting the New Relic agent in "production" environment.
2016-05-04T20:56:24.945689+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:24 +0000 web.1 (3)] INFO : To prevent agent startup add a NEWRELIC_AGENT_ENABLED=false environment variable or modify the "production" section of your newrelic.yml.
2016-05-04T20:56:24.945824+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:24 +0000 web.1 (3)] INFO : Reading configuration from config/newrelic.yml (/app)
2016-05-04T20:56:24.957157+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:24 +0000 web.1 (3)] INFO : Environment: production
2016-05-04T20:56:24.957261+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:24 +0000 web.1 (3)] INFO : Dispatcher: puma
2016-05-04T20:56:24.957403+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:24 +0000 web.1 (3)] INFO : Application: quimbee-staging
2016-05-04T20:56:24.957513+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:24 +0000 web.1 (3)] INFO : Deferring startup of agent reporting thread because puma may fork.
2016-05-04T20:56:25.008394+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:25 +0000 web.1 (3)] INFO : Installing Rails Sunspot instrumentation
2016-05-04T20:56:25.023592+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:25 +0000 web.1 (3)] INFO : Installing Memcache instrumentation for dalli gem
2016-05-04T20:56:25.025960+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:25 +0000 web.1 (3)] INFO : Installing Net instrumentation
2016-05-04T20:56:25.030194+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:25 +0000 web.1 (3)] INFO : Installing ActiveRecord 4 instrumentation
2016-05-04T20:56:25.030478+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:25 +0000 web.1 (3)] INFO : Installing deferred Rack instrumentation
2016-05-04T20:56:25.030664+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:25 +0000 web.1 (3)] INFO : Installing Rack::Builder middleware instrumentation
2016-05-04T20:56:25.033517+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:25 +0000 web.1 (3)] INFO : Installing ActiveJob instrumentation
2016-05-04T20:56:25.033980+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:25 +0000 web.1 (3)] INFO : Installing Rails 3+ middleware instrumentation
2016-05-04T20:56:25.034186+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:25 +0000 web.1 (3)] INFO : Installing DelayedJob instrumentation [part 1/2]
2016-05-04T20:56:25.036156+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:25 +0000 web.1 (3)] INFO : Installing middleware-based Excon instrumentation
2016-05-04T20:56:25.038727+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:25 +0000 web.1 (3)] INFO : Installing Rails 4 Controller instrumentation
2016-05-04T20:56:25.038914+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:25 +0000 web.1 (3)] INFO : Installing Rails 4 Error instrumentation
2016-05-04T20:56:25.039093+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:25 +0000 web.1 (3)] INFO : Installing Rails 4 view instrumentation
2016-05-04T20:56:25.039204+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:25 +0000 web.1 (3)] INFO : Finished instrumentation
2016-05-04T20:56:29.881814+00:00 app[web.1]: ** [NewRelic][2016-05-04 20:56:29 +0000 web.1 (3)] INFO : Doing deferred dependency-detection before Rack startup
2016-05-04T20:56:29.886947+00:00 app[web.1]: [3] * Listening on tcp://0.0.0.0:7282
2016-05-04T20:56:29.887162+00:00 app[web.1]: [3] ! WARNING: Detected 1 Thread(s) started in app boot:
2016-05-04T20:56:29.887296+00:00 app[web.1]: [3] ! #<Thread:0x007f40c3d331e0@/app/vendor/bundle/ruby/2.2.0/gems/puma_worker_killer-0.0.6/lib/puma_worker_killer/auto_reap.rb:12 sleep> - /app/vendor/bundle/ruby/2.2.0/gems/puma_worker_killer-0.0.6/lib/puma_worker_killer/auto_reap.rb:15:in `sleep'
2016-05-04T20:56:29.887677+00:00 app[web.1]: [3] Use Ctrl-C to stop
2016-05-04T20:56:29.912650+00:00 app[web.1]: [3] - Worker 0 (pid: 18) booted, phase: 0
2016-05-04T20:56:29.912799+00:00 app[web.1]: [3] - Worker 1 (pid: 20) booted, phase: 0
2016-05-04T20:56:30.173716+00:00 heroku[web.1]: State changed from starting to up

Should I be starting puma_worker_killer some other way?

[schneems]

No, that warning can be safely ignored. I don't know of a better way to initialize this code.

--  Richard Schneeman http://schneems.com

On May 4, 2016 at 4:19:21 PM, Diego Algorta (notifications@github.com) wrote:

Recently upgraded from Puma 2.15.3 to 3.4.0 and puma_worker_killer 0.0.4 to 0.0.6. I'm also using puma-heroku 1.0.0 plugin as the config I had was basically the same as that plugin's.

[oboxodo]

Ok, thanks. Maybe @evanphx does, considering it's related to an upgrade to Puma 3?

[schneems]

You're talking about this right?

2016-05-04T20:56:29.887162+00:00 app[web.1]: [3] ! WARNING: Detected 1 Thread(s) started in app boot:
2016-05-04T20:56:29.887296+00:00 app[web.1]: [3] ! #<Thread:0x007f40c3d331e0@/app/vendor/bundle/ruby/2.2.0/gems/puma_worker_killer-0.0.6/lib/puma_worker_killer/auto_reap.rb:12 sleep> - /app/vendor/bundle/ruby/2.2.0/gems/puma_worker_killer-0.0.6/lib/puma_worker_killer/auto_reap.rb:15:in `sleep'
2016-05-04T20:56:29.887677+00:00 app[web.1]: [3] Use Ctrl-C to stop

Puma has been warning about threads at start up for a number of versions. I don't know when they were introduced though.

[evanphx]

The warning is just that, a warning. If the code can deal with that thread not living into the workers, then it's fine. Puma doesn't know which are master threads and which are worker threads, so it just makes as much info available as possible.

[oboxodo]

Ok then... I'll just ignore it. Thanks!