require 'minitest/autorun' require 'prism' require 'stringio' class InstrumentationTest < Minitest::Test def setup @bus = Prism::Instrumentation::Bus.new end def test_instrument_returns_block_value result = @bus.instrument('demo.event') { 42 } assert_equal 42, result end def test_subscriber_receives_event_with_name_and_payload events = [] @bus.subscribe('demo.event') { |event| events << event } @bus.instrument('demo.event', foo: 'bar') { :ok } assert_equal 1, events.size assert_equal 'demo.event', events.first.name assert_equal 'bar', events.first.payload[:foo] end def test_duration_is_a_non_negative_float events = [] @bus.subscribe('demo.event') { |event| events << event } @bus.instrument('demo.event') { sleep 0.01 } assert_kind_of Float, events.first.duration assert_operator events.first.duration, :>=, 0.01 assert_operator events.first.duration_ms, :>=, 10.0 end def test_string_pattern_matches_exact_name_only events = [] @bus.subscribe('demo.event') { |event| events << event } @bus.instrument('other.event') { :ok } assert_empty events end def test_regexp_pattern_matches_by_suffix events = [] @bus.subscribe(/\.prism\z/) { |event| events << event } @bus.instrument('sql.prism') { :ok } @bus.instrument('unrelated.event') { :ok } assert_equal ['sql.prism'], events.map(&:name) end def test_nil_pattern_matches_everything events = [] @bus.subscribe { |event| events << event } @bus.instrument('a') { :ok } @bus.instrument('b') { :ok } assert_equal %w[a b], events.map(&:name) end def test_multiple_subscribers_all_notified calls = [] @bus.subscribe('demo.event') { calls << :first } @bus.subscribe('demo.event') { calls << :second } @bus.instrument('demo.event') { :ok } assert_equal %i[first second], calls end def test_unsubscribe_stops_future_notifications events = [] subscriber = @bus.subscribe('demo.event') { |event| events << event } @bus.instrument('demo.event') { :ok } @bus.unsubscribe(subscriber) @bus.instrument('demo.event') { :ok } assert_equal 1, events.size end def test_block_can_mutate_payload_before_publish events = [] @bus.subscribe('demo.event') { |event| events << event } @bus.instrument('demo.event', {}) { |payload| payload[:computed] = 'late' } assert_equal 'late', events.first.payload[:computed] end def test_exception_propagates_and_is_recorded_on_payload events = [] @bus.subscribe('demo.event') { |event| events << event } assert_raises(RuntimeError) do @bus.instrument('demo.event') { raise 'boom' } end assert_equal 1, events.size, 'event must still publish when the block raises' assert_equal ['RuntimeError', 'boom'], events.first.payload[:exception] assert_kind_of RuntimeError, events.first.payload[:exception_object] end def test_instrument_without_block_returns_nil_and_still_publishes events = [] @bus.subscribe('demo.event') { |event| events << event } result = @bus.instrument('demo.event') assert_nil result assert_equal 1, events.size end def test_concurrent_instrument_and_subscribe_do_not_corrupt_state counter = 0 mutex = Mutex.new @bus.subscribe('demo.event') { mutex.synchronize { counter += 1 } } threads = Array.new(20) do Thread.new { 50.times { @bus.instrument('demo.event') { :ok } } } end threads.each(&:join) assert_equal 1000, counter end def test_module_level_bus_is_a_singleton assert_same Prism::Instrumentation.bus, Prism::Instrumentation.bus end def test_module_level_instrument_and_subscribe_delegate_to_bus events = [] subscriber = Prism::Instrumentation.subscribe('module.demo') { |event| events << event } Prism::Instrumentation.instrument('module.demo') { :ok } Prism::Instrumentation.unsubscribe(subscriber) assert_equal 1, events.size end end class InstrumentationLogSubscriberTest < Minitest::Test def setup @bus = Prism::Instrumentation::Bus.new @io = StringIO.new end def test_attach_writes_one_formatted_line_per_event subscribers = attach_to(@bus, @io, patterns: ['sql.prism']) @bus.instrument('sql.prism', operation: 'SELECT', table: 'posts') { :ok } subscribers.each { |s| @bus.unsubscribe(s) } line = @io.string.lines.first assert_match(/sql\.prism \(\d+\.\d ms\)/, line.gsub('ms)', ' ms)')) assert_match(/operation="SELECT"/, line) assert_match(/table="posts"/, line) end def test_attach_ignores_events_not_matching_pattern attach_to(@bus, @io, patterns: ['sql.prism']) @bus.instrument('render_template.prism', identifier: 'posts/index') { :ok } assert_empty @io.string end def test_attach_hides_exception_object_from_output attach_to(@bus, @io, patterns: ['demo.event']) assert_raises(RuntimeError) { @bus.instrument('demo.event') { raise 'boom' } } refute_match(/exception_object/, @io.string) assert_match(/exception=\["RuntimeError", "boom"\]/, @io.string) end def test_attach_wires_to_the_process_wide_bus subscribers = Prism::Instrumentation::LogSubscriber.attach(@io, patterns: ['demo.singleton']) Prism::Instrumentation.instrument('demo.singleton', a: 1) { :ok } subscribers.each { |s| Prism::Instrumentation.unsubscribe(s) } Prism::Instrumentation.instrument('demo.singleton', a: 2) { :ok } assert_equal 1, @io.string.lines.size assert_match(/a=1/, @io.string) end private # Most assertions here only need LogSubscriber's formatting, so they run # against a throwaway Bus instead of the process-wide singleton to stay # isolated from other tests; #attach itself is exercised separately above. def attach_to(bus, io, patterns:) patterns.map { |pattern| bus.subscribe(pattern) { |event| io.puts(Prism::Instrumentation::LogSubscriber.format_event(event)) } } end end