Rufus not triggering when running Puma as a daemon (Rufus 3.7, Puma 5.2.1)

[wakproductions]

I seem to be encountering the same symptoms as puma/puma#607, which was apparently solved several years ago but maybe resurfaced in a newer update?

Rails 4.2.11
Ruby 2.5.2
Rufus Scheduler 3.7
Puma 5.2.1

Here is my scheduler: config/initializers/rufus-scheduler.rb

require 'rufus-scheduler'

s = Rufus::Scheduler.singleton

s.every '6s' do
  puts "Test output without calling a rake task"
  File.open(Rails.root.join('tmp', 'rufus-log.txt'), 'w') { |f|
    f.write("Running task, writing output #{Time.current}") }
end

s.cron '* * * * *' do |job|
  Rails.logger.info '=' * 80
  Rails.logger.info Time.now
  Rails.logger.info '-' * 80
  Rails.logger.info [ :env_tz, ENV['TZ'] ].inspect
  Rails.logger.info [ :uname, (`uname -a` rescue nil) ].inspect
  Rails.logger.info [ :rv, RUBY_VERSION, :rp, RUBY_PLATFORM ].inspect
  Rails.logger.info [ :ra, (Rails::VERSION.to_s rescue :nora) ].inspect
  Rails.logger.info EtOrbi.render_nozone_time(Time.now.to_f)
  Rails.logger.info EtOrbi.platform_info
  Rails.logger.info [ :fu, Fugit::VERSION, :rs, Rufus::Scheduler::VERSION ].inspect
  Rails.logger.info '-' * 80
  Rails.logger.info Fugit.parse('*/1 5-15 * * 0-5').inspect
  Rails.logger.info [ :nt, Fugit.parse('*/1 5-15 * * 0-5').next_time.to_s ].inspect
  Rails.logger.info '-' * 80
end

puts "Done scheduling Rufus"

Rails server as a terminal process (not a daemon)

Output (running as a server in console, RAILS_ENV=development)

