Skip to content

TaggedLogging to return a new logger instance #27792

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

Merged
merged 1 commit into from
Sep 11, 2018

Conversation

tjoyal
Copy link
Contributor

@tjoyal tjoyal commented Jan 24, 2017

Summary

I have a small question and what is better than a PR to discuss it.

ActiveSupport::TaggedLogging through the new method would mutate the argument instead of returning a new instance. This might be my design but it really got me confused at first. I would have expected some other kind of method to provide such mutation (eg.: ActiveSupport::TaggedLogging.tag(logger))

The changes in here would clone the logger received in argument (and the associated formatter that ActiveSupport::TaggedLogging perform on) returning a new instance.

The associated test is what made me really confused the first time I hit the original behaviour.

Todo:

  • If this go forward it'll require an entry in changelog?

@rails-bot
Copy link

Thanks for the pull request, and welcome! The Rails team is excited to review your changes, and you should hear from @arthurnn (or someone else) soon.

If any changes to this PR are deemed necessary, please add them as extra commits. This ensures that the reviewer can see what has changed since they last reviewed the code. Due to the way GitHub handles out-of-date commits, this should also make it reasonably obvious what issues have or haven't been addressed. Large or tricky changes may require several passes of review and changes.

This repository is being automatically checked for code quality issues using Code Climate. You can see results for this analysis in the PR status below. Newly introduced issues should be fixed before a Pull Request is considered ready to review.

Please see the contribution instructions for more information.

@arthurnn
Copy link
Member

I agree that new should return a new object, and not mutate the existent one.
@rafaelfranca @matthewd thoughts?
I am 👍 here

Copy link
Member

@rafaelfranca rafaelfranca left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM too. A CHANGELOG entry will be required since this may be a breaking change.

logger = logger.dup

logger.formatter = if logger.formatter
logger.formatter.dup
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Those lines should be aligned with the if. Rubocop is complaining.

@tjoyal tjoyal force-pushed the sandbox-tagged-logging branch 2 times, most recently from b58af1f to 4a7ff05 Compare February 1, 2017 18:16
@tjoyal tjoyal changed the title Sandbox tagged logging TaggedLogging to return a new logger instance Feb 1, 2017
@tjoyal
Copy link
Contributor Author

tjoyal commented Feb 1, 2017

Updated, tell me if you are good with the changes.

@matthewd
Copy link
Member

matthewd commented Feb 1, 2017

Does this risk multiplying the number of live logger instances we have in an application?

That seems like it could affect what gets silenced, for example.

@tjoyal
Copy link
Contributor Author

tjoyal commented Feb 2, 2017

Does this risk multiplying the number of live logger instances we have in an application?

My thought of chain on this is when calling new, I expect to get a new object.

I think it's a fair concern, and to some extent I would consider setting my Rails.logger to return a tagged logger from the ground up if I was planning to tag a lot of things. (vs re-init everywhere in the code leading to a lot of code duplication).

I think it would be possible to come up with a mutating method that is not named new that would have the old behaviour, but I don't see the need for it just yet.

That seems like it could affect what gets silenced, for example.

