Skip to content
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

ActionView logs not completely suppressed with Rails 7.1+ #385

Open
owst opened this issue Jan 24, 2024 · 0 comments · May be fixed by #386
Open

ActionView logs not completely suppressed with Rails 7.1+ #385

owst opened this issue Jan 24, 2024 · 0 comments · May be fixed by #386

Comments

@owst
Copy link

owst commented Jan 24, 2024

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:
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.

owst added a commit to owst/lograge that referenced this issue Jan 24, 2024
Fixes roidrage#385

Assumes that a built-in subscriber is nested under the component
namespace, so under ActionView or ActionController.
@owst owst linked a pull request Jan 24, 2024 that will close this issue
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant