From 6315a11b90727de782891f51b12951612abb66bd Mon Sep 17 00:00:00 2001 From: David Heinemeier Hansson Date: Sun, 25 Aug 2019 11:39:58 -0700 Subject: [PATCH] Logging at info level should be reserved for top-level concerns Information about partials and cable connection notices are too low level. --- actioncable/CHANGELOG.md | 2 + actioncable/lib/action_cable/channel/base.rb | 4 +- actionview/CHANGELOG.md | 7 ++ actionview/lib/action_view/log_subscriber.rb | 6 +- .../test/template/log_subscriber_test.rb | 64 ++++++++++--------- 5 files changed, 48 insertions(+), 35 deletions(-) diff --git a/actioncable/CHANGELOG.md b/actioncable/CHANGELOG.md index 6fc2f17d32..33a53164f5 100644 --- a/actioncable/CHANGELOG.md +++ b/actioncable/CHANGELOG.md @@ -1,3 +1,5 @@ +* Subscription confirmations and rejections are now logged at the `DEBUG` level instead of `INFO`. + *DHH* Please check [6-0-stable](https://github.com/rails/rails/blob/6-0-stable/actioncable/CHANGELOG.md) for previous changes. diff --git a/actioncable/lib/action_cable/channel/base.rb b/actioncable/lib/action_cable/channel/base.rb index af061c843a..83ef2c7eaf 100644 --- a/actioncable/lib/action_cable/channel/base.rb +++ b/actioncable/lib/action_cable/channel/base.rb @@ -283,7 +283,7 @@ module ActionCable def transmit_subscription_confirmation unless subscription_confirmation_sent? - logger.info "#{self.class.name} is transmitting the subscription confirmation" + logger.debug "#{self.class.name} is transmitting the subscription confirmation" ActiveSupport::Notifications.instrument("transmit_subscription_confirmation.action_cable", channel_class: self.class.name) do connection.transmit identifier: @identifier, type: ActionCable::INTERNAL[:message_types][:confirmation] @@ -298,7 +298,7 @@ module ActionCable end def transmit_subscription_rejection - logger.info "#{self.class.name} is transmitting the subscription rejection" + logger.debug "#{self.class.name} is transmitting the subscription rejection" ActiveSupport::Notifications.instrument("transmit_subscription_rejection.action_cable", channel_class: self.class.name) do connection.transmit identifier: @identifier, type: ActionCable::INTERNAL[:message_types][:rejection] diff --git a/actionview/CHANGELOG.md b/actionview/CHANGELOG.md index 71a8b3fdcb..de5478968d 100644 --- a/actionview/CHANGELOG.md +++ b/actionview/CHANGELOG.md @@ -1,3 +1,10 @@ +* Log lines for partial renders and started template renders are now + emitted at the `DEBUG` level instead of `INFO`. + + Completed template renders are still logged at the `INFO` level. + + *DHH* + * ActionView::Helpers::SanitizeHelper: support rails-html-sanitizer 1.1.0. *Juanito Fatas* diff --git a/actionview/lib/action_view/log_subscriber.rb b/actionview/lib/action_view/log_subscriber.rb index 02ac0ce477..2ce502ba9b 100644 --- a/actionview/lib/action_view/log_subscriber.rb +++ b/actionview/lib/action_view/log_subscriber.rb @@ -23,7 +23,7 @@ module ActionView end def render_partial(event) - info do + debug do message = +" Rendered #{from_rails_root(event.payload[:identifier])}" message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout] message << " (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})" @@ -35,7 +35,7 @@ module ActionView def render_collection(event) identifier = event.payload[:identifier] || "templates" - info do + debug do " Rendered collection of #{from_rails_root(identifier)}" \ " #{render_count(event.payload)} (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})" end @@ -83,7 +83,7 @@ module ActionView end def log_rendering_start(payload) - info do + debug do message = +" Rendering #{from_rails_root(payload[:identifier])}" message << " within #{from_rails_root(payload[:layout])}" if payload[:layout] message diff --git a/actionview/test/template/log_subscriber_test.rb b/actionview/test/template/log_subscriber_test.rb index 8b160a7336..a2ed1f100c 100644 --- a/actionview/test/template/log_subscriber_test.rb +++ b/actionview/test/template/log_subscriber_test.rb @@ -56,8 +56,9 @@ class AVLogSubscriberTest < ActiveSupport::TestCase @view.render(template: "test/hello_world") wait - assert_equal 2, @logger.logged(:info).size - assert_match(/Rendering test\/hello_world\.erb/, @logger.logged(:info).first) + assert_equal 1, @logger.logged(:debug).size + assert_equal 1, @logger.logged(:info).size + assert_match(/Rendering test\/hello_world\.erb/, @logger.logged(:debug).last) assert_match(/Rendered test\/hello_world\.erb/, @logger.logged(:info).last) end end @@ -67,8 +68,9 @@ class AVLogSubscriberTest < ActiveSupport::TestCase @view.render(file: "#{FIXTURE_LOAD_PATH}/test/hello_world.erb") wait - assert_equal 2, @logger.logged(:info).size - assert_match(/Rendering test\/hello_world\.erb/, @logger.logged(:info).first) + assert_equal 1, @logger.logged(:debug).size + assert_equal 1, @logger.logged(:info).size + assert_match(/Rendering test\/hello_world\.erb/, @logger.logged(:debug).last) assert_match(/Rendered test\/hello_world\.erb/, @logger.logged(:info).last) end end @@ -78,8 +80,9 @@ class AVLogSubscriberTest < ActiveSupport::TestCase @view.render(plain: "TEXT") wait - assert_equal 2, @logger.logged(:info).size - assert_match(/Rendering text template/, @logger.logged(:info).first) + assert_equal 1, @logger.logged(:debug).size + assert_equal 1, @logger.logged(:info).size + assert_match(/Rendering text template/, @logger.logged(:debug).last) assert_match(/Rendered text template/, @logger.logged(:info).last) end end @@ -89,8 +92,9 @@ class AVLogSubscriberTest < ActiveSupport::TestCase @view.render(inline: "<%= 'TEXT' %>") wait - assert_equal 2, @logger.logged(:info).size - assert_match(/Rendering inline template/, @logger.logged(:info).first) + assert_equal 1, @logger.logged(:debug).size + assert_equal 1, @logger.logged(:info).size + assert_match(/Rendering inline template/, @logger.logged(:debug).last) assert_match(/Rendered inline template/, @logger.logged(:info).last) end end @@ -100,8 +104,8 @@ class AVLogSubscriberTest < ActiveSupport::TestCase @view.render(Customer.new("david"), greeting: "hi") wait - assert_equal 1, @logger.logged(:info).size - assert_match(/Rendered customers\/_customer\.html\.erb/, @logger.logged(:info).last) + assert_equal 1, @logger.logged(:debug).size + assert_match(/Rendered customers\/_customer\.html\.erb/, @logger.logged(:debug).last) end end @@ -113,8 +117,8 @@ class AVLogSubscriberTest < ActiveSupport::TestCase @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("david") }) wait - assert_equal 1, @logger.logged(:info).size - assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:info).last) + assert_equal 1, @logger.logged(:debug).size + assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:debug).last) end end @@ -128,8 +132,8 @@ class AVLogSubscriberTest < ActiveSupport::TestCase @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("david") }) wait - assert_equal 2, @logger.logged(:info).size - assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, @logger.logged(:info).last) + assert_equal 2, @logger.logged(:debug).size + assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, @logger.logged(:debug).last) end end @@ -140,14 +144,14 @@ class AVLogSubscriberTest < ActiveSupport::TestCase @view.render(partial: "test/nested_cached_customer", locals: { cached_customer: Customer.new("Stan") }) wait - *, cached_inner, uncached_outer = @logger.logged(:info) + *, cached_inner, uncached_outer = @logger.logged(:debug) assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, cached_inner) assert_match(/Rendered test\/_nested_cached_customer\.erb \(Duration: .*?ms \| Allocations: .*?\)$/, uncached_outer) # Second render hits the cache for the _cached_customer partial. Outer template's log shouldn't be affected. @view.render(partial: "test/nested_cached_customer", locals: { cached_customer: Customer.new("Stan") }) wait - *, cached_inner, uncached_outer = @logger.logged(:info) + *, cached_inner, uncached_outer = @logger.logged(:debug) assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, cached_inner) assert_match(/Rendered test\/_nested_cached_customer\.erb \(Duration: .*?ms \| Allocations: .*?\)$/, uncached_outer) end @@ -160,16 +164,16 @@ class AVLogSubscriberTest < ActiveSupport::TestCase @view.render(partial: "test/cached_nested_cached_customer", locals: { cached_customer: Customer.new("Stan") }) wait - *, cached_inner, cached_outer = @logger.logged(:info) + *, cached_inner, cached_outer = @logger.logged(:debug) assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, cached_inner) assert_match(/Rendered test\/_cached_nested_cached_customer\.erb (.*) \[cache miss\]/, cached_outer) # One render: inner partial skipped, because the outer has been cached. - assert_difference -> { @logger.logged(:info).size }, +1 do + assert_difference -> { @logger.logged(:debug).size }, +1 do @view.render(partial: "test/cached_nested_cached_customer", locals: { cached_customer: Customer.new("Stan") }) wait end - assert_match(/Rendered test\/_cached_nested_cached_customer\.erb (.*) \[cache hit\]/, @logger.logged(:info).last) + assert_match(/Rendered test\/_cached_nested_cached_customer\.erb (.*) \[cache hit\]/, @logger.logged(:debug).last) end end @@ -180,15 +184,15 @@ class AVLogSubscriberTest < ActiveSupport::TestCase @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("david") }) wait - assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:info).last) + assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:debug).last) @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("david") }) wait - assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, @logger.logged(:info).last) + assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, @logger.logged(:debug).last) @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("Stan") }) wait - assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:info).last) + assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:debug).last) end end @@ -197,8 +201,8 @@ class AVLogSubscriberTest < ActiveSupport::TestCase @view.render(partial: "test/customer", collection: [ Customer.new("david"), Customer.new("mary") ]) wait - assert_equal 1, @logger.logged(:info).size - assert_match(/Rendered collection of test\/_customer.erb \[2 times\]/, @logger.logged(:info).last) + assert_equal 1, @logger.logged(:debug).size + assert_match(/Rendered collection of test\/_customer.erb \[2 times\]/, @logger.logged(:debug).last) end end @@ -207,8 +211,8 @@ class AVLogSubscriberTest < ActiveSupport::TestCase @view.render([ Customer.new("david"), Customer.new("mary") ], greeting: "hi") wait - assert_equal 1, @logger.logged(:info).size - assert_match(/Rendered collection of customers\/_customer\.html\.erb \[2 times\]/, @logger.logged(:info).last) + assert_equal 1, @logger.logged(:debug).size + assert_match(/Rendered collection of customers\/_customer\.html\.erb \[2 times\]/, @logger.logged(:debug).last) end end @@ -217,8 +221,8 @@ class AVLogSubscriberTest < ActiveSupport::TestCase @view.render([ GoodCustomer.new("david"), Customer.new("mary") ], greeting: "hi") wait - assert_equal 1, @logger.logged(:info).size - assert_match(/Rendered collection of templates/, @logger.logged(:info).last) + assert_equal 1, @logger.logged(:debug).size + assert_match(/Rendered collection of templates/, @logger.logged(:debug).last) end end @@ -230,8 +234,8 @@ class AVLogSubscriberTest < ActiveSupport::TestCase locals: { greeting: "hi" }) wait - assert_equal 1, @logger.logged(:info).size - assert_match(/Rendered collection of customers\/_customer\.html\.erb \[0 \/ 2 cache hits\]/, @logger.logged(:info).last) + assert_equal 1, @logger.logged(:debug).size + assert_match(/Rendered collection of customers\/_customer\.html\.erb \[0 \/ 2 cache hits\]/, @logger.logged(:debug).last) end end end