Definitely (it's a new instance after all, unless dup decide to handle logic to bridge behaviour between instances).

But once again, I think this is expected from a method that is called new.

As proposed up there, if one was to use a lot of tagged logging in his application, I think it would be fair to consider setting it as the default logger.

In the cases where I wanted to use tagged logging, the desired behaviour was to do a dup like in this PR so my tags are only applied to the current context of the unit of code I'm wrapping, and not propagated to other unit of code that might be called in other classes.

Eg.: A fairly simple example

class Object
  def method_a
    logger = ActiveSupport::TaggedLogging.new(Rails.logger)
    logger.tagged("BCX") do
      logger.info "something" # I expected this to be tagged
      method_b
    end
  end

  def method_b
    Rails.logger.info "something else" # I do not expect this to be tagged
  end
end

@tjoyal tjoyal force-pushed the sandbox-tagged-logging branch from 4a7ff05 to 62fba74 Compare February 27, 2017 21:01
Copy link
Member

@gmcgibbon gmcgibbon left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Still relevant in Rails 6 28e5085. I'll admit that when I first saw the source for ActiveSupport::TaggedLogging.new I thought it was being too clever. If we want to keep the mutation approach, could we just rename the new method to something more explanatory?

@rafaelfranca rafaelfranca merged commit 62fba74 into rails:master Sep 11, 2018
rafaelfranca added a commit that referenced this pull request Sep 11, 2018
TaggedLogging to return a new logger instance
@tjoyal tjoyal deleted the sandbox-tagged-logging branch September 18, 2018 09:56
suketa added a commit to suketa/rails_sandbox that referenced this pull request May 28, 2019
TaggedLogging to return a new logger instance
rails/rails#27792
palkan added a commit to anycable/anycable-rails that referenced this pull request Jun 21, 2019
Tagged logger return a new logger instance now: rails/rails#27792
@@ -57,8 +57,15 @@ def tags_text
end

def self.new(logger)
# Ensure we set a default formatter so we aren't extending nil!
logger.formatter ||= ActiveSupport::Logger::SimpleFormatter.new
logger = logger.dup
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Any special reason #dup was used here? I have opened #40759 to address a side-effect of not using #clone.

Edouard-chin added a commit to Edouard-chin/rails that referenced this pull request Jul 3, 2023
- Opening this PR to get some first impression and feedback and see if
  that’s the path we want to take.

  ## Context

  While working on rails#44695, I
  realised that Broadcasting was still a private API, although it’s
  commonly used. Rafael mentioned that making it public would require
  some refactor because of the original implementation which was hard
  to understand and maintain.

  TaggedLogging is another piece of this PR, while it’s not related
  to broadcasting, both features combined were a source of issues and
  confusion (see rails#38850, rails#27792, rails#45854 and some more).
  Broadcasting and tagged logging were a bit entangled and I felt it
  would be easier to have the bigger picture in a single PR.

  TaggedLogging is public and the new implementation doesn’t introduce
  any breaking change.

  Broadcasting is in a grey zone, it’s not referenced in our docs but
  I saw it often in apps and libraries. This refactor would break them.
  Happy to revisit that and find a way to make it compatible.

  ## Implementation

  The changes would make a lot of diff chunks, so to make it easier to
  review I opted to not modify the original files and free the constant
  name (Logger, TaggedLogging) for the new implementation that are
  inside new files.
  All code in this PR is new and uses code from the previous
  implementation that don’t appear in the diff. The goal would be to
  copy/paste the required code at the end of the review process.

  ---------------

  ### Changing how broadcasting works:

  Broadcasting in a nutshell worked by “transforming” an existing
  logger into a broadcasted one.
  The logger would then be responsible to log and format its own
  messages as well as passing the message along to other logger it
  broadcasts to.

  The problem with this approach was the following:

  - Heavy use of metaprogramming.
  - Accessing the loggers in the broadcast wasn’t possible.
    Removing a logger from the broadcast either.
  - More importantly, modifying the main logger (the one that broadcasts
    logs to the others) wasn’t possible and the main source of
    misunderstanding.

    ```ruby
      logger = Logger.new(STDOUT)
      stderr_logger = Logger.new(STDER))
      logger.extend(AS::Logger.broadcast(stderr_logger))

      logger.level = DEBUG # This modifies the level on all other loggers
      logger.formatter = … # Modified the formatter on all other loggers
    ```

  -> New approach

  To keep the contract unchanged on what Rails.logger returns, the new
  implementation is still a subclass of Logger.
  The difference is that now the broadcast logger just delegate al
  methods to all the other loggers it’s broadcasting to.
  It’s simple and boring and it’s now just an array that gets
  iterated over.

  Now, users can access all loggers inside the broadcast and modify
  them on the fly. They can also remove any logger from the broadcast
  at any time.

  ```ruby
  # Before

  stdout_logger = Logger.new(STDOUT)
  stderr_logger = Logger.new(STDER)
  file_logger = Logger.new(“development.log”)
  stdout_logger.extend(AS::Logger.broadcast(stderr_logger))
  stdout_logger.extend(AS::Logger.broadcast(file_logger))

  # After

  broadcast = BroadcastLogger.new
  broadcast.broadcast_to(stdout_logger, stderr_logger, file_logger)
  ```

  I also think that now, it should be more clear for users that the
  broadcast sole job is to pass everything to the whole loggers in
  the broadcast. So there should be no surprise that all loggers in
  the broadcast get their level modified when they call
  `broadcast.level = DEBUG` .

  It’s also easier to wrap your head around more complex setup such
  as broadcasting logs to another broadcast:
  `broadcast.broadcast_to(stdout_logger, other_broadcast)`

  ### Changing TaggedLogging

  Tagged logging is painful to implement because there is basically no
  good way to hook into the vanilla logger code. The easiest is to
  hook on the formatter but IMHO this is implemented at the wrong
  level.

  Adding tags on the formatter means:

  - Monkeypatching the formatter on the logger. With the broadcasting
    feature, that meant modifying all formatters on all loggers.
  - From its name, I would assume that a formatter job is just to
    format. Not add modify the logs and add extra information.

    What I felt was missing was an object responsible to process the
    logs just before it gets formatted. So I implemented a
    “LogProcessor” which seats just after the user pass a log,
    but before it gets formatted.
    I thought it is a good addition that would allow to have
    multiple processors in the case users or libraries need to pass
    their logs into multiple processors.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

8 participants