Add a public API for broadcasting logs #48615

Edouard-chin · 2023-06-30T02:55:14Z

Context

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

Broadcasting

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.

  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

To keep the contract unchanged on what Rails.logger returns, the new BroadcastLogger class implement duck typing with all methods that has the vanilla Ruby Logger class.
It's a simple and boring PORO that keeps an array of all the loggers that are part of the broadcast and iterate over whenever a log is sent.

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.

# 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(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)

activesupport/lib/active_support.rb

Edouard-chin · 2023-06-30T02:58:37Z

activesupport/lib/active_support/broadcast_logger.rb

+    # @return [Array<Logger>] All the logger that are part of this broadcast.
+    attr_reader :broadcasts
+
+    def initialize(logdev = File::NULL, *args, **kwargs)


Ideally would have preferred to be able to do BroadcastLogger.new(logger1, logger2), but that would mean either:

Modify the original signature

Create a PORO and implement duck typing because I felt the BroadcastLogger should behave just like a logger.

Not sure what's the best option

I think we should do the latter.

Sounds good thanks. So I guess if there is no red flag on this implementation, I'll go ahead and finish the PR (the AS test suite is passing already, I don't think this PR will change a lot to have a green CI).

Regarding

Broadcasting is in a grey zone and not referenced in our docs but I saw it often in apps and libraries. This refactor would break them.

Should we go through a deprecation cycle or nop?

nop. The broadcast method is nodoced.

I have no reservations about this implementation. I think it will be way easier to use and maintain.

Edouard-chin · 2023-07-03T22:17:23Z

Originally wanted to fix TaggedLogging and implement a better broadcast logger at the same time (because they are kind of coupled and the issues occur with tagged logging when used with a broadcast), but the changes are too big for a single PR and the the many diff hunks would be annoying to review.

I changed this PR to focus only on broadcasting and will propose the change for tagged logging in another PR.

Edouard-chin · 2023-07-03T22:29:44Z

activesupport/lib/active_support/broadcast_logger.rb

+    def progname; end
+
+    # Implemented for duck typing.
+    def level; end


Not sure what's the best approach here.

In the context of a broadcast, getting the level (and the progname above) don't make sense because the level on each loggers that are part of the broadcast can be different from one another.

In the previous implementation, level would return the level of the first logger in the broadcast. So I think we have a few options:

Do the same as before and return the level of the first logger.

Always return nil

Don't implement the method.

Maybe return the higher level between all the loggers that are going to be brodcasted to?

That's a good idea 👍

rafaelfranca · 2023-08-01T23:25:21Z

activesupport/lib/active_support/broadcast_logger.rb

+    def progname; end
+
+    # Implemented for duck typing.
+    def level; end


Maybe return the higher level between all the loggers that are going to be brodcasted to?

rafaelfranca · 2023-08-01T23:26:00Z

activesupport/lib/active_support/broadcast_logger.rb

+    end
+
+    # Implemented for duck typing.
+    def progname; end


Maybe return something like "Broadcast"?

rafaelfranca · 2023-08-01T23:26:27Z

activesupport/lib/active_support/broadcast_logger.rb

+
+    # Add logger(s) to the broadcast.
+    #
+    # @param loggers [Logger] Loggers that will be part of this broadcast.


Rails doesn't use yard, so let's change the documentation to follow Rails conventions.

rafaelfranca · 2023-08-01T23:27:27Z

activesupport/lib/active_support/broadcast_logger.rb

+      @formatter = formatter
+    end
+
+    def progname=(progname)


Do we want to allow assigning the progname? I think all the loggers inside the broadcast will have different prog names and we don't want to make all of them the same.

Yeah I agree that assigning the progname for all loggers is weird. But I was thinking that the behaviour on this broadcast should make it clear that any methods called on it will modify all inner loggers. Could be confusing if progname= is the only exception to that rule?

No strong opinion though and I'm happy to change it.

Good point. But I think progname is really uniq for each logger so I think it would be better to now allow a mass update. We can even raise an exception. But given progname will return Boardcast make this method change only the progname of the broadcast?

zzak · 2023-09-23T22:51:17Z

@Edouard-chin Could you squash your commits and rebase the changelog please? 🙏

Edouard-chin · 2023-09-24T00:19:36Z

👍 Thanks for marking this for the 7.1 release. I’ll do tomorrow when I come back home ! Le dim. 24 sept. 2023 à 00:51, zzak ***@***.***> a écrit :

