Log loaded extensions when PUMA_DEBUG is set

[MSP-Greg]

Description

This implements the feature requested in #3020, printing the loaded extensions if PUMA_DEBUG is set.

When Puma is running 'single' (no workers), the log is done in the main Puma process, after Server#run has been called, as some extensions maybe loaded in that call. For Puma running 'clustered' (workers used), the log is generated in Worker index 0, after Server#run is called and also in the master process.

Log is also generated on phased-restarts.

Added a test for both, small refactor (moved functionality to integration.rb) for using a control server in CI.

Closes #3020

Your checklist for this pull request

• I have reviewed the guidelines for contributing to this repository.
• I have added (or updated) appropriate tests if this PR fixes a bug or adds a feature.
• My pull request is 100 lines added/removed or less so that it can be easily reviewed.
• If this PR doesn't need tests (docs change), I added [ci skip] to the title of the PR.
• If this closes any issues, I have added "Closes #issue" to the PR description or my commit messages.
• I have updated the documentation accordingly.
• All new and existing tests passed, including Rubocop.

[dentarg]

Re: tests, I see there's wait_for_server_to_include, maybe that could be used? Just to look for the Loaded Extensions string at least (when starting with PUMA_DEBUG set)

[MSP-Greg]

Added tests. After #3035, I may try to add a count of the extensions to the two tests, so we'll know if there are additions.

Question - while running locally, I wondered if Puma in 'cluster' mode should log both master process and worker0 loaded extensions? Currently it only logs worker0.

[dentarg]

Added tests. After #3035, I may try to add a count of the extensions to the two tests, so we'll know if there are additions.

👍

Question - while running locally, I wondered if Puma in 'cluster' mode should log both master process and worker0 loaded extensions? Currently it only logs worker0.

I can only see it as a positive to log both

[MSP-Greg]

Changed to show both master and worker0 when running clustered. Sample output below:

Puma Clustered

[8850] Use Ctrl-C to stop
[8850] - Worker 0 (PID: 8852) booted in 0.01s, phase: 0
[8850] - Worker 1 (PID: 8854) booted in 0.01s, phase: 0
[8852] % ────────────────────────────────── Loaded Extensions - worker 0:
[8852] %     enumerator.so
[8852] %     fiber.so
[8852] %     rational.so
[8852] %     complex.so
[8852] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/enc/encdb.so
[8852] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/enc/trans/transdb.so
[8852] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/monitor.so
[8852] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/pathname.so
[8852] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/socket.so
[8852] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/etc.so
[8852] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/date_core.so
[8852] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/stringio.so
[8852] %     /mnt/GitHub/puma/lib/puma/puma_http11.so
[8852] %     /usr/vendor/bundle/puma/mri/ruby/3.2.0+3/extensions/x86_64-linux/3.2.0+3/nio4r-2.5.8/nio4r_ext.so
[8850] % ────────────────────────────────── Loaded Extensions - master:
[8850] %     enumerator.so
[8850] %     fiber.so
[8850] %     rational.so
[8850] %     complex.so
[8850] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/enc/encdb.so
[8850] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/enc/trans/transdb.so
[8850] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/monitor.so
[8850] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/pathname.so
[8850] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/socket.so
[8850] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/etc.so
[8850] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/date_core.so
[8850] %     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/stringio.so
[8850] %     /mnt/GitHub/puma/lib/puma/puma_http11.so

Puma Single

* Listening on http://127.0.0.1:40001
Use Ctrl-C to stop
% ────────────────────────────────── Loaded Extensions:
%     enumerator.so
%     fiber.so
%     rational.so
%     complex.so
%     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/enc/encdb.so
%     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/enc/trans/transdb.so
%     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/monitor.so
%     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/pathname.so
%     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/socket.so
%     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/etc.so
%     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/date_core.so
%     /usr/local/lib/ruby/3.2.0+3/x86_64-linux/stringio.so
%     /mnt/GitHub/puma/lib/puma/puma_http11.so
%     /usr/vendor/bundle/puma/mri/ruby/3.2.0+3/extensions/x86_64-linux/3.2.0+3/nio4r-2.5.8/nio4r_ext.so

[dentarg]

debug_loaded_extensions includes if @log_writer.debug? so no need to guard the method calls with it, right?

[MSP-Greg]

@dentarg

debug_loaded_extensions includes if @log_writer.debug? so no need to guard the method calls with it, right?

Not sure. I felt it was unlikely that many people would regularly be using PUMA_DEBUG, so guard the method call so it's never performed. The guard in the method could be removed, but once it's been called, LogWriter#debug has the conditional anyway, so adding one more seemed insignificant?

[dentarg]

If we want to remove if @log_writer.debug? from the debug_loaded_extensions definition, we should at least be consistent and guard the call in puma/lib/puma/single.rb too, no?

puma/lib/puma/single.rb

Line 60 in 01b013a

debug_loaded_extensions("────────────────────────────────── Loaded Extensions:")

[MSP-Greg]

we should at least be consistent and guard the call in puma/lib/puma/single.rb too, no?

Sorry and thanks for pointing that out, my mistake. Fixed in single.rb, removed conditional in runner.rb, with a comment...

[nateberkopec]

Wait on merge until I push 6.0.2 though 😄

[nateberkopec]

@MSP-Greg Merge when ready 👍