Rufus not triggering when running Puma as a daemon (Rufus 3.7, Puma 5.2.1)
wakproductions opened this issue · 6 comments
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.
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
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
It seems rails -d
for Rails 4.2 doesn't read config/puma.rb
puma/puma#1253
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.
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.
You're welcome!