mirrors
/
rails
mirror of https://github.com/rails/rails
8
0
Fork 0
Code Issues Projects Releases Wiki Activity

Logging at info level should be reserved for top-level concerns 

Information about partials and cable connection notices are too low level.
This commit is contained in:
David Heinemeier Hansson 2019-08-25 11:39:58 -07:00 committed by George Claghorn
parent 24f1f822e3
commit 6315a11b90
5 changed files with 48 additions and 35 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
actioncable/CHANGELOG.md
View File

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

4
actioncable/lib/action_cable/channel/base.rb
View File

@ -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]

7
actionview/CHANGELOG.md
View File

@ -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*

6
actionview/lib/action_view/log_subscriber.rb
View File

@ -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

64
actionview/test/template/log_subscriber_test.rb
View File

@ -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