New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[close #22917] Don't output to `STDOUT` twice #22933

Merged
merged 3 commits into from Jan 6, 2016

Conversation

Projects
None yet
4 participants
@schneems
Member

schneems commented Jan 5, 2016

When rails console or rails server are used along with a logger set to output to STDOUT then the contents will show up twice. This happens because the logger is extended with ActiveSupportLogger.broadcast with a destination of STDOUT even if it is already outputting to STDOUT.

Previously PR #22592 attempted to fix this issue, but it ended up causing NoMethodErrors. A better approach than relying on adding a method and flow control is to inspect the log destination directly. For this ActiveSupport::Logger.logger_outputs_to? was introduced

logger = Logger.new(STDOUT)
ActiveSupport::Logger.logger_outputs_to?(logger, STDOUT)
# => true

To accomplish this we must look inside of an instance variable of standard lib's Logger @logdev. There is a related Ruby proposal to expose this method in a standard way: https://bugs.ruby-lang.org/issues/11955

Show outdated Hide outdated activesupport/test/logger_test.rb
assert Logger.logger_outputs_to?(@logger, @output), "Expected logger_outputs_to? @output to return true but was false"
assert Logger.logger_outputs_to?(@logger, @output, STDOUT), "Expected logger_outputs_to? @output or STDOUT to return true but was false"
assert ! Logger.logger_outputs_to?(@logger, STDOUT), "Expected log_outputs? to STDOUT to return false, but was true"

This comment has been minimized.

@rafaelfranca

rafaelfranca Jan 5, 2016

Member

assert_not

@rafaelfranca

rafaelfranca Jan 5, 2016

Member

assert_not

This comment has been minimized.

@rafaelfranca

rafaelfranca Jan 5, 2016

Member

Also better to not align the messages, if we need to change something in one line we would have to change in others too.

The message is also using log_outputs? instead of logger_outputs_to?

@rafaelfranca

rafaelfranca Jan 5, 2016

Member

Also better to not align the messages, if we need to change something in one line we would have to change in others too.

The message is also using log_outputs? instead of logger_outputs_to?

Show outdated Hide outdated railties/lib/rails/commands/server.rb
@@ -137,7 +137,9 @@ def log_to_stdout
console.formatter = Rails.logger.formatter
console.level = Rails.logger.level
Rails.logger.extend(ActiveSupport::Logger.broadcast(console))
unless ActiveSupport::Logger.logger_outputs_to?(Rails.logger, $stdout)

This comment has been minimized.

@rafaelfranca

rafaelfranca Jan 5, 2016

Member

Why here it is using $stdout instead of STDOUT like other places?

@rafaelfranca

rafaelfranca Jan 5, 2016

Member

Why here it is using $stdout instead of STDOUT like other places?

This comment has been minimized.

@schneems

schneems Jan 6, 2016

Member

I matched $stdout to the existing usage in the file. I'll switch them both over to STDOUT.

@schneems

schneems Jan 6, 2016

Member

I matched $stdout to the existing usage in the file. I'll switch them both over to STDOUT.

Show outdated Hide outdated activesupport/lib/active_support/logger.rb
@@ -1,3 +1,4 @@
require 'active_support/core_ext/module/attribute_accessors'

This comment has been minimized.

@rafaelfranca

rafaelfranca Jan 5, 2016

Member

Is this still needed?

@rafaelfranca

rafaelfranca Jan 5, 2016

Member

Is this still needed?

@rafaelfranca

This comment has been minimized.

Show comment
Hide comment
@rafaelfranca

rafaelfranca Jan 5, 2016

Member

I agree that this approach is better but for me it is relying in something that is not public and we don't have guarantees if it will still work in the future.

Member

rafaelfranca commented Jan 5, 2016

I agree that this approach is better but for me it is relying in something that is not public and we don't have guarantees if it will still work in the future.

@schneems

This comment has been minimized.

Show comment
Hide comment
@schneems

schneems Jan 6, 2016

Member

relying in something that is not public and we don't have guarantees if it will still work in the future.

I designed this to fail gracefully, when something doesn't have that instance variable or that variable doesn't respond to dev then it will not return true. In that case we will always log to STDOUT which is no different from the behavior we have today. That interface hasn't changed in a very long time but I will stick around and maintain this code if the interface changes, I can accommodate any updates to Logger.

Member

schneems commented Jan 6, 2016

relying in something that is not public and we don't have guarantees if it will still work in the future.

I designed this to fail gracefully, when something doesn't have that instance variable or that variable doesn't respond to dev then it will not return true. In that case we will always log to STDOUT which is no different from the behavior we have today. That interface hasn't changed in a very long time but I will stick around and maintain this code if the interface changes, I can accommodate any updates to Logger.

[close #22917] Don't output to `STDOUT` twice
When `rails console` or `rails server` are used along with a logger set to output to `STDOUT` then the contents will show up twice. This happens because the logger is extended with `ActiveSupportLogger.broadcast` with a destination of STDOUT even if it is already outputting to `STDOUT`.

Previously PR #22592 attempted to fix this issue, but it ended up causing NoMethodErrors. A better approach than relying on adding a method and flow control is to inspect the log destination directly. For this `ActiveSupport::Logger.logger_outputs_to?` was introduced

```ruby
logger = Logger.new(STDOUT)
ActiveSupport::Logger.logger_outputs_to?(logger, STDOUT)
# => true
```

To accomplish this we must look inside of an instance variable of standard lib's Logger `@logdev`. There is a related Ruby proposal to expose this method in a standard way: https://bugs.ruby-lang.org/issues/11955
@schneems

This comment has been minimized.

Show comment
Hide comment
@schneems

schneems Jan 6, 2016

Member

updated

Member

schneems commented Jan 6, 2016

updated

@rafaelfranca

This comment has been minimized.

Show comment
Hide comment
@rafaelfranca

rafaelfranca Jan 6, 2016

Member

Seems good to me. I think the broadcast_message option is documented in the guides as well in the CHANGELOG, we should remove it too. :shipit:

Member

rafaelfranca commented Jan 6, 2016

Seems good to me. I think the broadcast_message option is documented in the guides as well in the CHANGELOG, we should remove it too. :shipit:

@schneems

This comment has been minimized.

Show comment
Hide comment
@schneems

schneems Jan 6, 2016

Member

I did a grep and removed all mentions of broadcast_message.

Member

schneems commented Jan 6, 2016

I did a grep and removed all mentions of broadcast_message.

schneems added a commit that referenced this pull request Jan 6, 2016

@schneems schneems merged commit cc58837 into rails:master Jan 6, 2016

1 check passed

continuous-integration/travis-ci/pr The Travis CI build passed
Details
@eileencodes

This comment has been minimized.

Show comment
Hide comment
@eileencodes

eileencodes Jan 6, 2016

Member

I don't think it made it into the guides. The original PR didn't have a changelog and I didn't add one. Here's the doc PR which was just in the code a13032c

Member

eileencodes commented Jan 6, 2016

I don't think it made it into the guides. The original PR didn't have a changelog and I didn't add one. Here's the doc PR which was just in the code a13032c

@schneems schneems referenced this pull request Jan 18, 2016

Closed

Inherits from as logger #19

kibitan added a commit to kibitan/nasulog that referenced this pull request Jan 29, 2016

kibitan added a commit to kibitan/nasulog that referenced this pull request Feb 7, 2016

schneems added a commit to schneems/rails that referenced this pull request Feb 12, 2016

Log to stdout by default
Originally this logic was added by my PR https://github.com/rails/rails/pull/11060/files to only log to stdout in development mode. This was to prevent double logging when STDOUT was already being set as a logger. Since the introduction of the ability to detect logging to STDOUT in rails#22933 we can inspect the destination of logs directly, this brings better dev/prod parity with logging behavior.
@jonathan-mui

This comment has been minimized.

Show comment
Hide comment
@jonathan-mui

jonathan-mui May 2, 2017

I attempted to follow #22592, but found out that has since been changed with this PR. How should this change be used in the environment config file to prevent duplicate logging?

I attempted to follow #22592, but found out that has since been changed with this PR. How should this change be used in the environment config file to prevent duplicate logging?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment