Setting logger level resets logger unexpectedly

[eprothro]

With the following initialization code

# Set timeout stream to application log stream
Rack::Timeout::Logger.logger = Rails.logger

# Set timeout logger level
# DEBUG results in `active` events every second
# Rack::Timeout.logger.level = ::Logger::INFO
# ERROR results in only `timed_out` and `expired` events
Rack::Timeout::Logger.level = Rails.logger.try(:level) || ::Logger::ERROR

The logger is set to STDERR, instead of the logger object set (Rails.logger in this example).

[6] pry(main)> Rack::Timeout::Logger.logger
=> #<Logger:0x007fe3664b1990   # <= default logger
 @default_formatter=#<Logger::Formatter:0x007fe3664b1968 @datetime_format=nil>,
 @formatter=#<ActiveSupport::Logger::SimpleFormatter:0x007fe3664b1878 @datetime_format=nil, @source="web">,
 @level=0,
 @logdev=
  #<Logger::LogDevice:0x007fe3664b1918
   @dev=#<IO:<STDOUT>>,
   @filename=nil,
   @mutex=#<Logger::LogDevice::LogDeviceMutex:0x007fe3664b18f0 @mon_count=0, @mon_mutex=#<Mutex:0x007fe3664b18a0>, @mon_owner=nil>,
   @shift_age=nil,
   @shift_size=nil>,
 @progname=nil>

[7] pry(main)> Rack::Timeout::Logger.logger = Rails.logger
=> #<Logger:0x007fe3664b1990   # <= explicitly set logger
 @default_formatter=#<Logger::Formatter:0x007fe3664b1968 @datetime_format=nil>,
 @formatter=#<ActiveSupport::Logger::SimpleFormatter:0x007fe3664b1878 @datetime_format=nil, @source="web">,
 @level=0,
 @logdev=
  #<Logger::LogDevice:0x007fe3664b1918
   @dev=#<IO:<STDOUT>>,
   @filename=nil,
   @mutex=#<Logger::LogDevice::LogDeviceMutex:0x007fe3664b18f0 @mon_count=0, @mon_mutex=#<Mutex:0x007fe3664b18a0>, @mon_owner=nil>,
   @shift_age=nil,
   @shift_size=nil>,
 @progname=nil>

[8] pry(main)> Rack::Timeout::Logger.device
=> nil

[9] pry(main)> Rack::Timeout::Logger.level = ::Logger::ERROR
=> 3

[10] pry(main)> Rack::Timeout::Logger.device
=> #<IO:<STDERR>>       # <= setting level resets underlying device

[11] pry(main)> Rack::Timeout::Logger.logger
=> #<Logger:0x007fe36669fa90      # <= logger is reverted to default
 @default_formatter=#<Logger::Formatter:0x007fe36669fa68 @datetime_format=nil>,
 @formatter=#<Proc:0x007fe361e1f810@/Users/eprothro/.rbenv/versions/2.2.4/lib/ruby/gems/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/logging-observer.rb:17 (lambda)>,
 @level=3,
 @logdev=
  #<Logger::LogDevice:0x007fe36669fa18
   @dev=#<IO:<STDERR>>,
   @filename=nil,
   @mutex=#<Logger::LogDevice::LogDeviceMutex:0x007fe36669f9f0 @mon_count=0, @mon_mutex=#<Mutex:0x007fe36669f9a0>, @mon_owner=nil>,
   @shift_age=nil,
   @shift_size=nil>,
 @progname=nil>

[eprothro]

For any others, here is our workaround:

# only print rack timeout errors unless debugging
logger = Rails.logger.clone
logger.level = Rails.logger.debug? ? ::Logger::DEBUG : ::Logger::ERROR
Rack::Timeout::Logger.logger = logger

[kch]

This behavior is documented in the readme.

You wouldn't want us changing the log level on the rails logger object from under rails (If that's possible at all). That way madness lies.

[eprothro]

I certainly agree that would be egregious.

However, from my perspective, if an object allows me to independently set the logger and the level, I expect it to handle doing so with the least amount of surprise. I was quite surprised by the behavior.

An internal clone upon logger set might just satisfy all the needs?

[kch]

Mind that you are setting Rack::Timeout::Logger.logger, and then Rack::Timeout::Logger.level, not Rack::Timeout::Logger.logger.level. So I hope the fact that level is not a property of .logger, but of …::Logger hints at the defined behavior.

Also, your workaround is pretty clean.

IIRC, the reason this interface ended up this way is because there's no way to read the device from a logger object (which I could use to create the new logger)…

Maybe I could make it so you can either use logger= or level= & device=, but not one then the other. That would be more restrictive but certainly prevent the surprise, whilst sparing a lot of code.

Is there anything else you get from using rails's logger other than the output device?

[eprothro]

Maybe I could make it so you can either use logger= or level= & device=, but not one then the other. That would be more restrictive but certainly prevent the surprise, whilst sparing a lot of code.

I certainly would vote for that approach over what exists now. I have done that in my interfaces a few times and have been happy enough with the result.

Is there anything else you get from using rails's logger other than the output device?

Yes, formatter. The reason I clone here (instead of calling update with device and level) is that my logger (descendent of Logger, forget Rails for a moment) has a custom formatter (descendent of Logger::Formatter) that I lose if Rack::Timeout creates its own Logger with only my device and level. And like any good citizen, I would like consistent log formatting.

[eprothro]

And just FWIW, my first-blush interpretation of the separate level and logger was:

Rack::Timeout: "Oh hey, I'll use your logger, and also, you can put me at a different, specific log_level and I'll prefer that level instead of the level defined in your logger when I determine to print a message or not."

Me: "Nice! That's kinda different, but pretty much exactly what I wanted, thanks!"

[kch]

@eprothro if you can come up with something better in a PR I'll consider it for merging. Otherwise I'll leave this open but it's not a priority. So it falls under I'll get to it when I get to it.

[eprothro]

Agree with that prioritization.

-Evan Prothro
Sent from my mobile

On Mar 15, 2016, at 5:28 PM, Caio Chassot notifications@github.com wrote:

@eprothro if you can come up with something better in a PR I'll consider it for merging. Otherwise I'll leave this open but it's not a priority. So it falls under I'll get to it when I get to it.

—
You are receiving this because you were mentioned.
Reply to this email directly or view it on GitHub

[aguynamedben]

👍 I also found this confusing. Thanks for the workaround @eprothro

[schneems]

Last comment was 4 years ago. If there's still a bug please make a an https://www.codetriage.com/example_app and open a new issue so we can track it.