ActionView logs not completely suppressed with Rails 7.1+

[owst]

Background

After this Rails change rails/rails@9c58a54 (included in 7.1+) some ActionView::LogSubscriber-generated logs have been split out into a separate ActionView::LogSubscriber::Start subscriber. Unfortunately, this breaks lograge's unsubscription code invoked here:

lograge/lib/lograge.rb

Lines 112 to 113 in 2839d2c

	when ActionView::LogSubscriber
	unsubscribe(:action_view, subscriber)

specifically this line:

lograge/lib/lograge.rb

Line 124 in 2839d2c

ActiveSupport::Notifications.unsubscribe listener if listener.instance_variable_get('@delegate') == subscriber

since the condition is now false for the built-in Start subscriber, as the delegate is not equal to subscriber - it's an instance of ActionView::LogSubscriber::Start not ActionView::LogSubscriber. I assume this code is trying to only unsubscribe Rails' builtin log subscriber and not anything else that happens to be subscribed to the same event.

This has the effect of not silencing logs that were silenced in Rails 7.0.

Reproduction

Copy the following to repro.rb - it defines a minimal Rails app inline:

require 'bundler/inline'

gemfile(true) do
  source 'https://rubygems.org'

  gem 'rails', '~> 7.0.8'
  gem 'puma'
  gem 'lograge'
end

require 'action_controller/railtie'
require 'logger'

Rails.logger = Logger.new(STDOUT)

class App < ::Rails::Application
  config.eager_load = false
  config.lograge.enabled = true

  routes.append do
    root to: 'root#index'
  end
end

class RootController < ActionController::Base
  def index
    render plain: Rails.version
  end
end

App.initialize!

Rack::Server.start(app: App)

If we run ruby repro.rb and then curl the listening address (for me, curl http://0.0.0.0:9292) I see these logs with Rails 7.0.8:

I, [2024-01-24T20:44:02.287069 #47669]  INFO -- : method=GET path=/ format=*/* controller=RootController action=index status=200 allocations=1327 duration=1.25 view=1.20

whereas if I change 7.0.8 to 7.1.3 and follow the same process, I see these logs:

D, [2024-01-24T20:44:44.011525 #47740] DEBUG -- :   Rendering text template
I, [2024-01-24T20:44:44.011663 #47740]  INFO -- : method=GET path=/ format=*/* controller=RootController action=index status=200 allocations=2003 duration=2.32 view=2.27

N.B. the additional debug logging.

[januszm]

For now a quick solution is to avoid using debug log level (it seems to work fine with INFO).