stock_trend_finder (development_updates)$ rails s -p 4000
=> Booting Puma
=> Rails 4.2.11 application starting in development on http://localhost:4000
=> Run `rails server -h` for more startup options
=> Ctrl-C to shutdown server
Done scheduling Rufus
Puma starting in single mode...
* Puma version: 5.2.1 (ruby 2.5.2-p104) ("Fettisdagsbulle")
*  Min threads: 0
*  Max threads: 5
*  Environment: development
*          PID: 1879
* Listening on http://127.0.0.1:4000
* Listening on http://[::1]:4000
Use Ctrl-C to stop
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
================================================================================
2021-02-19 12:06:00 -0500
--------------------------------------------------------------------------------
[:env_tz, nil]
[:uname, "Linux DESKTOP-PTRKO96 4.19.104-microsoft-standard #1 SMP Wed Feb 19 06:37:35 UTC 2020 x86_64 GNU/Linux\n"]
[:rv, "2.5.2", :rp, "x86_64-linux"]
[:ra, "Rails::VERSION"]
(secs:1613754360.0179772,utc~:"2021-02-19 17:06:00.017977237701416016",ltz~:"EST")
(etz:nil,tnz:"EST",tziv:"1.2.9",tzidv:nil,rv:"2.5.2",rp:"x86_64-linux",win:false,rorv:"4.2.11",astz:[ActiveSupport::TimeZone, "America/New_York"],eov:"1.2.4",eotnz:#<TZInfo::TimezoneProxy: America/New_York>,eotnfz:"-0500",eotlzn:"America/New_York",eotnfZ:"EST",debian:"America/New_York",centos:nil,osx:"America/New_York")
[:fu, "1.4.2", :rs, "3.7.0"]
--------------------------------------------------------------------------------
#<Fugit::Cron:0x00007f8b1404e920 @original="*/1 5-15 * * 0-5", @cron_s=nil, @seconds=[0], @minutes=nil, @hours=[5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15], @monthdays=nil, @months=nil, @weekdays=[[0], [1], [2], [3], [4], [5]], @zone=nil, @timezone=nil>
[:nt, "2021-02-19 12:07:00 -0500"]
--------------------------------------------------------------------------------
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
================================================================================
2021-02-19 12:07:00 -0500
--------------------------------------------------------------------------------
[:env_tz, nil]
[:uname, "Linux DESKTOP-PTRKO96 4.19.104-microsoft-standard #1 SMP Wed Feb 19 06:37:35 UTC 2020 x86_64 GNU/Linux\n"]
[:rv, "2.5.2", :rp, "x86_64-linux"]
[:ra, "Rails::VERSION"]
(secs:1613754420.056664,utc~:"2021-02-19 17:07:00.05666399002075195",ltz~:"EST")
(etz:nil,tnz:"EST",tziv:"1.2.9",tzidv:nil,rv:"2.5.2",rp:"x86_64-linux",win:false,rorv:"4.2.11",astz:[ActiveSupport::TimeZone, "America/New_York"],eov:"1.2.4",eotnz:#<TZInfo::TimezoneProxy: America/New_York>,eotnfz:"-0500",eotlzn:"America/New_York",eotnfZ:"EST",debian:"America/New_York",centos:nil,osx:"America/New_York")
[:fu, "1.4.2", :rs, "3.7.0"]
--------------------------------------------------------------------------------
#<Fugit::Cron:0x000055dd9d483110 @original="*/1 5-15 * * 0-5", @cron_s=nil, @seconds=[0], @minutes=nil, @hours=[5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15], @monthdays=nil, @months=nil, @weekdays=[[0], [1], [2], [3], [4], [5]], @zone=nil, @timezone=nil>
[:nt, "2021-02-19 12:08:00 -0500"]
--------------------------------------------------------------------------------
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task
Test output without calling a rake task


<...continues on...>

I can confirm that it was writing to the file in tmp/rufus-log.txt as expected too.

Rails server as a terminal process (as a daemon)

RAILS_ENV=development

stock_trend_finder (development_updates)$ rails s -d -p 4000
=> Booting Puma
=> Rails 4.2.11 application starting in development on http://localhost:4000
=> Run `rails server -h` for more startup options
Done scheduling Rufus

If I tail the Rails log I see nothing, except a lone DB query that it runs for another initializer at startup.

[jmettraux]

Hello,

so in Rails daemon mode, Puma only advertises "Booting Puma" and nothing more. It may be going in clustered mode.

if you put this in a config/puma.rb:

on_worker_boot do |worker_number|
  puts ". worker ##{worker_number} starting ..."
end

Does it behave differently in daemon versus non-daemon?

If yes, you could start the scheduling from there. Maybe:

on_worker_boot do |worker_number|
  puts ". worker ##{worker_number} starting ..."
  if worker_number == 0
    Rufus::Scheduler.singleton.every '5s' do
      puts ".. Hello, it's #{Time.now}"
    end
  end
end

https://puma.io/puma/#configuration
https://gist.github.com/rpocklin/308ba709a9647f7d1b92
https://devcenter.heroku.com/articles/deploying-rails-applications-with-the-puma-web-server#on-worker-boot

[wakproductions]

I need to look up more about this clustering mode you mention, but for now here's the result of running the code you suggested:

stock_trend_finder (development_updates)$ rails s -p 4000
=> Booting Puma
=> Rails 4.2.11 application starting in development on http://localhost:4000
=> Run `rails server -h` for more startup options
=> Ctrl-C to shutdown server
Done scheduling Rufus
Puma starting in single mode...
* Puma version: 5.2.1 (ruby 2.5.2-p104) ("Fettisdagsbulle")
*  Min threads: 0
*  Max threads: 5
*  Environment: development
*          PID: 25980
* Listening on http://127.0.0.1:4000
* Listening on http://[::1]:4000
Use Ctrl-C to stop
Test output without calling a rake task
Test output without calling a rake task
================================================================================
2021-02-19 18:01:00 -0500
--------------------------------------------------------------------------------
[:env_tz, nil]
[:uname, "Linux DESKTOP-PTRKO96 4.19.104-microsoft-standard #1 SMP Wed Feb 19 06:37:35 UTC 2020 x86_64 GNU/Linux\n"]
[:rv, "2.5.2", :rp, "x86_64-linux"]
[:ra, "Rails::VERSION"]
(secs:1613775660.1281312,utc~:"2021-02-19 23:01:00.12813115119934082",ltz~:"EST")
(etz:nil,tnz:"EST",tziv:"1.2.9",tzidv:nil,rv:"2.5.2",rp:"x86_64-linux",win:false,rorv:"4.2.11",astz:[ActiveSupport::TimeZone, "America/New_York"],eov:"1.2.4",eotnz:#<TZInfo::TimezoneProxy: America/New_York>,eotnfz:"-0500",eotlzn:"America/New_York",eotnfZ:"EST",debian:"America/New_York",centos:nil,osx:"America/New_York")
[:fu, "1.4.2", :rs, "3.7.0"]
--------------------------------------------------------------------------------
#<Fugit::Cron:0x00007fb56c0263a8 @original="*/1 5-15 * * 0-5", @cron_s=nil, @seconds=[0], @minutes=nil, @hours=[5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15], @monthdays=nil, @months=nil, @weekdays=[[0], [1], [2], [3], [4], [5]], @zone=nil, @timezone=nil>
[:nt, "2021-02-21 05:00:00 -0500"]
--------------------------------------------------------------------------------
^C- Gracefully stopping, waiting for requests to finish
=== puma shutdown: 2021-02-19 18:01:02 -0500 ===
- Goodbye!
Exiting

stock_trend_finder (development_updates)$ rails s -d -p 4000
=> Booting Puma
=> Rails 4.2.11 application starting in development on http://localhost:4000
=> Run `rails server -h` for more startup options
Done scheduling Rufus

[jmettraux]

It seems rails -d for Rails 4.2 doesn't read config/puma.rb puma/puma#1253

[jmettraux]

OK, it seems you would need to use a newer version of Rails or to call bundle exec puma (as seen in the Puma issue 1253 above).

I've tested with a setup similar to yours and, like you, starting with rails s -d ends up with the threads killed by the daemonization forking. The rufus-scheduler thread is killed at that point.

If you use bundle exec puma Puma will let you use config/puma.rb and tune your application.

[wakproductions]

Thank you for the help John. It seems that in the latest version of Puma they removed daemon support (puma/puma#2170) . I've decided that the easiest way of working around this is to run my app in a Docker container, and could spin up a separate container for the scheduled jobs, after putting them in a rake task.

[jmettraux]

You're welcome!