…

@Edouard-chin <https://github.com/Edouard-chin> Could you squash your commits and rebase the changelog please? 🙏 — Reply to this email directly, view it on GitHub <#48615 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AB567BWASQXNAWTCYA5NKTDX35RXDANCNFSM6AAAAAAZZIUWQ4> . You are receiving this because you were mentioned.Message ID: ***@***.***>

Edouard-chin · 2023-09-24T14:22:20Z

Should be good for another 👀

- ## 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. ### 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 ``` To keep the contract unchanged on what Rails.logger returns, the new BroadcastLogger class implement duck typing with all methods that has the vanilla Ruby Logger class. It's a simple and boring PORO that keeps an array of all the loggers that are part of the broadcast and iterate over whenever a log is sent. 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(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)`

miharekar · 2023-09-28T09:46:19Z

I'd like to write a proper issue/PR but I'm not sure how to debug further regarding logging changes.

Logs worked fine in 7.1.0.beta1 but in 7.1.0.rc1 (with this in) I no longer have most logs in stdout, only in development.log. I only have Started PATCH… and similar in stdout, but nothing about request params or activerecord, or anything. It is in development.log though.

I tried creating a fresh rails app with a generator, and the logs showing in stdout there, as expected. I've looked at app and environment configs and can't see any diff there. I've put a debugger inside LogSubscriber but it looks the same for both apps. So I'm not sure what's going on and how to debug it further 🤔

Here's the app: https://github.com/miharekar/decent-visualizer/tree/broken-logs

Edouard-chin · 2023-09-28T11:08:36Z

Thanks for letting me know, you are right I'm seeing the same thing. Sorry for missing that. Looking now 👀

Edouard-chin · 2023-09-28T14:08:37Z

Opened a PR in #49417 to fix this.

- An oversight of rails#48615 is that it changes the `Rails.logger` to be a broadcast logger after the app is booted. Anything referencing `Rails.logger` during the boot process will get a simple logger and ultimately resulting in logs not being broadcasted. For example `ActionController::Base.logger.info("abc")` would just output logs in the `development.log` file, not on STDOUT. ---- The only solution I could think of is to create a BroadcastLogger earlier at boot, and add logger to that broadcast when needed (instead of modiyfing the `Rails.logger` variable).

In rails/rails#48615, Rails 7.1 introduced a new BroadcastLogger class that allows users to send logs to multiple loggers, which means we need to adjust the SDK's logger assignment for it.

* Adopt Rails 7.1's new BroadcastLogger In rails/rails#48615, Rails 7.1 introduced a new BroadcastLogger class that allows users to send logs to multiple loggers, which means we need to adjust the SDK's logger assignment for it. * Update changelog

