From d4d3c0c50a8880bf5294b1243d0147a4d857def2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc=20Busqu=C3=A9?= Date: Thu, 22 Jul 2021 19:02:43 +0200 Subject: [PATCH] Adds observability to the new event bus This commit adds observability abilities to the new event bus adapter: - It adds creation time and caller location to the `Spree::Event::Event` instance bound to the subscribers. - It wraps the execution of listeners within a new `Spree::Event::Execution` class, which wraps the execution time, a benchmark of the operation, and the result returned by the subscription. Both the `Spree::Event::Event` and the list of `Spree::Event::Execution` are wrapped within a new `Spree::Event::Firing` object, which is returned on `Spree::Event.fire`. Therefore, a typical flow could be getting the event's caller from within the subscriber block and then inspecting the firing object from there if needed. Having all the metadata collected in a single place when we do `Spree::Event.fire` will simplify things if we implement some event store in the future. --- core/lib/spree/event.rb | 9 +- core/lib/spree/event/adapters/default.rb | 11 +- core/lib/spree/event/event.rb | 21 +- core/lib/spree/event/execution.rb | 44 ++++ core/lib/spree/event/firing.rb | 30 +++ core/lib/spree/event/listener.rb | 10 +- .../lib/spree/event/adapters/default_spec.rb | 190 +++++++----------- core/spec/lib/spree/event/listener_spec.rb | 31 ++- core/spec/lib/spree/event_spec.rb | 110 ++++------ 9 files changed, 254 insertions(+), 202 deletions(-) create mode 100644 core/lib/spree/event/execution.rb create mode 100644 core/lib/spree/event/firing.rb diff --git a/core/lib/spree/event.rb b/core/lib/spree/event.rb index 5cf3aa0ca6c..f017a60f9df 100644 --- a/core/lib/spree/event.rb +++ b/core/lib/spree/event.rb @@ -57,7 +57,8 @@ module Event # instead. # @option opts [Any] :adapter Reserved to indicate the adapter to use as # event bus. Defaults to {#default_adapter} - # @return [Spree::Event::Event] an event object, unless the adapter is + # @return [Spree::Event::Firing] A firing object encapsulating metadata for + # the event and the originated listener executions, unless the adapter is # {Spree::Event::Adapters::ActiveSupportNotifications} # # @example Trigger an event named 'order_finalized' @@ -71,7 +72,11 @@ module Event def fire(event_name, opts = {}, &block) adapter = opts.delete(:adapter) || default_adapter handle_block_on_fire(block, opts, adapter) if block_given? - adapter.fire normalize_name(event_name), opts + if deprecation_handler.legacy_adapter?(adapter) + adapter.fire(normalize_name(event_name), opts) + else + adapter.fire(normalize_name(event_name), caller_location: caller_locations(1)[0], **opts) + end end # Subscribe to events matching the given name. diff --git a/core/lib/spree/event/adapters/default.rb b/core/lib/spree/event/adapters/default.rb index 3d8ba15e925..16e1d1f04e8 100644 --- a/core/lib/spree/event/adapters/default.rb +++ b/core/lib/spree/event/adapters/default.rb @@ -2,6 +2,7 @@ require 'spree/event/event' require 'spree/event/listener' +require 'spree/event/firing' module Spree module Event @@ -32,12 +33,12 @@ def initialize end # @api private - def fire(event_name, opts = {}) - Event.new(payload: opts).tap do |event| - listeners_for_event(event_name).each do |listener| - listener.call(event) - end + def fire(event_name, caller_location: caller_locations(1)[0], **payload) + event = Event.new(payload: payload, caller_location: caller_location) + executions = listeners_for_event(event_name).map do |listener| + listener.call(event) end + Firing.new(event: event, executions: executions) end # @api private diff --git a/core/lib/spree/event/event.rb b/core/lib/spree/event/event.rb index ae61593c4bf..6d76e267e3f 100644 --- a/core/lib/spree/event/event.rb +++ b/core/lib/spree/event/event.rb @@ -12,15 +12,34 @@ module Event # Spree::Event.subscribe 'event_name' do |event| # puts event.payload['foo'] #=> 'bar' # end + # + # Besides, it can be accessed through the returned value in {Spree::Event.fire}. + # It can be useful for debugging and logging purposes, as it contains + # helpful metadata like the event time or the caller location. class Event # Hash with the options given to {Spree::Event.fire} # # @return [Hash] attr_reader :payload + # Time of the event firing + # + # @return [Time] + attr_reader :firing_time + + # Location for the event caller + # + # It's usually set by {Spree::Event.fire}, and it points to the caller of + # that method. + # + # @return [Thread::Backtrace::Location] + attr_reader :caller_location + # @api private - def initialize(payload:) + def initialize(payload:, caller_location:, firing_time: Time.now.utc) @payload = payload + @caller_location = caller_location + @firing_time = firing_time end end end diff --git a/core/lib/spree/event/execution.rb b/core/lib/spree/event/execution.rb new file mode 100644 index 00000000000..755e95eea85 --- /dev/null +++ b/core/lib/spree/event/execution.rb @@ -0,0 +1,44 @@ +# frozen_string_literal: true + +module Spree + module Event + # Execution of a {Spree::Event::Listener} + # + # When an event is fired, it executes all subscribed listeners. Every single + # execution is represented as an instance of this class. It contains the + # result value of the listener, along with helpful metadata as the time of + # the execution or a benchmark for it. + # + # You'll most likely interact with this class for debugging or logging + # purposes through the returned value in {Spree::Event.fire}. + class Execution + # The listener to which the execution belongs + # + # @return [Spree::Event::Listener] + attr_reader :listener + + # The value returned by the {#listener}'s block + # + # @return [Any] + attr_reader :result + + # Benchmark for the {#listener}'s block + # + # @return [Benchmark::Tms] + attr_reader :benchmark + + # Time of execution + # + # @return [Time] + attr_reader :execution_time + + # @private + def initialize(listener:, result:, benchmark:, execution_time: Time.now.utc) + @listener = listener + @result = result + @benchmark = benchmark + @execution_time = execution_time + end + end + end +end diff --git a/core/lib/spree/event/firing.rb b/core/lib/spree/event/firing.rb new file mode 100644 index 00000000000..5fa591979c4 --- /dev/null +++ b/core/lib/spree/event/firing.rb @@ -0,0 +1,30 @@ +# frozen_string_literal: true + +module Spree + module Event + # The result of firing an event + # + # It encapsulates a fired {Spree::Event::Event} as well as the + # {Spree::Event::Execution}s it originated. + # + # This class is useful mainly for debugging and logging purposes. An + # instance of it is returned on {Spree::Event.fire}. + class Firing + # Fired event + # + # @return [Spree::Event::Event] + attr_reader :event + + # Listener executions that the firing originated + # + # @return [Array] + attr_reader :executions + + # @api private + def initialize(event:, executions:) + @event = event + @executions = executions + end + end + end +end diff --git a/core/lib/spree/event/listener.rb b/core/lib/spree/event/listener.rb index c54718548fb..4cfb986824e 100644 --- a/core/lib/spree/event/listener.rb +++ b/core/lib/spree/event/listener.rb @@ -1,5 +1,8 @@ # frozen_string_literal: true +require 'benchmark' +require 'spree/event/execution' + module Spree module Event # Subscription to an event @@ -25,7 +28,12 @@ def initialize(pattern:, block:) # @api private def call(event) - @block.call(event) + result = nil + benchmark = Benchmark.measure do + result = @block.call(event) + end + + Execution.new(listener: self, result: result, benchmark: benchmark) end # @api private diff --git a/core/spec/lib/spree/event/adapters/default_spec.rb b/core/spec/lib/spree/event/adapters/default_spec.rb index 7a76c276984..bbc766f4468 100644 --- a/core/spec/lib/spree/event/adapters/default_spec.rb +++ b/core/spec/lib/spree/event/adapters/default_spec.rb @@ -7,85 +7,59 @@ module Spree module Event module Adapters RSpec.describe Default do + let(:counter) do + Class.new do + attr_reader :count + + def initialize + @count = 0 + end + + def inc + @count += 1 + end + end + end + describe '#fire' do it 'executes listeners subscribed as a string to the event name' do bus = described_class.new - dummy = Class.new do - attr_reader :run - - def initialize - @run = false - end - - def toggle - @run = true - end - end.new - bus.subscribe('foo') { dummy.toggle } + dummy = counter.new + bus.subscribe('foo') { dummy.inc } bus.fire 'foo' - expect(dummy.run).to be(true) + expect(dummy.count).to be(1) end it 'executes listeners subscribed as a regexp to the event name' do bus = described_class.new - dummy = Class.new do - attr_reader :run - - def initialize - @run = false - end - - def toggle - @run = true - end - end.new - bus.subscribe(/oo/) { dummy.toggle } + dummy = counter.new + bus.subscribe(/oo/) { dummy.inc } bus.fire 'foo' - expect(dummy.run).to be(true) + expect(dummy.count).to be(1) end it "doesn't execute listeners not subscribed to the event name" do bus = described_class.new - dummy = Class.new do - attr_reader :run - - def initialize - @run = false - end - - def toggle - @run = true - end - end.new - bus.subscribe('bar') { dummy.toggle } + dummy = counter.new + bus.subscribe('bar') { dummy.inc } bus.fire 'foo' - expect(dummy.run).to be(false) + expect(dummy.count).to be(0) end it "doesn't execute listeners partially matching as a string" do bus = described_class.new - dummy = Class.new do - attr_reader :run - - def initialize - @run = false - end - - def toggle - @run = true - end - end.new - bus.subscribe('bar') { dummy.toggle } + dummy = counter.new + bus.subscribe('bar') { dummy.inc } bus.fire 'barr' - expect(dummy.run).to be(false) + expect(dummy.count).to be(0) end it 'binds given options to the subscriber as the event payload' do @@ -99,6 +73,30 @@ def toggle expect(dummy.box).to eq('foo') end + + it 'adds the fired event with given caller location to the firing result object' do + bus = described_class.new + dummy = counter.new + bus.subscribe('foo') { :work } + + firing = bus.fire 'foo', caller_location: caller_locations(0)[0] + + expect(firing.event.caller_location.to_s).to include(__FILE__) + end + + it 'adds the triggered executions to the firing result object', :aggregate_failures do + bus = described_class.new + dummy = counter.new + listener1 = bus.subscribe('foo') { dummy.inc } + listener2 = bus.subscribe('foo') { dummy.inc } + + firing = bus.fire 'foo' + + executions = firing.executions + expect(executions.count).to be(2) + expect(executions.map(&:listener)).to match([listener1, listener2]) + expect(executions.map(&:result)).to match([1, 2]) + end end describe '#subscribe' do @@ -133,114 +131,62 @@ def toggle context 'when given a listener' do it 'unsubscribes given listener' do bus = described_class.new - dummy = Class.new do - attr_reader :run - - def initialize - @run = false - end - - def toggle - @run = true - end - end.new - listener = bus.subscribe('foo') { dummy.toggle } + dummy = counter.new + listener = bus.subscribe('foo') { dummy.inc } bus.unsubscribe listener bus.fire 'foo' - expect(dummy.run).to be(false) + expect(dummy.count).to be(0) end end context 'when given an event name' do it 'unsubscribes all listeners for that event' do bus = described_class.new - dummy = Class.new do - attr_reader :run + dummy = counter.new - def initialize - @run = false - end - - def toggle - @run = true - end - end.new - - bus.subscribe('foo') { dummy.toggle } + bus.subscribe('foo') { dummy.inc } bus.unsubscribe 'foo' bus.fire 'foo' - expect(dummy.run).to be(false) + expect(dummy.count).to be(0) end end it 'unsubscribes listeners that match event with a regexp' do bus = described_class.new - dummy = Class.new do - attr_reader :run - - def initialize - @run = false - end - - def toggle - @run = true - end - end.new - bus.subscribe(/foo/) { dummy.toggle } + dummy = counter.new + bus.subscribe(/foo/) { dummy.inc } bus.unsubscribe 'foo' bus.fire 'foo' - expect(dummy.run).to be(false) + expect(dummy.count).to be(0) end it "doesn't unsubscribe listeners for other events" do bus = described_class.new - dummy = Class.new do - attr_reader :run - - def initialize - @run = false - end + dummy = counter.new - def toggle - @run = true - end - end.new - - bus.subscribe('foo') { dummy.toggle } + bus.subscribe('foo') { dummy.inc } bus.unsubscribe 'bar' bus.fire 'foo' - expect(dummy.run).to be(true) + expect(dummy.count).to be(1) end - it 'can resubscribe other listeners to the same event' do + it 'can resubscribe other listeners to the same event', :aggregate_failures do bus = described_class.new - dummy1, dummy2 = Array.new(2) do - Class.new do - attr_reader :run - - def initialize - @run = false - end - - def toggle - @run = true - end - end.new - end + dummy1, dummy2 = Array.new(2) { counter.new } - bus.subscribe('foo') { dummy1.toggle } + bus.subscribe('foo') { dummy1.inc } bus.unsubscribe 'foo' - bus.subscribe('foo') { dummy2.toggle } + bus.subscribe('foo') { dummy2.inc } bus.fire 'foo' - expect(dummy1.run).to be(false) - expect(dummy2.run).to be(true) + expect(dummy1.count).to be(0) + expect(dummy2.count).to be(1) end end end diff --git a/core/spec/lib/spree/event/listener_spec.rb b/core/spec/lib/spree/event/listener_spec.rb index f64b1f10505..3f310c1b642 100644 --- a/core/spec/lib/spree/event/listener_spec.rb +++ b/core/spec/lib/spree/event/listener_spec.rb @@ -1,13 +1,38 @@ # frozen_string_literal: true require 'spree/event/listener' +require 'spree/event/execution' RSpec.describe Spree::Event::Listener do describe '#call' do - it 'returns the result of calling block with given event' do - listener = described_class.new(pattern: 'foo', block: ->(event) { event[:bar] }) + it 'returns an execution instance' do + listener = described_class.new(pattern: 'foo', block: proc {}) - expect(listener.call(bar: 'bar')).to eq('bar') + expect(listener.call(:event)).to be_a(Spree::Event::Execution) + end + + it "binds the event and sets execution's result" do + listener = described_class.new(pattern: 'foo', block: ->(event) { event[:foo] }) + + execution = listener.call(foo: :bar) + + expect(execution.result).to eq(:bar) + end + + it 'sets itself as the execution listener' do + listener = described_class.new(pattern: 'foo', block: proc { 'foo' }) + + execution = listener.call(:event) + + expect(execution.listener).to be(listener) + end + + it "sets the execution's benchmark" do + listener = described_class.new(pattern: 'foo', block: proc { 'foo' }) + + execution = listener.call(:event) + + expect(execution.benchmark).to be_a(Benchmark::Tms) end end diff --git a/core/spec/lib/spree/event_spec.rb b/core/spec/lib/spree/event_spec.rb index 728256a8324..7afff24618d 100644 --- a/core/spec/lib/spree/event_spec.rb +++ b/core/spec/lib/spree/event_spec.rb @@ -8,6 +8,20 @@ RSpec.describe Spree::Event do subject { described_class } + let(:counter) do + Class.new do + attr_reader :count + + def initialize + @count = 0 + end + + def inc + @count += 1 + end + end + end + def build_bus Spree::Event::Adapters::Default.new end @@ -19,7 +33,7 @@ def build_bus end describe '.adapter' do - it 'deprecates and forwards to default_adapter' do + it 'deprecates and forwards to default_adapter', :aggregate_failures do expect(Spree::Deprecation).to receive(:warn).with(/deprecated.*default_adapter/m) expect(subject.adapter).to be(subject.default_adapter) @@ -27,44 +41,25 @@ def build_bus end describe '.fire' do - it 'forwards to adapter' do + it 'forwards to adapter', :aggregate_failures do bus = build_bus - dummy = Class.new do - attr_reader :run + dummy = counter.new + subject.subscribe('foo', adapter: bus) { dummy.inc } - def initialize - @run = false - end + firing = subject.fire 'foo', adapter: bus - def toggle - @run = true - end - end.new - subject.subscribe('foo', adapter: bus) { dummy.toggle } - - subject.fire 'foo', adapter: bus - - expect(dummy.run).to be(true) + expect(dummy.count).to be(1) + expect(firing.executions.first.result).to be(1) end it 'coerces event names given as symbols' do bus = build_bus - dummy = Class.new do - attr_reader :run - - def initialize - @run = false - end - - def toggle - @run = true - end - end.new - subject.subscribe('foo', adapter: bus) { dummy.toggle } + dummy = counter.new + subject.subscribe('foo', adapter: bus) { dummy.inc } subject.fire :foo, adapter: bus - expect(dummy.run).to be(true) + expect(dummy.count).to be(1) end it 'raises error if a block is given and the adapter is not ActiveSupportNotifications' do @@ -76,17 +71,7 @@ def toggle end it 'executes a block when given and the adapter is ActiveSupportNotifications' do - dummy = Class.new do - attr_reader :run - - def initialize - @run = false - end - - def toggle - @run = true - end - end.new + dummy = counter.new if Spree::Event::Adapters::DeprecationHandler.legacy_adapter_set_by_env allow(Spree::Deprecation).to receive(:warn).with(/Blocks.*are ignored/) @@ -94,9 +79,18 @@ def toggle expect(Spree::Deprecation).to receive(:warn).with(/Blocks.*are ignored/) end - subject.fire(:foo, adapter: Spree::Event::Adapters::ActiveSupportNotifications) { dummy.toggle } + subject.fire(:foo, adapter: Spree::Event::Adapters::ActiveSupportNotifications) { dummy.inc } + + expect(dummy.count).to be(1) + end + + it "provides caller location to the event" do + bus = build_bus + subject.subscribe('foo', adapter: bus) { :work } + + firing = subject.fire 'foo', adapter: bus - expect(dummy.run).to be(true) + expect(firing.event.caller_location.to_s).to include(__FILE__) end end @@ -121,44 +115,24 @@ def toggle describe '#unsubscribe' do it 'delegates to the adapter' do bus = build_bus - dummy = Class.new do - attr_reader :run - - def initialize - @run = false - end - - def toggle - @run = true - end - end.new - listener = subject.subscribe('foo', adapter: bus) { dummy.toggle } + dummy = counter.new + listener = subject.subscribe('foo', adapter: bus) { dummy.inc } subject.unsubscribe listener, adapter: bus subject.fire 'foo', adapter: bus - expect(dummy.run).to be(false) + expect(dummy.count).to be(0) end it 'coerces event names given as symbols' do bus = build_bus - dummy = Class.new do - attr_reader :run - - def initialize - @run = false - end - - def toggle - @run = true - end - end.new - subject.subscribe('foo', adapter: bus) { dummy.toggle } + dummy = counter.new + subject.subscribe('foo', adapter: bus) { dummy.inc } subject.unsubscribe :foo, adapter: bus subject.fire 'foo', adapter: bus - expect(dummy.run).to be(false) + expect(dummy.count).to be(0) end end