95b6fbd00f
It's possible since Rails 6 (3ea2857943dc294d7809930b4cc5b318b9c39577) to let the framework create Event objects, but the guides and docs weren't updated to lead with this example. Manually instantiating an Event doesn't record CPU time and allocations, I've seen it more than once that people copy-pasting the example code get confused about these stats returning 0. The tests here show that - just like the apps I've worked on - the old pattern keeps getting copy-pasted.
540 lines
16 KiB
Ruby
540 lines
16 KiB
Ruby
# frozen_string_literal: true
|
|
|
|
require_relative "abstract_unit"
|
|
require "active_support/core_ext/module/delegation"
|
|
|
|
module Notifications
|
|
class TestCase < ActiveSupport::TestCase
|
|
def setup
|
|
@old_notifier = ActiveSupport::Notifications.notifier
|
|
@notifier = ActiveSupport::Notifications::Fanout.new
|
|
ActiveSupport::Notifications.notifier = @notifier
|
|
@events = []
|
|
@named_events = []
|
|
@subscription = @notifier.subscribe { |*args| @events << event(*args) }
|
|
@named_subscription = @notifier.subscribe("named.subscription") { |*args| @named_events << event(*args) }
|
|
end
|
|
|
|
def teardown
|
|
ActiveSupport::Notifications.notifier = @old_notifier
|
|
end
|
|
|
|
private
|
|
def event(*args)
|
|
ActiveSupport::Notifications::Event.new(*args)
|
|
end
|
|
end
|
|
|
|
class SubscribeEventObjectsTest < TestCase
|
|
def test_subscribe_events
|
|
events = []
|
|
@notifier.subscribe do |event|
|
|
events << event
|
|
end
|
|
|
|
ActiveSupport::Notifications.instrument("foo")
|
|
event = events.first
|
|
assert event, "should have an event"
|
|
assert_operator event.allocations, :>, 0
|
|
assert_operator event.cpu_time, :>, 0
|
|
assert_operator event.idle_time, :>=, 0
|
|
assert_operator event.duration, :>, 0
|
|
end
|
|
|
|
def test_subscribe_to_events_where_payload_is_changed_during_instrumentation
|
|
@notifier.subscribe do |event|
|
|
assert_equal "success!", event.payload[:my_key]
|
|
end
|
|
|
|
ActiveSupport::Notifications.instrument("foo") do |payload|
|
|
payload[:my_key] = "success!"
|
|
end
|
|
end
|
|
|
|
def test_subscribe_to_events_can_handle_nested_hashes_in_the_paylaod
|
|
@notifier.subscribe do |event|
|
|
assert_equal "success!", event.payload[:some_key][:key_one]
|
|
assert_equal "great_success!", event.payload[:some_key][:key_two]
|
|
end
|
|
|
|
ActiveSupport::Notifications.instrument("foo", some_key: { key_one: "success!" }) do |payload|
|
|
payload[:some_key][:key_two] = "great_success!"
|
|
end
|
|
end
|
|
|
|
def test_subscribe_via_top_level_api
|
|
old_notifier = ActiveSupport::Notifications.notifier
|
|
ActiveSupport::Notifications.notifier = ActiveSupport::Notifications::Fanout.new
|
|
|
|
event = nil
|
|
ActiveSupport::Notifications.subscribe("foo") do |e|
|
|
event = e
|
|
end
|
|
|
|
ActiveSupport::Notifications.instrument("foo") do
|
|
100.times { Object.new } # allocate at least 100 objects
|
|
end
|
|
|
|
assert event
|
|
assert_operator event.allocations, :>=, 100
|
|
ensure
|
|
ActiveSupport::Notifications.notifier = old_notifier
|
|
end
|
|
|
|
def test_subscribe_with_a_single_arity_lambda_listener
|
|
event_name = nil
|
|
listener = ->(event) do
|
|
event_name = event.name
|
|
end
|
|
|
|
@notifier.subscribe(&listener)
|
|
ActiveSupport::Notifications.instrument("event_name")
|
|
|
|
assert_equal "event_name", event_name
|
|
end
|
|
|
|
def test_subscribe_with_a_single_arity_callable_listener
|
|
event_name = nil
|
|
listener = Class.new do
|
|
define_method :call do |event|
|
|
event_name = event.name
|
|
end
|
|
end
|
|
|
|
@notifier.subscribe(nil, listener.new)
|
|
ActiveSupport::Notifications.instrument("event_name")
|
|
|
|
assert_equal "event_name", event_name
|
|
end
|
|
end
|
|
|
|
class TimedAndMonotonicTimedSubscriberTest < TestCase
|
|
def test_subscribe
|
|
event_name = "foo"
|
|
class_of_started = nil
|
|
class_of_finished = nil
|
|
|
|
ActiveSupport::Notifications.subscribe(event_name) do |name, started, finished, unique_id, data|
|
|
class_of_started = started.class
|
|
class_of_finished = finished.class
|
|
end
|
|
|
|
ActiveSupport::Notifications.instrument(event_name)
|
|
|
|
assert_equal [Time, Time], [class_of_started, class_of_finished]
|
|
end
|
|
|
|
def test_monotonic_subscribe
|
|
event_name = "foo"
|
|
class_of_started = nil
|
|
class_of_finished = nil
|
|
|
|
ActiveSupport::Notifications.monotonic_subscribe(event_name) do |name, started, finished, unique_id, data|
|
|
class_of_started = started.class
|
|
class_of_finished = finished.class
|
|
end
|
|
|
|
ActiveSupport::Notifications.instrument(event_name)
|
|
|
|
assert_equal [Float, Float], [class_of_started, class_of_finished]
|
|
end
|
|
end
|
|
|
|
class BuildHandleTest < TestCase
|
|
def test_interleaved_event
|
|
event_name = "foo"
|
|
actual_times = []
|
|
|
|
ActiveSupport::Notifications.subscribe(event_name) do |name, started, finished, unique_id, data|
|
|
actual_times << [started, finished]
|
|
end
|
|
|
|
times = (1..4).map { |s| Time.new(2020, 1, 1) + s }
|
|
|
|
instrumenter = ActiveSupport::Notifications.instrumenter
|
|
travel_to times[0]
|
|
handle1 = instrumenter.build_handle(event_name, {})
|
|
handle2 = instrumenter.build_handle(event_name, {})
|
|
|
|
handle1.start
|
|
travel_to times[1]
|
|
handle2.start
|
|
travel_to times[2]
|
|
handle1.finish
|
|
travel_to times[3]
|
|
handle2.finish
|
|
|
|
assert_equal [
|
|
# from when start1 was returned, to when its state passed to finish
|
|
[times[0], times[2]],
|
|
# from when start2 was returned, to when its state passed to finish
|
|
[times[1], times[3]],
|
|
], actual_times
|
|
end
|
|
|
|
def test_subscribed_interleaved_with_event
|
|
instrumenter = ActiveSupport::Notifications.instrumenter
|
|
|
|
name = "foo"
|
|
events1 = []
|
|
events2 = []
|
|
|
|
callback1 = lambda { |event| events1 << event }
|
|
callback2 = lambda { |event| events2 << event }
|
|
|
|
ActiveSupport::Notifications.subscribed(callback1, name) do
|
|
handle = instrumenter.build_handle(name, {})
|
|
handle.start
|
|
|
|
ActiveSupport::Notifications.subscribed(callback2, name) do
|
|
handle.finish
|
|
end
|
|
end
|
|
|
|
assert_equal 1, events1.size
|
|
assert_empty events2
|
|
|
|
assert_equal name, events1[0].name
|
|
assert events1[0].time
|
|
assert events1[0].end
|
|
end
|
|
end
|
|
|
|
class SubscribedTest < TestCase
|
|
def test_subscribed
|
|
name = "foo"
|
|
name2 = name * 2
|
|
expected = [name, name]
|
|
|
|
events = []
|
|
callback = lambda { |*_| events << _.first }
|
|
ActiveSupport::Notifications.subscribed(callback, name) do
|
|
ActiveSupport::Notifications.instrument(name)
|
|
ActiveSupport::Notifications.instrument(name2)
|
|
ActiveSupport::Notifications.instrument(name)
|
|
end
|
|
assert_equal expected, events
|
|
|
|
ActiveSupport::Notifications.instrument(name)
|
|
assert_equal expected, events
|
|
end
|
|
|
|
def test_subscribed_all_messages
|
|
name = "foo"
|
|
name2 = name * 2
|
|
expected = [name, name2, name]
|
|
|
|
events = []
|
|
callback = lambda { |*_| events << _.first }
|
|
ActiveSupport::Notifications.subscribed(callback) do
|
|
ActiveSupport::Notifications.instrument(name)
|
|
ActiveSupport::Notifications.instrument(name2)
|
|
ActiveSupport::Notifications.instrument(name)
|
|
end
|
|
assert_equal expected, events
|
|
|
|
ActiveSupport::Notifications.instrument(name)
|
|
assert_equal expected, events
|
|
end
|
|
|
|
def test_subscribing_to_instrumentation_while_inside_it
|
|
# the repro requires that there are no evented subscribers for the "foo" event,
|
|
# so we have to duplicate some of the setup code
|
|
old_notifier = ActiveSupport::Notifications.notifier
|
|
ActiveSupport::Notifications.notifier = ActiveSupport::Notifications::Fanout.new
|
|
|
|
ActiveSupport::Notifications.subscribe("foo", TestSubscriber.new)
|
|
|
|
assert_nothing_raised do
|
|
ActiveSupport::Notifications.instrument("foo") do
|
|
ActiveSupport::Notifications.subscribe("foo") { }
|
|
end
|
|
end
|
|
ensure
|
|
ActiveSupport::Notifications.notifier = old_notifier
|
|
end
|
|
|
|
def test_timed_subscribed
|
|
event_name = "foo"
|
|
class_of_started = nil
|
|
class_of_finished = nil
|
|
callback = lambda do |name, started, finished, unique_id, data|
|
|
class_of_started = started.class
|
|
class_of_finished = finished.class
|
|
end
|
|
|
|
ActiveSupport::Notifications.subscribed(callback, event_name) do
|
|
ActiveSupport::Notifications.instrument(event_name)
|
|
end
|
|
|
|
ActiveSupport::Notifications.instrument(event_name)
|
|
|
|
assert_equal [Time, Time], [class_of_started, class_of_finished]
|
|
end
|
|
|
|
def test_monotonic_timed_subscribed
|
|
event_name = "foo"
|
|
class_of_started = nil
|
|
class_of_finished = nil
|
|
callback = lambda do |name, started, finished, unique_id, data|
|
|
class_of_started = started.class
|
|
class_of_finished = finished.class
|
|
end
|
|
|
|
ActiveSupport::Notifications.subscribed(callback, event_name, monotonic: true) do
|
|
ActiveSupport::Notifications.instrument(event_name)
|
|
end
|
|
|
|
ActiveSupport::Notifications.instrument(event_name)
|
|
|
|
assert_equal [Float, Float], [class_of_started, class_of_finished]
|
|
end
|
|
end
|
|
|
|
class InspectTest < TestCase
|
|
def test_inspect_output_is_small
|
|
expected = "#<ActiveSupport::Notifications::Fanout (2 patterns)>"
|
|
assert_equal expected, @notifier.inspect
|
|
end
|
|
end
|
|
|
|
class UnsubscribeTest < TestCase
|
|
def test_unsubscribing_removes_a_subscription
|
|
@notifier.publish :foo
|
|
@notifier.wait
|
|
assert_equal [[:foo]], @events
|
|
@notifier.unsubscribe(@subscription)
|
|
@notifier.publish :foo
|
|
@notifier.wait
|
|
assert_equal [[:foo]], @events
|
|
end
|
|
|
|
def test_unsubscribing_by_name_removes_a_subscription
|
|
@notifier.publish "named.subscription", :foo
|
|
@notifier.wait
|
|
assert_equal [["named.subscription", :foo]], @named_events
|
|
@notifier.unsubscribe("named.subscription")
|
|
@notifier.publish "named.subscription", :foo
|
|
@notifier.wait
|
|
assert_equal [["named.subscription", :foo]], @named_events
|
|
end
|
|
|
|
def test_unsubscribing_by_name_leaves_the_other_subscriptions
|
|
@notifier.publish "named.subscription", :foo
|
|
@notifier.wait
|
|
assert_equal [["named.subscription", :foo]], @events
|
|
@notifier.unsubscribe("named.subscription")
|
|
@notifier.publish "named.subscription", :foo
|
|
@notifier.wait
|
|
assert_equal [["named.subscription", :foo], ["named.subscription", :foo]], @events
|
|
end
|
|
|
|
def test_unsubscribing_by_name_leaves_regexp_matched_subscriptions
|
|
@matched_events = []
|
|
@notifier.subscribe(/subscription/) { |*args| @matched_events << event(*args) }
|
|
@notifier.publish("named.subscription", :before)
|
|
@notifier.wait
|
|
[@events, @named_events, @matched_events].each do |collector|
|
|
assert_includes(collector, ["named.subscription", :before])
|
|
end
|
|
@notifier.unsubscribe("named.subscription")
|
|
@notifier.publish("named.subscription", :after)
|
|
@notifier.publish("other.subscription", :after)
|
|
@notifier.wait
|
|
assert_includes(@events, ["named.subscription", :after])
|
|
assert_includes(@events, ["other.subscription", :after])
|
|
assert_includes(@matched_events, ["other.subscription", :after])
|
|
assert_not_includes(@matched_events, ["named.subscription", :after])
|
|
assert_not_includes(@named_events, ["named.subscription", :after])
|
|
end
|
|
|
|
private
|
|
def event(*args)
|
|
args
|
|
end
|
|
end
|
|
|
|
class TestSubscriber
|
|
attr_reader :starts, :finishes, :publishes
|
|
|
|
def initialize
|
|
@starts = []
|
|
@finishes = []
|
|
@publishes = []
|
|
end
|
|
|
|
def start(*args); @starts << args; end
|
|
def finish(*args); @finishes << args; end
|
|
def publish(*args); @publishes << args; end
|
|
end
|
|
|
|
class SyncPubSubTest < TestCase
|
|
def test_events_are_published_to_a_listener
|
|
@notifier.publish :foo
|
|
@notifier.wait
|
|
assert_equal [[:foo]], @events
|
|
end
|
|
|
|
def test_publishing_multiple_times_works
|
|
@notifier.publish :foo
|
|
@notifier.publish :foo
|
|
@notifier.wait
|
|
assert_equal [[:foo], [:foo]], @events
|
|
end
|
|
|
|
def test_publishing_after_a_new_subscribe_works
|
|
@notifier.publish :foo
|
|
@notifier.publish :foo
|
|
|
|
@notifier.subscribe("not_existent") { |event| @events << event }
|
|
|
|
@notifier.publish :foo
|
|
@notifier.publish :foo
|
|
@notifier.wait
|
|
|
|
assert_equal [[:foo]] * 4, @events
|
|
end
|
|
|
|
def test_log_subscriber_with_string
|
|
events = []
|
|
@notifier.subscribe("1") { |*args| events << args }
|
|
|
|
@notifier.publish "1"
|
|
@notifier.publish "1.a"
|
|
@notifier.publish "a.1"
|
|
@notifier.wait
|
|
|
|
assert_equal [["1"]], events
|
|
end
|
|
|
|
def test_log_subscriber_with_pattern
|
|
events = []
|
|
@notifier.subscribe(/\d/) { |*args| events << args }
|
|
|
|
@notifier.publish "1"
|
|
@notifier.publish "a.1"
|
|
@notifier.publish "1.a"
|
|
@notifier.wait
|
|
|
|
assert_equal [["1"], ["a.1"], ["1.a"]], events
|
|
end
|
|
|
|
def test_multiple_log_subscribers
|
|
@another = []
|
|
@notifier.subscribe { |*args| @another << args }
|
|
@notifier.publish :foo
|
|
@notifier.wait
|
|
|
|
assert_equal [[:foo]], @events
|
|
assert_equal [[:foo]], @another
|
|
end
|
|
|
|
def test_publish_with_subscriber
|
|
subscriber = TestSubscriber.new
|
|
@notifier.subscribe nil, subscriber
|
|
@notifier.publish :foo
|
|
|
|
assert_equal [[:foo]], subscriber.publishes
|
|
end
|
|
|
|
private
|
|
def event(*args)
|
|
args
|
|
end
|
|
end
|
|
|
|
class InstrumentationTest < TestCase
|
|
delegate :instrument, to: ActiveSupport::Notifications
|
|
|
|
def test_instrument_returns_block_result
|
|
assert_equal 2, instrument(:awesome) { 1 + 1 }
|
|
end
|
|
|
|
def test_instrument_yields_the_payload_for_further_modification
|
|
assert_equal 2, instrument(:awesome) { |p| p[:result] = 1 + 1 }
|
|
assert_equal 1, @events.size
|
|
assert_equal :awesome, @events.first.name
|
|
assert_equal Hash[result: 2], @events.first.payload
|
|
end
|
|
|
|
def test_instrumenter_exposes_its_id
|
|
assert_equal 20, ActiveSupport::Notifications.instrumenter.id.size
|
|
end
|
|
|
|
def test_nested_events_can_be_instrumented
|
|
instrument(:awesome, payload: "notifications") do
|
|
instrument(:wot, payload: "child") do
|
|
1 + 1
|
|
end
|
|
|
|
assert_equal 1, @events.size
|
|
assert_equal :wot, @events.first.name
|
|
assert_equal Hash[payload: "child"], @events.first.payload
|
|
end
|
|
|
|
assert_equal 2, @events.size
|
|
assert_equal :awesome, @events.last.name
|
|
assert_equal Hash[payload: "notifications"], @events.last.payload
|
|
end
|
|
|
|
def test_instrument_publishes_when_exception_is_raised
|
|
begin
|
|
instrument(:awesome, payload: "notifications") do
|
|
raise "FAIL"
|
|
end
|
|
rescue RuntimeError => e
|
|
assert_equal "FAIL", e.message
|
|
end
|
|
|
|
assert_equal 1, @events.size
|
|
assert_equal Hash[payload: "notifications",
|
|
exception: ["RuntimeError", "FAIL"], exception_object: e], @events.last.payload
|
|
end
|
|
|
|
def test_event_is_pushed_even_without_block
|
|
instrument(:awesome, payload: "notifications")
|
|
assert_equal 1, @events.size
|
|
assert_equal :awesome, @events.last.name
|
|
assert_equal Hash[payload: "notifications"], @events.last.payload
|
|
end
|
|
end
|
|
|
|
class EventTest < TestCase
|
|
def test_events_are_initialized_with_details
|
|
time = Time.now.to_f
|
|
event = event(:foo, time, time + 0.01, random_id, {})
|
|
|
|
assert_equal :foo, event.name
|
|
assert_in_epsilon 10.0, event.duration, 0.01
|
|
end
|
|
|
|
def test_event_cpu_time_does_not_raise_error_when_start_or_finished_not_called
|
|
time = Time.now
|
|
event = event(:foo, time, time + 0.01, random_id, {})
|
|
|
|
assert_equal 0, event.cpu_time
|
|
end
|
|
|
|
def test_events_consumes_information_given_as_payload
|
|
event = event(:foo, Process.clock_gettime(Process::CLOCK_MONOTONIC), Process.clock_gettime(Process::CLOCK_MONOTONIC) + 1, random_id, payload: :bar)
|
|
assert_equal Hash[payload: :bar], event.payload
|
|
end
|
|
|
|
def test_subscribe_raises_error_on_non_supported_arguments
|
|
notifier = ActiveSupport::Notifications::Fanout.new
|
|
|
|
assert_raises ArgumentError do
|
|
notifier.subscribe(:symbol) { |*_| }
|
|
end
|
|
assert_raises ArgumentError do
|
|
notifier.subscribe(Object.new) { |*_| }
|
|
end
|
|
end
|
|
|
|
private
|
|
def random_id
|
|
@random_id ||= SecureRandom.hex(10)
|
|
end
|
|
end
|
|
end
|