Rails 7.1.0 introduces a new default logger class, ActiveSupport::BroadcastLogger, which does not inherit from Logger. (See: rails/rails#48615.) Instead of testing for a specific class, we can test the interface.

- An oversight of rails#48615 is that it changes the `Rails.logger` to be a broadcast logger after the app is booted. Anything referencing `Rails.logger` during the boot process will get a simple logger and ultimately resulting in logs not being broadcasted. For example `ActionController::Base.logger.info("abc")` would just output logs in the `development.log` file, not on STDOUT. ---- The only solution I could think of is to create a BroadcastLogger earlier at boot, and add logger to that broadcast when needed (instead of modiyfing the `Rails.logger` variable).

Rails 7.1.0 introduces a new default logger class, ActiveSupport::BroadcastLogger, which does not inherit from Logger. (See: rails/rails#48615.) Instead of testing for a specific class, we can test the interface.

Rails 7.1.0 introduces a new default logger class, ActiveSupport::BroadcastLogger, which does not inherit from Logger. (See: rails/rails#48615.) Instead of testing for a specific class, we can test the interface. Co-authored-by: zogoo <ch.tsogbadrakh@gmail.com>

rails-bot bot added the activesupport label Jun 30, 2023

Edouard-chin commented Jun 30, 2023

View reviewed changes

activesupport/lib/active_support.rb Outdated Show resolved Hide resolved

Edouard-chin commented Jun 30, 2023

View reviewed changes

Edouard-chin mentioned this pull request Jun 30, 2023

Tags leak across broadcasted loggers #46084

Open

rails-bot bot added actioncable activejob activerecord railties labels Jul 3, 2023

Edouard-chin force-pushed the ec-logger branch 2 times, most recently from 7fc578f to 77de8a6 Compare July 3, 2023 21:53

Edouard-chin changed the title ~~Refactor tagged logging and add a public API for broadcasting logs~~ Add a public API for broadcasting logs Jul 3, 2023

Edouard-chin force-pushed the ec-logger branch 2 times, most recently from 2f0d5cf to e3fc8f8 Compare July 3, 2023 22:11

Edouard-chin commented Jul 3, 2023

View reviewed changes

Edouard-chin force-pushed the ec-logger branch from e3fc8f8 to e67181a Compare July 4, 2023 14:57

Edouard-chin force-pushed the ec-logger branch from e67181a to fa0c9ed Compare August 1, 2023 18:10

rafaelfranca reviewed Aug 1, 2023

View reviewed changes

Edouard-chin force-pushed the ec-logger branch 3 times, most recently from f2924c6 to cf65083 Compare August 14, 2023 14:32

zzak added this to the 7.1.0 milestone Sep 23, 2023

Edouard-chin force-pushed the ec-logger branch from cf65083 to 54f38bf Compare September 24, 2023 14:10

rafaelfranca force-pushed the ec-logger branch from 54f38bf to 1fbd812 Compare September 25, 2023 20:40

rafaelfranca merged commit 4c72cc2 into rails:main Sep 25, 2023
4 checks passed

bensheldon mentioned this pull request Sep 25, 2023

Use ActiveSupport::BroadcastLogger bensheldon/good_job#1089

Merged

kjellberg mentioned this pull request Sep 26, 2023

Logger.broadcast removed from ActiveSupport causing sidekiq to break sidekiq/sidekiq#6054

Closed

Edouard-chin mentioned this pull request Sep 28, 2023

Fix the BroadcastLogger being initialized too late: #49417

Merged

4 tasks

st0012 mentioned this pull request Oct 1, 2023

Adopt Rails 7.1's new BroadcastLogger getsentry/sentry-ruby#2120

Merged

ohbarye mentioned this pull request Oct 5, 2023

Rails 7.1's new BroadcastLogger causes TypeError in Vonage::Config Vonage/vonage-ruby-sdk#288

Closed

elliterate mentioned this pull request Oct 13, 2023

Test logger interface instead of class saml-idp/saml_idp#194

Closed

Edouard-chin mentioned this pull request Oct 24, 2023

BroadcastLogger#tagged without a block returns an array instead of a logger #49757

Open

ghiculescu mentioned this pull request Dec 11, 2023

ActiveSupport::BroadcastLogger does not respect config.log_level in Rails 7.1 #50324

Closed

Zogoo mentioned this pull request Jan 3, 2024

Test logger interface instead of class saml-idp/saml_idp#200

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add a public API for broadcasting logs #48615

Add a public API for broadcasting logs #48615

Edouard-chin commented Jun 30, 2023 •

edited

Edouard-chin Jun 30, 2023

rafaelfranca Jun 30, 2023

Edouard-chin Jun 30, 2023

rafaelfranca Jun 30, 2023

Edouard-chin commented Jul 3, 2023

Edouard-chin Jul 3, 2023

rafaelfranca Aug 1, 2023

Edouard-chin Aug 3, 2023

rafaelfranca Aug 1, 2023

rafaelfranca Aug 1, 2023

rafaelfranca Aug 1, 2023

rafaelfranca Aug 1, 2023

Edouard-chin Aug 3, 2023

rafaelfranca Aug 3, 2023

zzak commented Sep 23, 2023

Edouard-chin commented Sep 24, 2023 via email

Edouard-chin commented Sep 24, 2023

miharekar commented Sep 28, 2023 •

edited

Edouard-chin commented Sep 28, 2023

Edouard-chin commented Sep 28, 2023

Add a public API for broadcasting logs #48615

Add a public API for broadcasting logs #48615

Conversation

Edouard-chin commented Jun 30, 2023 • edited

Context

Broadcasting

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Edouard-chin commented Jul 3, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

zzak commented Sep 23, 2023

Edouard-chin commented Sep 24, 2023 via email

Edouard-chin commented Sep 24, 2023

miharekar commented Sep 28, 2023 • edited

Edouard-chin commented Sep 28, 2023

Edouard-chin commented Sep 28, 2023

Edouard-chin commented Jun 30, 2023 •

edited

miharekar commented Sep 28, 2023 •

edited