From 2ab098c1ebffc9054102e8368ceb70d4ecc58b4a Mon Sep 17 00:00:00 2001 From: Andrew Konchin Date: Sat, 7 Mar 2020 19:09:24 +0200 Subject: [PATCH 1/4] Catch exceptions in run_hooks mehtod --- lib/puma/cluster.rb | 10 +++++----- lib/puma/configuration.rb | 11 +++++++++-- lib/puma/launcher.rb | 2 +- test/test_config.rb | 16 ++++++++++++++++ 4 files changed, 31 insertions(+), 8 deletions(-) diff --git a/lib/puma/cluster.rb b/lib/puma/cluster.rb index 989828fb33..f535571030 100644 --- a/lib/puma/cluster.rb +++ b/lib/puma/cluster.rb @@ -137,7 +137,7 @@ def spawn_workers diff.times do idx = next_worker_index - @launcher.config.run_hooks :before_worker_fork, idx + @launcher.config.run_hooks :before_worker_fork, idx, @launcher.events pid = fork { worker(idx, master) } if !pid @@ -149,7 +149,7 @@ def spawn_workers debug "Spawned worker: #{pid}" @workers << Worker.new(idx, pid, @phase, @options) - @launcher.config.run_hooks :after_worker_fork, idx + @launcher.config.run_hooks :after_worker_fork, idx, @launcher.events end if diff > 0 @@ -268,7 +268,7 @@ def worker(index, master) # Invoke any worker boot hooks so they can get # things in shape before booting the app. - @launcher.config.run_hooks :before_worker_boot, index + @launcher.config.run_hooks :before_worker_boot, index, @launcher.events server = start_server @@ -310,7 +310,7 @@ def worker(index, master) # Invoke any worker shutdown hooks so they can prevent the worker # exiting until any background operations are completed - @launcher.config.run_hooks :before_worker_shutdown, index + @launcher.config.run_hooks :before_worker_shutdown, index, @launcher.events ensure @worker_write << "t#{Process.pid}\n" rescue nil @worker_write.close @@ -486,7 +486,7 @@ def run @master_read, @worker_write = read, @wakeup - @launcher.config.run_hooks :before_fork, nil + @launcher.config.run_hooks :before_fork, nil, @launcher.events GC.compact if GC.respond_to?(:compact) spawn_workers diff --git a/lib/puma/configuration.rb b/lib/puma/configuration.rb index 838e61731a..6a32b9efac 100644 --- a/lib/puma/configuration.rb +++ b/lib/puma/configuration.rb @@ -275,8 +275,15 @@ def load_plugin(name) @plugins.create name end - def run_hooks(key, arg) - @options.all_of(key).each { |b| b.call arg } + def run_hooks(key, arg, events) + @options.all_of(key).each do |b| + begin + b.call arg + rescue => e + events.log "WARNING hook #{key} failed with exception (#{e.class}) #{e.message}" + events.debug e.backtrace.join("\n") + end + end end def self.temp_path diff --git a/lib/puma/launcher.rb b/lib/puma/launcher.rb index 4620d0377d..1add24e6c9 100644 --- a/lib/puma/launcher.rb +++ b/lib/puma/launcher.rb @@ -237,7 +237,7 @@ def reload_worker_directory end def restart! - @config.run_hooks :on_restart, self + @config.run_hooks :on_restart, self, @events if Puma.jruby? close_binder_listeners diff --git a/test/test_config.rb b/test/test_config.rb index d3d87d0902..8e9648676a 100644 --- a/test/test_config.rb +++ b/test/test_config.rb @@ -197,6 +197,22 @@ def test_config_raise_exception_on_sigterm conf.options[:raise_exception_on_sigterm] = true assert_equal conf.options[:raise_exception_on_sigterm], true end + + def test_run_hooks_and_exception + require 'puma/events' + + conf = Puma::Configuration.new do |c| + c.on_restart do |a| + raise RuntimeError, 'Error from hook' + end + end + conf.load + events = Puma::Events.strings + + conf.run_hooks :on_restart, 'ARG', events + expected = /WARNING hook on_restart failed with exception \(RuntimeError\) Error from hook/ + assert_match expected, events.stdout.string + end end # Thread unsafe modification of ENV From f830c28b3e299dacd15ff259818daf2f9802c317 Mon Sep 17 00:00:00 2001 From: Andrew Konchin Date: Sun, 8 Mar 2020 23:21:14 +0200 Subject: [PATCH 2/4] Add missing unit tests on Configuration#run_hooks method --- test/test_config.rb | 90 +++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 90 insertions(+) diff --git a/test/test_config.rb b/test/test_config.rb index 8e9648676a..2506da32a7 100644 --- a/test/test_config.rb +++ b/test/test_config.rb @@ -198,6 +198,96 @@ def test_config_raise_exception_on_sigterm assert_equal conf.options[:raise_exception_on_sigterm], true end + def test_run_hooks_on_restart_hook + require 'puma/events' + + messages = [] + conf = Puma::Configuration.new do |c| + c.on_restart do |a| + messages << "on_restart is called with #{a}" + end + end + conf.load + + conf.run_hooks :on_restart, 'ARG', Puma::Events.strings + assert_equal messages, ['on_restart is called with ARG'] + end + + def test_run_hooks_before_worker_fork + require 'puma/events' + + messages = [] + conf = Puma::Configuration.new do |c| + c.on_worker_fork do |a| + messages << "before_worker_fork is called with #{a}" + end + end + conf.load + + conf.run_hooks :before_worker_fork, 'ARG', Puma::Events.strings + assert_equal messages, ['before_worker_fork is called with ARG'] + end + + def test_run_hooks_after_worker_fork + require 'puma/events' + + messages = [] + conf = Puma::Configuration.new do |c| + c.after_worker_fork do |a| + messages << "after_worker_fork is called with #{a}" + end + end + conf.load + + conf.run_hooks :after_worker_fork, 'ARG', Puma::Events.strings + assert_equal messages, ['after_worker_fork is called with ARG'] + end + + def test_run_hooks_before_worker_boot + require 'puma/events' + + messages = [] + conf = Puma::Configuration.new do |c| + c.on_worker_boot do |a| + messages << "before_worker_boot is called with #{a}" + end + end + conf.load + + conf.run_hooks :before_worker_boot, 'ARG', Puma::Events.strings + assert_equal messages, ['before_worker_boot is called with ARG'] + end + + def test_run_hooks_before_worker_shutdown + require 'puma/events' + + messages = [] + conf = Puma::Configuration.new do |c| + c.on_worker_shutdown do |a| + messages << "before_worker_shutdown is called with #{a}" + end + end + conf.load + + conf.run_hooks :before_worker_shutdown, 'ARG', Puma::Events.strings + assert_equal messages, ['before_worker_shutdown is called with ARG'] + end + + def test_run_hooks_before_fork + require 'puma/events' + + messages = [] + conf = Puma::Configuration.new do |c| + c.before_fork do |a| + messages << "before_fork is called with #{a}" + end + end + conf.load + + conf.run_hooks :before_fork, 'ARG', Puma::Events.strings + assert_equal messages, ['before_fork is called with ARG'] + end + def test_run_hooks_and_exception require 'puma/events' From 55eddb708a4cf087742f77e907f0c4f1790dee0b Mon Sep 17 00:00:00 2001 From: Andrew Konchin Date: Sun, 8 Mar 2020 23:28:59 +0200 Subject: [PATCH 3/4] History.md: Add note about the bugfix --- History.md | 1 + 1 file changed, 1 insertion(+) diff --git a/History.md b/History.md index 2555344dc4..464c34d588 100644 --- a/History.md +++ b/History.md @@ -17,6 +17,7 @@ * Preserve `BUNDLE_GEMFILE` env var when using `prune_bundler` (#1893) * Send 408 request timeout even when queue requests is disabled (#2119) * Rescue IO::WaitReadable instead of EAGAIN for blocking read (#2121) + * Rescue exceptions in hooks defined by users (on_worker_boot, after_worker_fork etc) (#1551) * Refactor * Remove unused loader argument from Plugin initializer (#2095) From 6eecc874b20c8d0829e64775927ca0fdda50d9a6 Mon Sep 17 00:00:00 2001 From: Andrew Konchin Date: Mon, 9 Mar 2020 18:29:55 +0200 Subject: [PATCH 4/4] Code review: fix wording and introduce a test helper assert_run_hooks --- History.md | 2 +- test/test_config.rb | 98 +++++++++++---------------------------------- 2 files changed, 25 insertions(+), 75 deletions(-) diff --git a/History.md b/History.md index 464c34d588..b0a76dfef0 100644 --- a/History.md +++ b/History.md @@ -17,7 +17,7 @@ * Preserve `BUNDLE_GEMFILE` env var when using `prune_bundler` (#1893) * Send 408 request timeout even when queue requests is disabled (#2119) * Rescue IO::WaitReadable instead of EAGAIN for blocking read (#2121) - * Rescue exceptions in hooks defined by users (on_worker_boot, after_worker_fork etc) (#1551) + * Rescue and log exceptions in hooks defined by users (on_worker_boot, after_worker_fork etc) (#1551) * Refactor * Remove unused loader argument from Plugin initializer (#2095) diff --git a/test/test_config.rb b/test/test_config.rb index 2506da32a7..e47da9096b 100644 --- a/test/test_config.rb +++ b/test/test_config.rb @@ -4,6 +4,7 @@ require_relative "helpers/config_file" require "puma/configuration" +require 'puma/events' class TestConfigFile < TestConfigFileBase parallelize_me! @@ -199,98 +200,30 @@ def test_config_raise_exception_on_sigterm end def test_run_hooks_on_restart_hook - require 'puma/events' - - messages = [] - conf = Puma::Configuration.new do |c| - c.on_restart do |a| - messages << "on_restart is called with #{a}" - end - end - conf.load - - conf.run_hooks :on_restart, 'ARG', Puma::Events.strings - assert_equal messages, ['on_restart is called with ARG'] + assert_run_hooks :on_restart end def test_run_hooks_before_worker_fork - require 'puma/events' - - messages = [] - conf = Puma::Configuration.new do |c| - c.on_worker_fork do |a| - messages << "before_worker_fork is called with #{a}" - end - end - conf.load - - conf.run_hooks :before_worker_fork, 'ARG', Puma::Events.strings - assert_equal messages, ['before_worker_fork is called with ARG'] + assert_run_hooks :before_worker_fork, configured_with: :on_worker_fork end def test_run_hooks_after_worker_fork - require 'puma/events' - - messages = [] - conf = Puma::Configuration.new do |c| - c.after_worker_fork do |a| - messages << "after_worker_fork is called with #{a}" - end - end - conf.load - - conf.run_hooks :after_worker_fork, 'ARG', Puma::Events.strings - assert_equal messages, ['after_worker_fork is called with ARG'] + assert_run_hooks :after_worker_fork end def test_run_hooks_before_worker_boot - require 'puma/events' - - messages = [] - conf = Puma::Configuration.new do |c| - c.on_worker_boot do |a| - messages << "before_worker_boot is called with #{a}" - end - end - conf.load - - conf.run_hooks :before_worker_boot, 'ARG', Puma::Events.strings - assert_equal messages, ['before_worker_boot is called with ARG'] + assert_run_hooks :before_worker_boot, configured_with: :on_worker_boot end def test_run_hooks_before_worker_shutdown - require 'puma/events' - - messages = [] - conf = Puma::Configuration.new do |c| - c.on_worker_shutdown do |a| - messages << "before_worker_shutdown is called with #{a}" - end - end - conf.load - - conf.run_hooks :before_worker_shutdown, 'ARG', Puma::Events.strings - assert_equal messages, ['before_worker_shutdown is called with ARG'] + assert_run_hooks :before_worker_shutdown, configured_with: :on_worker_shutdown end def test_run_hooks_before_fork - require 'puma/events' - - messages = [] - conf = Puma::Configuration.new do |c| - c.before_fork do |a| - messages << "before_fork is called with #{a}" - end - end - conf.load - - conf.run_hooks :before_fork, 'ARG', Puma::Events.strings - assert_equal messages, ['before_fork is called with ARG'] + assert_run_hooks :before_fork end def test_run_hooks_and_exception - require 'puma/events' - conf = Puma::Configuration.new do |c| c.on_restart do |a| raise RuntimeError, 'Error from hook' @@ -303,6 +236,23 @@ def test_run_hooks_and_exception expected = /WARNING hook on_restart failed with exception \(RuntimeError\) Error from hook/ assert_match expected, events.stdout.string end + + private + + def assert_run_hooks(hook_name, options = {}) + configured_with = options[:configured_with] || hook_name + + messages = [] + conf = Puma::Configuration.new do |c| + c.send(configured_with) do |a| + messages << "#{hook_name} is called with #{a}" + end + end + conf.load + + conf.run_hooks hook_name, 'ARG', Puma::Events.strings + assert_equal messages, ["#{hook_name} is called with ARG"] + end end # Thread unsafe modification of ENV