Make framework log subscribers to consume structured events #55900

gmcgibbon · 2025-10-14T07:17:56Z

Motivation / Background

This Pull Request has been created because framework log subscribers currently consume notification events. Since the introduction of structured event subscribers in #55690, this doesn't necessarily need to happen anymore. We can instead use the structured event subscribers to produce logs instead for environments like development.

Detail

This Pull Request adds a base class for framework structured event log subscribers, and changes current log subscribers (private API since #55755) to consume structured events instead of notification events.

Checklist

Before submitting the PR make sure the following are checked:

This Pull Request is related to one change. Unrelated changes should be opened in separate PRs.
Commit message has a detailed description of what changed and why. If this PR fixes a related issue include it in the commit message. Ex: [Fix #issue-number]
Tests are added or updated if you fix a bug or add a feature.
CHANGELOG files are updated for the changed libraries if there is a behavior change or additional feature. Minor bug fixes and documentation changes should not be included.

actionview/lib/action_view/railtie.rb

activesupport/CHANGELOG.md

…seful for logging Related to #55900.

rafaelfranca · 2025-10-14T23:40:37Z

Shiped #55904 before this one.

zzak · 2025-10-16T13:08:31Z

activesupport/lib/active_support/log_subscriber.rb

-    CYAN    = "\e[36m"
-    WHITE   = "\e[37m"
-
-    mattr_accessor :colorize_logging, default: true


Isn't this breaking API change?

Since mattr_accessor are not picked up by RDoc, it is not visible in the public API docs however:
https://api.rubyonrails.org/classes/ActiveSupport/LogSubscriber.html

I did find one case of it in the wild, when running rails_semantic_logger tests against this branch:
amazing-print/amazing_print@main...zzak:amazing_print:rails-log-subscribers-colorize_logging

I thought it wasn't because it wasn't visible in docs. I would opt to have private API users update their own code, but I'm open to suggestions. If someone else agrees, we can add deprecations, but I don't think it is necessary.

I thought it wasn't because it wasn't visible in docs.

This is the general rule, yes so I think we're fine. The public API which is documented is through configuration:
https://edgeapi.rubyonrails.org/classes/Rails/Application/Configuration.html#method-i-colorize_logging

But I think that using mattr_* is intentionally meant to be private is false, that is just a side-effect of missing RDoc support.

This breaks Rails projects that use Awesome Print (or its maintained fork Amazing Print):

# lib/amazing_print/ext/active_support.rb if defined?(ActiveSupport::LogSubscriber) AwesomePrint.force_colors! ActiveSupport::LogSubscriber.colorize_logging end

Source: https://github.com/awesome-print/awesome_print/blob/8a7ff0aabacbebf694c3e27242809219a96d5a3b/lib/awesome_print/ext/active_support.rb#L44-L46

While using the public ActiveSupport.colorize_logging API can be a quick fix for Amazing Print (the maintainers are pretty responsive), Awesome Print has been stale for years and many projects probably still depend on it (my current company does). So upgrading to Rails 8.2+ would mean requiring some companies to switch to amazing_print.

I understand this is possibly a private API, although there may be some ambiguity, and it is used by a few OSS projects according to https://sourcegraph.com/search?q=context:global+%22ActiveSupport::LogSubscriber.colorize_logging%22&patternType=keyword&sm=0. Not that many overall, but notables ones are awesome print, amazing print, a profiler class in the main Gitlab repo, a spec helper in https://github.com/rsim/oracle-enhanced, and a few other projects with 100+ github stars.

So I am wondering if the change is fine as is, or if this warrants a deprecation, a mention in the upgrade guides, or another course of action.

One last thing, it's not just external gems, but https://github.com/rails/kredis also uses ActiveSupport::LogSubscriber.colorize_logging in one of its tests:

https://github.com/rails/kredis/blob/a6643a0b4cfa6512159d0a98638ba20401da917d/test/log_subscriber_test.rb#L12

zzak · 2025-10-16T13:45:36Z

Tried this branch with rails_semantic_logger tests and it seems they will have to change how they swap out subscribers, like:
reidmorrison/rails_semantic_logger@master...zzak:rails_semantic_logger:swap-structured_event_subscribers

If you unsubscribe from these do other things break, either intentionally or unintentionally. 🤔

Lograge also does something like this:
https://github.com/roidrage/lograge/blob/27066cd75d449cb91ed79b18c4271d62a76c9839/lib/lograge.rb#L109-L127

Not sure how actionable it is, just came to me when thinking about this and thought it might be valuable context. 🙏

gmcgibbon · 2025-10-16T20:49:38Z

rails/actionview/lib/action_view/log_subscriber.rb

Line 6 in 844fe07

class LogSubscriber < ActiveSupport::LogSubscriber # :nodoc:

Most log subscribers are nodoc. I made all log subscribers nodoc in #55755, and if that is released in 8.1, and this in 8.2, that should be sufficient IMO.

gmcgibbon · 2025-10-16T21:55:54Z

I'll backport the more recent structured logging additions here to 8.1 stable so that we can include that in the full release (or another RC). Looks like the pressure is off to get this out before 8.1, and its a pretty big change, so I'll leave it open for a few more days for feedback.

Related to rails#55900.

activesupport/lib/active_support/event_reporter/log_subscriber.rb

Introduce base class for structured event logging. Because so much of the logic is copied from the original log subscriber, this also introduced ActiveSupport::ColorizeLogging that may be used to log in color.

chaadow · 2025-10-23T18:29:17Z

activesupport/lib/active_support/event_reporter/log_subscriber.rb

+
+module ActiveSupport
+  class EventReporter
+    class LogSubscriber


Since there is a CHANGELOG entry for this class, should we add some rdoc documentation?

Yes, I'll put this on my TODO list, but PRs are welcome in the meantime!

p-schlickmann · 2025-10-24T16:08:26Z

@gmcgibbon @rafaelfranca can you advise how this change could have broken two tests from SolidQueue which depend on ActiveSupport::Logger?

I have confirmed it's because of this PR, I just don't understand why, yet.

https://github.com/rails/solid_queue/blob/main/test/unit/worker_test.rb#L105-L115

https://github.com/rails/solid_queue/blob/main/test/unit/dispatcher_test.rb#L39-L49

claudiob · 2025-10-25T00:49:00Z

Hello everyone! I noticed something changed in my Rails app and I was able to pinpoint to this commit.
When a Rails app runs with RAILS_LOG_LEVEL=debug RAILS_ENV=production, then the Rails log:

before this PR: includes the SQL statements and the rendered partials
after this PR: does not

Is this expected? Here is the full log:

Before this PR (for instance pointing to the previous commit `9834097`):

git:main~/code/houston$ RAILS_LOG_LEVEL=debug RAILS_ENV=production rv
=> Booting Puma
=> Rails 8.2.0.alpha application starting in production 
=> Run `bin/rails server --help` for more startup options
Generating image variants require the image_processing gem. Please add `gem "image_processing", "~> 1.2"` to your Gemfile or set `config.active_storage.variant_processor = :disabled`.
Puma starting in single mode...
* Puma version: 7.1.0 ("Neon Witch")
* Ruby version: ruby 3.4.5 (2025-07-16 revision 20cda200d3) +PRISM [arm64-darwin23]
*  Min threads: 3
*  Max threads: 3
*  Environment: production
*          PID: 48978
* Listening on http://0.0.0.0:9876
Use Ctrl-C to stop
[90852500-b950-449a-aac4-90f040b4bcf8] Started GET "/zips" for 127.0.0.1 at 2025-10-24 17:44:53 -0700
[90852500-b950-449a-aac4-90f040b4bcf8] Processing by Administered::ZipsController#index as HTML
[90852500-b950-449a-aac4-90f040b4bcf8]   Agent Load (2.4ms)  SELECT "agents".* FROM "agents" ORDER BY "agents"."id" ASC LIMIT $1  [["LIMIT", 1]]
[90852500-b950-449a-aac4-90f040b4bcf8]   Zip Count (7.0ms)  SELECT COUNT(*) FROM "zips"
[90852500-b950-449a-aac4-90f040b4bcf8]   Rendering layout layouts/application.html.erb
[90852500-b950-449a-aac4-90f040b4bcf8]   Rendering administered/zips/index.html.erb within layouts/application
[90852500-b950-449a-aac4-90f040b4bcf8]   Zip Load (1.2ms)  SELECT "zips".* FROM "zips" ORDER BY "zips"."code" ASC LIMIT $1 OFFSET $2  [["LIMIT", 20], ["OFFSET", 0]]
[90852500-b950-449a-aac4-90f040b4bcf8]   County Load (1.8ms)  SELECT "counties".* FROM "counties" WHERE "counties"."id" IN ($1, $2, $3, $4)  [["id", 1883], ["id", 1227], ["id", 1228], ["id", 1234]]
[90852500-b950-449a-aac4-90f040b4bcf8]   State Load (1.3ms)  SELECT "states".* FROM "states" WHERE "states"."id" IN ($1, $2)  [["id", 22], ["id", 33]]
[90852500-b950-449a-aac4-90f040b4bcf8]   Rendered application/_table.html.erb (Duration: 48.7ms | GC: 2.0ms)
[90852500-b950-449a-aac4-90f040b4bcf8]   Rendered administered/zips/index.html.erb within layouts/application (Duration: 51.5ms | GC: 2.7ms)
[90852500-b950-449a-aac4-90f040b4bcf8]   Rendered layout layouts/application.html.erb (Duration: 61.2ms | GC: 2.7ms)
[90852500-b950-449a-aac4-90f040b4bcf8] Completed 200 OK in 126ms (Views: 49.7ms | ActiveRecord: 45.6ms (5 queries, 0 cached) | GC: 4.1ms)

After this PR:

git:main~/code/houston$ RAILS_LOG_LEVEL=debug RAILS_ENV=production rv
=> Booting Puma
=> Rails 8.2.0.alpha application starting in production 
=> Run `bin/rails server --help` for more startup options
Generating image variants require the image_processing gem. Please add `gem "image_processing", "~> 1.2"` to your Gemfile or set `config.active_storage.variant_processor = :disabled`.
Puma starting in single mode...
* Puma version: 7.1.0 ("Neon Witch")
* Ruby version: ruby 3.4.5 (2025-07-16 revision 20cda200d3) +PRISM [arm64-darwin23]
*  Min threads: 3
*  Max threads: 3
*  Environment: production
*          PID: 49151
* Listening on http://0.0.0.0:9876
Use Ctrl-C to stop
[31cdf92d-9c7b-49ea-8758-c8b8ce205dec] Started GET "/zips" for 127.0.0.1 at 2025-10-24 17:47:46 -0700
[31cdf92d-9c7b-49ea-8758-c8b8ce205dec] Processing by Administered::ZipsController#index as HTML
[31cdf92d-9c7b-49ea-8758-c8b8ce205dec] Completed 200 OK in 138ms (Views: 65.4ms | ActiveRecord: 47.4ms (5 queries, 0 cached) | GC: 17.0ms)

skarlcf · 2025-10-26T10:43:36Z

He everyone,
I've noticed some issues with Active Support Event Reporter after this PR merge.

To describe issue, I will use examples from official documentation: https://edgeapi.rubyonrails.org/classes/ActiveSupport/EventReporter.html

Before this PR merge:

# Gemfile
gem "rails", github: "rails/rails", ref: "14ffa17"

# Terminal
$ bin/rails c
Loading development environment (Rails 8.2.0.alpha)
Type 'help' for help.
api(dev):001> Rails.event.notify("user_created", { id: nil })
=> nil
api(dev):002> Rails.event.notify("user.created", { id: nil })
=> nil
api(dev):003* class UserCreatedEvent
api(dev):004*   def initialize(id:, name:)
api(dev):005*     @id = id
api(dev):006*     @name = name
api(dev):007*   end
api(dev):008* 
api(dev):009*   def serialize
api(dev):010*     {
api(dev):011*       id: @id,
api(dev):012*       name: @name
api(dev):013*     }
api(dev):014*   end
api(dev):015> end
=> :serialize
api(dev):016> Rails.event.notify(UserCreatedEvent.new(id: 123, name: "John Doe"))
=> nil
api(dev):017> Rails.event
=> 
#<ActiveSupport::EventReporter:0x00007fe97e766460
 @debug_mode=true,
 @payload_filter=
  #<ActiveSupport::ParameterFilter:0x00007fe97c3480b0
   @blocks=nil,
   @deep_regexps=nil,
   @mask="[FILTERED]",
   @no_filters=false,
   @regexps=[/passw|email|secret|token|_key|crypt|salt|certificate|otp|ssn|cvv|cvc/i]>,
 @raise_on_error=true,
 @subscribers=[]>
api(dev):018>

After PR merge:

# Gemfile
gem "rails", github: "rails/rails", ref: "66e027d9649f48f63513e1c6836b12bb96f50320"

# Terminal
$ bin/rails c
Loading development environment (Rails 8.2.0.alpha)
Type 'help' for help.
api(dev):001> Rails.event.notify("user_created", { id: nil })
(api):1:in '<main>': no implicit conversion from nil to integer (TypeError)

            event_namespace = name[0, name.index(".")]
                                   ^^^^^^^^^^^^^^^^^^
api(dev):002> Rails.event.notify("user.created", { id: nil })
=> nil
api(dev):003* class UserCreatedEvent
api(dev):004*   def initialize(id:, name:)
api(dev):005*     @id = id
api(dev):006*     @name = name
api(dev):007*   end
api(dev):008* 
api(dev):009*   def serialize
api(dev):010*     {
api(dev):011*       id: @id,
api(dev):012*       name: @name
api(dev):013*     }
api(dev):014*   end
api(dev):015> end
=> :serialize
api(dev):016> Rails.event.notify(UserCreatedEvent.new(id: 123, name: "John Doe"))
(api):16:in '<main>': no implicit conversion from nil to integer (TypeError)

            event_namespace = name[0, name.index(".")]
                                   ^^^^^^^^^^^^^^^^^^
api(dev):017> Rails.event
=> 
#<ActiveSupport::EventReporter:0x00007fe6ec7a66f8
 @debug_mode=true,
 @payload_filter=
  #<ActiveSupport::ParameterFilter:0x00007fe6ea3a2d38
   @blocks=nil,
   @deep_regexps=nil,
   @mask="[FILTERED]",
   @no_filters=false,
   @regexps=[/passw|email|secret|token|_key|crypt|salt|certificate|otp|ssn|cvv|cvc/i]>,
 @raise_on_error=true,
 @subscribers=
  [{subscriber: #<ActionDispatch::LogSubscriber:0x00007fe6ecafc118>,
    filter:
     #<Proc:0x00007fe6ecafc000 /home/kamil/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/bundler/gems/rails-66e027d9649f/activesupport/lib/active_support/event_reporter/log_subscriber.rb:32>},
   {subscriber: #<ActiveStorage::LogSubscriber:0x00007fe6ebd8f7c8>,
    filter:
     #<Proc:0x00007fe6ebd8f6b0 /home/kamil/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/bundler/gems/rails-66e027d9649f/activesupport/lib/active_support/event_reporter/log_subscriber.rb:32>},
   {subscriber: #<ActiveRecord::LogSubscriber:0x00007fe6ea6ed740>,
    filter:
     #<Proc:0x00007fe6ea6ed5d8 /home/kamil/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/bundler/gems/rails-66e027d9649f/activesupport/lib/active_support/event_reporter/log_subscriber.rb:32>}]>
api(dev):018>

There is no info in RDoc that event name must have a dot ".".

zzak · 2025-10-26T12:16:41Z

@claudiob Ahh yeah, because those events are set to debug only mode, which is false in production:

rails/railties/lib/rails/application/bootstrap.rb

Line 76 in 66e027d

Rails.event.debug_mode = Rails.env.development?

@skarlcf @p-schlickmann It's not mandatory, but probably would be better to open a bug to track these so we're not trampling over each other on this thread.

gmcgibbon · 2025-10-27T08:09:42Z

Ah, sorry the . problem I will fix. As for the debug mode problem, we might have to change the logging criteria on some events. I'll look into that.

rails-bot bot added actionmailer actionpack actionview activejob activerecord activestorage activesupport labels Oct 14, 2025

gmcgibbon force-pushed the new_log_subscribers branch from d1d2f2e to 1bec302 Compare October 14, 2025 16:27

rafaelfranca reviewed Oct 14, 2025

View reviewed changes

actionview/lib/action_view/railtie.rb Outdated Show resolved Hide resolved

activesupport/CHANGELOG.md Outdated Show resolved Hide resolved

rafaelfranca added this to the 8.1.0 milestone Oct 14, 2025

gmcgibbon force-pushed the new_log_subscribers branch 2 times, most recently from 609b1f4 to 8b810c8 Compare October 14, 2025 22:24

rafaelfranca approved these changes Oct 14, 2025

View reviewed changes

rafaelfranca added a commit that referenced this pull request Oct 14, 2025

Make the Structured Event Subscriber emit events in format that are u…

d6f9f62

…seful for logging Related to #55900.

rafaelfranca mentioned this pull request Oct 14, 2025

Make the Structured Event Subscriber emit events in format that are useful for logging #55904

Merged

rafaelfranca modified the milestones: 8.1.0, 8.2.0 Oct 14, 2025

gmcgibbon force-pushed the new_log_subscribers branch 8 times, most recently from cecbd80 to 3493a2b Compare October 16, 2025 07:24

zzak reviewed Oct 16, 2025

View reviewed changes

gmcgibbon force-pushed the new_log_subscribers branch from 3493a2b to 2117e11 Compare October 16, 2025 20:40

gmcgibbon added a commit to Shopify/rails that referenced this pull request Oct 16, 2025

Add missing structured event data for logs

ef146a5

Related to rails#55900.

gmcgibbon mentioned this pull request Oct 16, 2025

Add missing structured event data for logs #55922

Merged

byroot reviewed Oct 18, 2025

View reviewed changes

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

gmcgibbon force-pushed the new_log_subscribers branch 2 times, most recently from 5b73cee to 4f9b7d3 Compare October 22, 2025 04:10

github-actions bot added the railties label Oct 22, 2025

gmcgibbon force-pushed the new_log_subscribers branch from 4f9b7d3 to b601abc Compare October 22, 2025 04:21

byroot reviewed Oct 22, 2025

View reviewed changes

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

gmcgibbon force-pushed the new_log_subscribers branch from b601abc to d8977f2 Compare October 22, 2025 16:19

gmcgibbon added 7 commits October 22, 2025 11:28

Introduce ActiveSupport::EventReporter::LogSubscriber

aebcb61

Introduce base class for structured event logging. Because so much of the logic is copied from the original log subscriber, this also introduced ActiveSupport::ColorizeLogging that may be used to log in color.

Convert log subscriber in Active Job to consume structured events

dbc3a5d

Convert log subscribers in Action Pack to consume structured events

4a4aae7

Convert log subscriber in Action View to consume structured events

46b8605

Convert log subscriber in Active Record to consume structured events

308594b

Convert log subscriber in Action Mailer to consume structured events

8df8755

Convert log subscriber in Active Storage to consume structured events

b646f35

gmcgibbon force-pushed the new_log_subscribers branch from d8977f2 to b646f35 Compare October 22, 2025 16:29

gmcgibbon merged commit 54264bd into rails:main Oct 23, 2025
4 checks passed

gmcgibbon deleted the new_log_subscribers branch October 23, 2025 16:07

chaadow reviewed Oct 23, 2025

View reviewed changes

faraquet mentioned this pull request Oct 26, 2025

Fix broken rails_main tests rails/solid_queue#667

Open

gmcgibbon mentioned this pull request Oct 27, 2025

Fix event reporter log subscriber consuming events without namespaces #56013

Merged

4 tasks

bquorning mentioned this pull request Oct 27, 2025

Test using Docker and TestContainers zendesk/active_record_host_pool#175

Merged

Uh oh!

Make framework log subscribers to consume structured events #55900

Make framework log subscribers to consume structured events #55900

Conversation

gmcgibbon commented Oct 14, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Motivation / Background

Detail

Checklist

Uh oh!

Uh oh!

Uh oh!

rafaelfranca commented Oct 14, 2025

Uh oh!

zzak Oct 16, 2025

Choose a reason for hiding this comment

Uh oh!

gmcgibbon Oct 16, 2025

Choose a reason for hiding this comment

Uh oh!

zzak Oct 17, 2025

Choose a reason for hiding this comment

Uh oh!

jeromedalbert Oct 24, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jeromedalbert Oct 24, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

zzak commented Oct 16, 2025

Uh oh!

gmcgibbon commented Oct 16, 2025

Uh oh!

gmcgibbon commented Oct 16, 2025

Uh oh!

Uh oh!

Uh oh!

Uh oh!

chaadow Oct 23, 2025

Choose a reason for hiding this comment

Uh oh!

gmcgibbon Oct 23, 2025

Choose a reason for hiding this comment

Uh oh!

p-schlickmann commented Oct 24, 2025

Uh oh!

claudiob commented Oct 25, 2025

Before this PR (for instance pointing to the previous commit 9834097):

After this PR:

Uh oh!

skarlcf commented Oct 26, 2025

Uh oh!

zzak commented Oct 26, 2025

Uh oh!

gmcgibbon commented Oct 27, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

9 participants

gmcgibbon commented Oct 14, 2025 •

edited

Loading

jeromedalbert Oct 24, 2025 •

edited

Loading

jeromedalbert Oct 24, 2025 •

edited

Loading

Before this PR (for instance pointing to the previous commit `9834097`):