Puma: Setting `log_requests` in puma config file

[jchristie55332]

Describe the bug

When log_requests is set in a puma configuration file it is not respected and as such the requests are not logged to standard out.

Puma config:

DATETIME_FORMAT = '%Y-%m-%d %H:%M:%S %z'.freeze

environment ENV.fetch('RAILS_ENV')

log_requests

log_formatter do |str|
  "#{Time.now.strftime DATETIME_FORMAT} : |Puma| #{str}"
end

To Reproduce

Install Puma into rails project and add puma config file
Boot application using rails s

Expected behavior

Application to log all requests to STDOUT

Desktop (please complete the following information):

• OS: Mac OS 10.14.06
• Puma Version: 4.3.0

[composerinteralia]

I tried this out in a non-rails context on puma master by running RAILS_ENV=development bundle exec bin/puma test/rackup/hello.ru -C config.rb where config.rb contained the config from this issue. I did see logs for requests when I ran this, so there may be something going on here outside puma. Are you able to provide a sample Rails application that reproduces this problem?

---

Curiously, while the standard puma logs did use the custom log_formatter, the request logs did not:

2019-11-13 20:00:08 -0500 : |Puma| Puma starting in single mode...
2019-11-13 20:00:08 -0500 : |Puma| * Version 4.3.0 (ruby 2.6.3-p62), codename: Mysterious Traveller
2019-11-13 20:00:08 -0500 : |Puma| * Min threads: 0, max threads: 16
2019-11-13 20:00:08 -0500 : |Puma| * Environment: development
2019-11-13 20:00:08 -0500 : |Puma| * Listening on tcp://0.0.0.0:9292
2019-11-13 20:00:08 -0500 : |Puma| Use Ctrl-C to stop
127.0.0.1 - - [13/Nov/2019:20:00:12 -0500] "GET / HTTP/1.1" 200 - 0.0001
127.0.0.1 - - [13/Nov/2019:20:03:15 -0500] "GET / HTTP/1.1" 200 - 0.0002

I wonder if that is expected, or if there is a separate bug here with the request logs not using the log_formatter

[jchristie55332]

@composerinteralia the test case that you have specified is using the CLI, however this issue specifically affects the rack handler which is why the issue cannot be reproduced. I have pushed a base generated rails app that shows the issue (https://github.com/jchristie55332/puma-rails-test-app)

[jchristie55332]

Curiously, while the standard puma logs did use the custom log_formatter, the request logs did not:

2019-11-13 20:00:08 -0500 : |Puma| Puma starting in single mode...
2019-11-13 20:00:08 -0500 : |Puma| * Version 4.3.0 (ruby 2.6.3-p62), codename: Mysterious Traveller
2019-11-13 20:00:08 -0500 : |Puma| * Min threads: 0, max threads: 16
2019-11-13 20:00:08 -0500 : |Puma| * Environment: development
2019-11-13 20:00:08 -0500 : |Puma| * Listening on tcp://0.0.0.0:9292
2019-11-13 20:00:08 -0500 : |Puma| Use Ctrl-C to stop
127.0.0.1 - - [13/Nov/2019:20:00:12 -0500] "GET / HTTP/1.1" 200 - 0.0001
127.0.0.1 - - [13/Nov/2019:20:03:15 -0500] "GET / HTTP/1.1" 200 - 0.0002

I wonder if that is expected, or if there is a separate bug here with the request logs not using the log_formatter

The request logs use the commonlogger.rb which is why they are using a different format. I would like to open a feature request to either allow the logger to be configurable (similar to log_requests) or for commonlogger.rb to respect log_formatter if supplied.

(I'm happy to work on this as is a current issue I am facing)

[nateberkopec]

Closed by #2075