rails: Too much magic in `Rails.logger` and logging to `STDERR` causes duplicate output.

With the following code in a Rails configuration file:

Rails.logger = Logger.new(STDERR)

Causes duplicate log statements when running the app with rails s. It’s caused by the following:

https://github.com/rails/rails/blob/346ae79d5a11152f508df8d5506f8a0682ddb74b/railties/lib/rails/commands/server/server_command.rb#L75-L85

The implementation of logger_outputs_to? uses private details of the logger instance to determine whether it’s logging to STDOUT. In this specific case, adding STDERR as part of the check might also work. However, not all logger objects have the same private details causing this check to fail in those cases too.

https://github.com/rails/rails/blob/346ae79d5a11152f508df8d5506f8a0682ddb74b/activesupport/lib/active_support/logger.rb#L16-L20

I don’t think we should be inspecting private object details and I believe that the implementation creates too many edge cases which are better handled by explicit configuration.

My advice would be:

Default to Rails.logger = Logger.new(STDERR) (& don’t log to log files).
Don’t use instance_variable_get and consider removing logger_outputs_to?.
Remove monkey patching (and private implementation introspection) of Rails.logger.
Educate users on how to get previous behaviour if it’s desired.

If we want to support output to multiple targets, this should be a feature of the log library not the interface for logging. I suggest some kind of tee logger should be appropriate, but I think it’s better if we keep this simple in Rails and let logger gem solve this problem.

About this issue

Original URL
State: open
Created 2 years ago
Comments: 29 (28 by maintainers)

Most upvoted comments

Okay sure, but why?

It’s a feature of Rails. It helps you understand what’s actually happening when you run your code.

~ $ rails c
irb(main):001:0> User.where(github: "Tabby").first
D, [2023-02-07T21:42:18.624272 #7] DEBUG -- :   User Load (2.1ms)  SELECT "users".* FROM "users" WHERE "users"."github" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["github", "Tabby"], ["LIMIT", 1]]
=> nil
irb(main):003:0> User.where(email: "t<redacted>y@b<redacted>n.online").first
D, [2023-02-07T21:42:40.034092 #7] DEBUG -- :   User Load (2.0ms)  SELECT "users".* FROM "users" WHERE "users"."email" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["email", "t<redacted>y@b<redacted>n.online"], ["LIMIT", 1]]
=> nil

schneems on Feb 7, 2023

I’m coming from a pragmatic place: Any code that solves the double logging problem while meeting all other specifications is fine.

If you don’t like that interface, instead of exposing the destination perhaps more of a respond_to type pattern could be good where we directly ask the object it’s capabilities. Something like:

logger.writes_to?(STDOUT)

Just for example. I’m really not attached to any particular interface though.

At the end of the day, I think Rails just needs to answer the question: Will the end user see SQL logs on the console in development or not?

if no: inject a STDOUT logger
if yes: do nothing, prevent double output to STDOUT

There might be some other way to do it, but for many releases Rails exposes the setting of the logger to Rails users. Spitballing here, but we could try some other gnarly solutions:

In a block re-assign $stdout to a StringIO instance, then intentionally trigger a log then inspect the StringIO instance and reset $stdout to see if it gets written. That’s actually probably the most correct “can you do this thing” we can ask of the logger that doesn’t violate its interface. However: it’s gnarly. I don’t know Rails would accept that code. I guess you could try to make that case if you want.

So it seems either we introduce a less-than-optimal API into Ruby to get rid of an awful hack in Rails, or we introduce a possibly questionable hack into Rails to avoid a different hack in Rails.

schneems on Mar 16, 2023

I’m not happy with it, but it works and I didn’t see any other alternative. I opened an issue on bugs.ruby-lang about opening an interface to expose the logger destination but it didn’t go far. If you’re interested in removing that hack that’s probably the best next step.

schneems on Feb 5, 2023

Default to Rails.logger = Logger.new(STDERR) (& don’t log to log files).

I don’t think this is going to happen. Logging to files has been the default for so long, and it’s not likely to change. We should make Rails.logger = Logger.new(STDERR) work correctly though.

I suggest some kind of tee logger should be appropriate, but I think it’s better if we keep this simple in Rails and let logger gem solve this problem.

This seems good to me, but I don’t have time to do the legwork. If we have a tee logger available, then I’d be happy to change Rails to use it.

tenderlove on Oct 12, 2022