Skip to content

Allow logs to be tagged without a block#38850

Merged
eileencodes merged 1 commit intorails:masterfrom
eugeneius:tagged_logging_without_block
Mar 31, 2020
Merged

Allow logs to be tagged without a block#38850
eileencodes merged 1 commit intorails:masterfrom
eugeneius:tagged_logging_without_block

Conversation

@eugeneius
Copy link
Copy Markdown
Member

Calling ActiveSupport::TaggedLogger#tagged without a block now returns a new logger with the tags applied. This is useful for when you want to tag an individual log line, rather than an entire request.

Our application has code that looks like this in several places:

class NotificationWorker
  LOG_PREFIX = "[Notifications]"

  def perform
    log("Started delivering notifications")

    Notification.pending.find_each do |notification|
      notification.deliver!
      log("Successfully delivered notification #{notification.id}")
    rescue
      log("Failed to deliver notification #{notification.id}, #{e.class}: #{e.message}", level: :error)
    end

    log("Finished delivering notifications")
  end

  def log(msg, level: :info)
    Rails.logger.send(level, "#{LOG_PREFIX} #{msg}")
  end
end

The brackets in LOG_PREFIX imitate tagged logging, so that we can search for those lines in the same way that we search for all of the logs from a particular request or job. We want to be able to find the lines summarising the outcome of the job, without any other lines logged by deliver!.

With this change, we'll be able to write that code in a way that's closer to normal logger usage:

class NotificationWorker
  def perform
    logger.info("Started delivering notifications")

    Notification.pending.find_each do |notification|
      notification.deliver!
      logger.info("Successfully delivered notification #{notification.id}")
    rescue
      logger.error("Failed to deliver notification #{notification.id}, #{e.class}: #{e.message}")
    end

    logger.info("Finished delivering notifications")
  end

  def logger
    Rails.logger.tagged("Notifications")
  end
end

Copy link
Copy Markdown
Member

@eileencodes eileencodes left a comment

Choose a reason for hiding this comment

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

This looks great, but I think the new docs feel repetitive and left a suggestion.

Calling `#tagged` without a block now returns a new logger with the tags
applied. This is useful for when you want to tag an individual log line,
rather than an entire request.
@eugeneius eugeneius force-pushed the tagged_logging_without_block branch from 4c0a07d to f84e0d6 Compare March 31, 2020 15:05
@eileencodes eileencodes merged commit a1b6f08 into rails:master Mar 31, 2020
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.
@erikbelusic
Copy link
Copy Markdown

I have a question here, about the original intended behavior, as I am perceiving this "intended" behavior as a potential bug.
Why is it appropriate for tagging without a block to share tags across threads, but it is the opposite when tagging with a block?

Specifically talking about this:
https://github.com/rails/rails/blob/main/activesupport/test/tagged_logging_test.rb#L80C1-L89

vs this:
https://github.com/rails/rails/blob/main/activesupport/test/tagged_logging_test.rb#L178-L189

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.

3 participants