From b6193d3fc797c281cd7cd40ee17dc7691b4f99e0 Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Thu, 1 Oct 2026 18:37:15 +0200 Subject: [PATCH 1/3] Expect real response durations in the request specs logtail-rack 0.2.8 times responses with the monotonic clock, which Timecop doesn't freeze, so "Completed 200 OK in 0.0ms" no longer holds. The last CI run on main still resolved logtail-rack 0.2.7. Co-Authored-By: Claude Opus 5.5 --- spec/logtail-rails/http_events_spec.rb | 4 ++-- spec/logtail-rails/rack_logger_spec.rb | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/spec/logtail-rails/http_events_spec.rb b/spec/logtail-rails/http_events_spec.rb index 2e8bb2a..d185ab9 100755 --- a/spec/logtail-rails/http_events_spec.rb +++ b/spec/logtail-rails/http_events_spec.rb @@ -45,7 +45,7 @@ def method_for_action(action_name) expect(lines[0]).to include("Started GET \\\"/rack_http\\\"") expect(lines[1]).to include("Processing by RackHttpController#index as HTML") - expect(lines[2]).to include("Completed 200 OK in 0.0ms") + expect(lines[2]).to match(/Completed 200 OK in \d+\.\d+ms/) end context "with the route silenced" do @@ -87,7 +87,7 @@ def method_for_action(action_name) expect(lines.length).to eq(2) expect(lines[0]).to include("Processing by RackHttpController#index as HTML") - expect(lines[1]).to include("GET /rack_http completed with 200 OK in 0.0ms") + expect(lines[1]).to match(/GET \/rack_http completed with 200 OK in \d+\.\d+ms/) end end end diff --git a/spec/logtail-rails/rack_logger_spec.rb b/spec/logtail-rails/rack_logger_spec.rb index e3c2109..6976159 100755 --- a/spec/logtail-rails/rack_logger_spec.rb +++ b/spec/logtail-rails/rack_logger_spec.rb @@ -49,7 +49,7 @@ def method_for_action(action_name) expect(lines.length).to eq(3) expect(lines[0]).to include("Started GET \\\"/rails_rack_logger\\\"") expect(lines[1]).to include("Processing by RailsRackLoggerController#index as HTML") - expect(lines[2]).to include("Completed 200 OK in 0.0ms") + expect(lines[2]).to match(/Completed 200 OK in \d+\.\d+ms/) ensure Logtail::Integrations::Rails::EventLogSubscriber.enabled = original_enabled end From e8c607105e681fe44f27ddbf009c239883885ffa Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Thu, 1 Oct 2026 18:37:21 +0200 Subject: [PATCH 2/3] Add failing tests for the leftover "Rendering" listeners on Rails 7.2+ Since Rails 7.1, ActionView::LogSubscriber.attach_to subscribes ActionView::LogSubscriber::Start listeners that log "Rendering ..." at debug level. The integration removes them, but on Rails 7.2 to 8.1 they survive, so every template render logs "Rendering" twice at debug level. Co-Authored-By: Claude Opus 5.5 --- .../action_view/log_subscriber_spec.rb | 30 +++++++++++++++++++ 1 file changed, 30 insertions(+) diff --git a/spec/logtail-rails/action_view/log_subscriber_spec.rb b/spec/logtail-rails/action_view/log_subscriber_spec.rb index 29d0b5e..08b06f0 100755 --- a/spec/logtail-rails/action_view/log_subscriber_spec.rb +++ b/spec/logtail-rails/action_view/log_subscriber_spec.rb @@ -75,6 +75,36 @@ def method_for_action(action_name) end end end + + context "with a debug level" do + around(:each) do |example| + old_level = logger.level + logger.level = ::Logger::DEBUG + example.run + logger.level = old_level + end + + it "should not log the start of the rendering" do + dispatch_rails_request("/action_view_log_subscriber") + expect(io.string.scan("Rendered spec/support/rails/templates/template.html").length).to eq(1) + expect(io.string).not_to include("Rendering") + end + end + end + end + + if defined?(::ActionView::LogSubscriber::Start) + describe "integrate!" do + # Since Rails 7.1, ActionView::LogSubscriber.attach_to subscribes these listeners next to the + # subscriber itself. They log "Rendering ..." at debug level. + it "should remove the listeners logging the start of a rendering" do + notifier = ::ActiveSupport::Notifications.notifier + listeners = %w(render_template.action_view render_layout.action_view).flat_map do |name| + notifier.respond_to?(:all_listeners_for) ? notifier.all_listeners_for(name) : notifier.listeners_for(name) + end + + expect(listeners.map(&:delegate).grep(::ActionView::LogSubscriber::Start)).to be_empty + end end end From 8405f3dd99a4254c436e90bcaddc8b3141ac73fc Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Thu, 1 Oct 2026 18:38:59 +0200 Subject: [PATCH 3/3] Remove the "Rendering" listeners with all_listeners_for on Rails 7.2+ Rails 7.2 made ActionView::LogSubscriber::Start silenceable, and it counts as silenced while ActionView::Base.logger is nil, as it is at boot. listeners_for skips silenced listeners, so the cleanup in attach_to found none and every render logged "Rendering" twice at debug level. Look them up with all_listeners_for where ActiveSupport has it, and collect them with flat_map: all_listeners_for returns the notifier's cached array, which concat would modify. Co-Authored-By: Claude Opus 5.5 --- .../action_view/log_subscriber/logtail_log_subscriber.rb | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/lib/logtail-rails/action_view/log_subscriber/logtail_log_subscriber.rb b/lib/logtail-rails/action_view/log_subscriber/logtail_log_subscriber.rb index 7fb451f..91fedd2 100755 --- a/lib/logtail-rails/action_view/log_subscriber/logtail_log_subscriber.rb +++ b/lib/logtail-rails/action_view/log_subscriber/logtail_log_subscriber.rb @@ -76,9 +76,12 @@ def self.attach_to(*) super if ::Rails::VERSION::MAJOR > 7 || ::Rails::VERSION::MAJOR == 7 && ::Rails::VERSION::MINOR >= 1 - # Clean extra listeners subscribed in parent's attach_to method - ::ActiveSupport::Notifications.notifier.listeners_for("render_template.action_view") - .concat(::ActiveSupport::Notifications.notifier.listeners_for("render_layout.action_view")).flatten + # Clean extra listeners subscribed in parent's attach_to method. Since Rails 7.2 they count as + # silenced while ActionView::Base.logger is nil, as it is at boot, and listeners_for skips those. + # all_listeners_for returns the notifier's cached array, so don't concat onto it. + notifier = ::ActiveSupport::Notifications.notifier + %w(render_template.action_view render_layout.action_view) + .flat_map { |name| notifier.respond_to?(:all_listeners_for) ? notifier.all_listeners_for(name) : notifier.listeners_for(name) } .filter { |listener| listener.delegate.class == ::ActionView::LogSubscriber::Start } .each { |listener| ActiveSupport::Notifications.unsubscribe(listener) } end