Log loaded extensions when PUMA_DEBUG is set (puma#3036)

* log loaded extensions when env['PUMA_DEBUG'] is set

Co-authored-by: Jeremy Evans <code@jeremyevans.net>

* Add tests

* IO.popen change for JRuby ?

* Fix !DRY code

Co-authored-by: Jeremy Evans <code@jeremyevans.net>
Co-authored-by: Patrik Ragnarsson <patrik@starkast.net>

lib/puma/cluster.rb

@@ -467,6 +467,7 @@ def run
                   @events.fire(:ping!, w)
                   if !booted && @workers.none? {|worker| worker.last_status.empty?}
                     @events.fire_on_booted!
+                    debug_loaded_extensions("Loaded Extensions - master:") if @log_writer.debug?
                     booted = true
                   end
                 end
@@ -476,6 +477,7 @@ def run
             end
             if in_phased_restart && workers_not_booted.zero?
               @events.fire_on_booted!
+              debug_loaded_extensions("Loaded Extensions - master:") if @log_writer.debug?
               in_phased_restart = false
             end
 

lib/puma/cluster/worker.rb

@@ -115,6 +115,11 @@ def run
 
         while restart_server.pop
           server_thread = server.run
+
+          if @log_writer.debug? && index == 0
+            debug_loaded_extensions "Loaded Extensions - worker 0:"
+          end
+
           stat_thread ||= Thread.new(@worker_write) do |io|
             Puma.set_thread_name "stat pld"
             base_payload = "p#{Process.pid}"

lib/puma/log_writer.rb

@@ -80,6 +80,10 @@ def internal_write(str)
     end
     private :internal_write
 
+    def debug?
+      @debug
+    end
+
     def debug(str)
       log("% #{str}") if @debug
     end

lib/puma/runner.rb

@@ -198,5 +198,12 @@ def stats
         }
       }
     end
+
+    # this method call should always be guarded by `@log_writer.debug?`
+    def debug_loaded_extensions(str)
+      @log_writer.debug "────────────────────────────────── #{str}"
+      re_ext = /\.#{RbConfig::CONFIG['DLEXT']}\z/i
+      $LOADED_FEATURES.grep(re_ext).each { |f| @log_writer.debug("    #{f}") }
+    end
   end
 end

lib/puma/single.rb

@@ -57,6 +57,8 @@ def run
 
       @events.fire_on_booted!
 
+      debug_loaded_extensions("Loaded Extensions:") if @log_writer.debug?
+
       begin
         server_thread.join
       rescue Interrupt

test/helpers/integration.rb

@@ -65,7 +65,7 @@ def silent_and_checked_system_command(*args)
     assert(system(*args, out: File::NULL, err: File::NULL))
   end
 
-  def cli_server(argv, unix: false, config: nil, merge_err: false, log: false)
+  def cli_server(argv, unix: false, config: nil, merge_err: false, log: false, no_wait: false, puma_debug: nil)
     if config
       config_file = Tempfile.new(%w(config .rb))
       config_file.write config
@@ -79,12 +79,15 @@ def cli_server(argv, unix: false, config: nil, merge_err: false, log: false)
       @tcp_port = UniquePort.call
       cmd = "#{BASE} #{puma_path} #{config} -b tcp://#{HOST}:#{@tcp_port} #{argv}"
     end
+
+    env = puma_debug ? {'PUMA_DEBUG' => 'true' } : {}
+
     if merge_err
-      @server = IO.popen(cmd, "r", :err=>[:child, :out])
+      @server = IO.popen(env, cmd, :err=>[:child, :out])
     else
-      @server = IO.popen(cmd, "r")
+      @server = IO.popen(env, cmd)
     end
-    wait_for_server_to_boot(log: log)
+    wait_for_server_to_boot(log: log) unless no_wait
     @pid = @server.pid
     @server
   end
@@ -291,6 +294,17 @@ def thread_run_refused(unix: false)
     end
   end
 
+
+  def set_pumactl_args(unix: false)
+    if unix
+      @control_path = tmp_path('.cntl_sock')
+      "--control-url unix://#{@control_path} --control-token #{TOKEN}"
+    else
+      @control_tcp_port = UniquePort.call
+      "--control-url tcp://#{HOST}:#{@control_tcp_port} --control-token #{TOKEN}"
+    end
+  end
+
   def cli_pumactl(argv, unix: false)
     arg =
       if unix

test/test_integration_cluster.rb

@@ -448,6 +448,14 @@ def test_hook_data
     File.unlink file1 if File.file? file1
   end
 
+  def test_puma_debug_loaded_exts
+    cli_server "-w #{workers} test/rackup/hello.ru", puma_debug: true
+
+    assert wait_for_server_to_include('Loaded Extensions - worker 0:')
+    assert wait_for_server_to_include('Loaded Extensions - master:')
+    @pid = @server.pid
+  end
+
   private
 
   def worker_timeout(timeout, iterations, details, config)

test/test_integration_pumactl.rb

@@ -9,23 +9,22 @@ def workers ; 2 ; end
 
   def setup
     super
-
-    @state_path   = tmp_path('.state')
-    @control_path = tmp_path('.sock')
+    @control_path = nil
+    @state_path = tmp_path('.state')
   end
 
   def teardown
     super
 
-    refute File.exist?(@control_path), "Control path must be removed after stop"
+    refute @control_path && File.exist?(@control_path), "Control path must be removed after stop"
   ensure
     [@state_path, @control_path].each { |p| File.unlink(p) rescue nil }
   end
 
   def test_stop_tcp
     skip_if :jruby, :truffleruby # Undiagnose thread race. TODO fix
     @control_tcp_port = UniquePort.call
-    cli_server "-q test/rackup/sleep.ru --control-url tcp://#{HOST}:#{@control_tcp_port} --control-token #{TOKEN} -S #{@state_path}"
+    cli_server "-q test/rackup/sleep.ru #{set_pumactl_args} -S #{@state_path}"
 
     cli_pumactl "stop"
 
@@ -46,7 +45,8 @@ def test_halt_unix
   def ctl_unix(signal='stop')
     skip_unless :unix
     stderr = Tempfile.new(%w(stderr .log))
-    cli_server "-q test/rackup/sleep.ru --control-url unix://#{@control_path} --control-token #{TOKEN} -S #{@state_path}",
+
+    cli_server "-q test/rackup/sleep.ru #{set_pumactl_args unix: true} -S #{@state_path}",
       config: "stdout_redirect nil, '#{stderr.path}'",
       unix: true
 
@@ -60,7 +60,7 @@ def ctl_unix(signal='stop')
 
   def test_phased_restart_cluster
     skip_unless :fork
-    cli_server "-q -w #{workers} test/rackup/sleep.ru --control-url unix://#{@control_path} --control-token #{TOKEN} -S #{@state_path}", unix: true
+    cli_server "-q -w #{workers} test/rackup/sleep.ru #{set_pumactl_args unix: true} -S #{@state_path}", unix: true
 
     start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
 
@@ -96,7 +96,7 @@ def test_phased_restart_cluster
   def test_refork_cluster
     skip_unless :fork
     wrkrs = 3
-    cli_server "-q -w #{wrkrs} test/rackup/sleep.ru --control-url unix://#{@control_path} --control-token #{TOKEN} -S #{@state_path}",
+    cli_server "-q -w #{wrkrs} test/rackup/sleep.ru #{set_pumactl_args unix: true} -S #{@state_path}",
       config: 'fork_worker 50',
       unix: true
 
@@ -133,7 +133,7 @@ def test_refork_cluster
   def test_prune_bundler_with_multiple_workers
     skip_unless :fork
 
-    cli_server "-q -C test/config/prune_bundler_with_multiple_workers.rb --control-url unix://#{@control_path} --control-token #{TOKEN} -S #{@state_path}", unix: true
+    cli_server "-q -C test/config/prune_bundler_with_multiple_workers.rb #{set_pumactl_args unix: true} -S #{@state_path}", unix: true
 
     s = UNIXSocket.new @bind_path
     @ios_to_close << s

test/test_integration_single.rb

@@ -190,8 +190,7 @@ def test_puma_started_log_writing
   end
 
   def test_application_logs_are_flushed_on_write
-    @control_tcp_port = UniquePort.call
-    cli_server "--control-url tcp://#{HOST}:#{@control_tcp_port} --control-token #{TOKEN} test/rackup/write_to_stdout.ru"
+    cli_server "#{set_pumactl_args} test/rackup/write_to_stdout.ru"
 
     read_body connect
 
@@ -237,4 +236,12 @@ def test_closed_listener
     end
     assert true
   end
+
+  def test_puma_debug_loaded_exts
+    cli_server "#{set_pumactl_args} test/rackup/hello.ru", puma_debug: true
+
+    assert wait_for_server_to_include('Loaded Extensions:')
+
+    cli_pumactl 'stop'
+  end
 end