diff --git a/lib/service/base.rb b/lib/service/base.rb index e3e6edd9f9c..13a59d68e08 100644 --- a/lib/service/base.rb +++ b/lib/service/base.rb @@ -70,7 +70,7 @@ module Service end def inspect_steps - Service::StepsInspector.new(self) + Service::StepsInspector.new(self).inspect end private @@ -129,7 +129,7 @@ module Service # @!visibility private class Step - attr_reader :name, :method_name, :class_name + attr_reader :name, :method_name, :class_name, :instance, :context def initialize(name, method_name = name, class_name: nil) @name = name @@ -138,14 +138,9 @@ module Service end def call(instance, context) - object = class_name&.new(context) - method = object&.method(:call) || instance.method(method_name) - if method.parameters.any? { _1[0] != :keyreq } - raise "In #{type} '#{name}': default values in step implementations are not allowed. Maybe they could be defined in a params or options block?" - end - args = context.slice(*method.parameters.select { _1[0] == :keyreq }.map(&:last)) - context[result_key] = Context.build({ object: }.compact) - instance.instance_exec(**args, &method) + @instance, @context = instance, context + context[result_key] = Context.build + with_runtime { run_step } end def result_key @@ -154,9 +149,28 @@ module Service private + def run_step + object = class_name&.new(context) + method = object&.method(:call) || instance.method(method_name) + if method.parameters.any? { _1[0] != :keyreq } + raise "In #{type} '#{name}': default values in step implementations are not allowed. Maybe they could be defined in a params or options block?" + end + args = context.slice(*method.parameters.select { _1[0] == :keyreq }.map(&:last)) + context[result_key][:object] = object if object + instance.instance_exec(**args, &method) + end + def type self.class.name.split("::").last.downcase.sub(/^(\w+)step$/, "\\1") end + + def with_runtime + started_at = Process.clock_gettime(Process::CLOCK_MONOTONIC) + yield.tap do + ended_at = Process.clock_gettime(Process::CLOCK_MONOTONIC) + context[result_key][:__runtime__] = ended_at - started_at + end + end end # @!visibility private @@ -168,7 +182,7 @@ module Service @optional = optional.present? end - def call(instance, context) + def run_step context[name] = super if !optional && (!context[name] || context[name].try(:empty?)) raise ArgumentError, "Model not found" @@ -185,7 +199,7 @@ module Service # @!visibility private class PolicyStep < Step - def call(instance, context) + def run_step if !super context[result_key].fail(reason: context[result_key].object&.reason) context.fail! @@ -202,7 +216,7 @@ module Service @default_values_from = default_values_from end - def call(instance, context) + def run_step attributes = class_name.attribute_names.map(&:to_sym) default_values = {} default_values = context[default_values_from].slice(*attributes) if default_values_from @@ -212,7 +226,6 @@ module Service options: context[:options], ) context[contract_name] = contract - context[result_key] = Context.build if contract.invalid? context[result_key].fail(errors: contract.errors, parameters: contract.raw_attributes) context.fail! @@ -243,7 +256,7 @@ module Service instance_exec(&block) end - def call(instance, context) + def run_step ActiveRecord::Base.transaction { steps.each { |step| step.call(instance, context) } } end end @@ -261,8 +274,7 @@ module Service instance_exec(&block) end - def call(instance, context) - context[result_key] = Context.build + def run_step steps.each do |step| @current_step = step step.call(instance, context) @@ -270,15 +282,14 @@ module Service rescue *exceptions => e raise e if e.is_a?(Failure) context[@current_step.result_key].fail(raised_exception?: true, exception: e) - context[result_key].fail(exception: e) + context[result_key][:exception] = e context.fail! end end # @!visibility private class OptionsStep < Step - def call(instance, context) - context[result_key] = Context.build + def run_step context[:options] = class_name.new(context[:options]) end end @@ -428,7 +439,10 @@ module Service # @!visibility private def initialize(initial_context = {}) - @context = Context.build(initial_context.merge(__steps__: self.class.steps)) + @context = + Context.build( + initial_context.merge(__steps__: self.class.steps, __service_class__: self.class), + ) end # @!visibility private diff --git a/lib/service/runner.rb b/lib/service/runner.rb index 692c2d436d3..18d73070fa2 100644 --- a/lib/service/runner.rb +++ b/lib/service/runner.rb @@ -97,7 +97,7 @@ class Service::Runner }, on_exceptions: { condition: ->(*exceptions) do - next unless failure_for?("result.try.default") + next unless result["result.try.default"]&.exception next true if exceptions.empty? exceptions.any? { result["result.try.default"].exception.is_a?(_1) } end, diff --git a/lib/service/steps_inspector.rb b/lib/service/steps_inspector.rb index fcb4b79d069..5ab0c804e33 100644 --- a/lib/service/steps_inspector.rb +++ b/lib/service/steps_inspector.rb @@ -9,9 +9,11 @@ class Service::StepsInspector class Step attr_reader :step, :result, :nesting_level - delegate :name, to: :step + delegate :name, :result_key, to: :step delegate :failure?, :success?, :error, :raised_exception?, to: :step_result, allow_nil: true + alias error? failure? + def self.for(step, result, nesting_level: 0) class_name = "#{module_parent_name}::#{step.class.name.split("::").last.sub(/^(\w+)Step$/, "\\1")}" @@ -38,13 +40,18 @@ class Service::StepsInspector end def inspect - "#{" " * nesting_level}[#{inspect_type}] '#{name}' #{emoji}".rstrip + "#{" " * nesting_level}[#{inspect_type}] #{name}#{runtime} #{emoji}".rstrip end private + def runtime + return unless step_result&.__runtime__ + " (#{(step_result.__runtime__ * 1000).round(4)} ms)" + end + def step_result - result["result.#{type}.#{name}"] + result[result_key] end def result_emoji @@ -59,7 +66,7 @@ class Service::StepsInspector end def unexpected_result_text - return " <= expected to return true but got false instead" if failure? + return " <= expected to return true but got false instead" if error? " <= expected to return false but got true instead" end end @@ -97,11 +104,7 @@ class Service::StepsInspector end def inspect - "#{" " * nesting_level}[#{inspect_type}]" - end - - def step_result - nil + "#{" " * nesting_level}[#{inspect_type}]#{runtime}#{unexpected_result_emoji}" end end @@ -111,12 +114,12 @@ class Service::StepsInspector # @!visibility private class Try < Transaction - def error - step_result.exception.inspect + def error? + step_result.exception end - def step_result - result["result.#{type}.#{name}"] + def error + step_result.exception.full_message end end @@ -127,24 +130,40 @@ class Service::StepsInspector @result = result end - # Inspect the provided result object. - # Example output: - # [1/4] [model] 'channel' ✅ - # [2/4] [params] 'default' ✅ - # [3/4] [policy] 'check_channel_permission' ❌ - # [4/4] [step] 'change_status' - # @return [String] the steps of the result object with their state def inspect + output = <<~OUTPUT + Inspecting #{result.__service_class__} result object: + + #{execution_flow} + OUTPUT + output += "\nWhy it failed:\n\n#{error}" if error.present? + output + end + + # Example output: + # [1/4] [model] channel (0.02 ms) ✅ + # [2/4] [params] default (0.1 ms) ✅ + # [3/4] [policy] check_channel_permission ❌ + # [4/4] [step] change_status + # @return [String] the steps of the result object with their state + def execution_flow steps - .map + .filter_map .with_index do |step, index| + next if @encountered_error + @encountered_error = index + 1 if step.failure? "[#{format("%#{steps.size.to_s.size}s", index + 1)}/#{steps.size}] #{step.inspect}" end .join("\n") + .then do |output| + skipped_steps = steps.size - @encountered_error.to_i + next output unless @encountered_error && skipped_steps.positive? + "#{output}\n\n(#{skipped_steps} more steps not shown as the execution flow was stopped before reaching them)" + end end # @return [String, nil] the first available error, if any. def error - steps.detect(&:failure?)&.error + steps.detect(&:error?)&.error end end diff --git a/plugins/chat/plugin.rb b/plugins/chat/plugin.rb index 31da38f55ec..fda894c9325 100644 --- a/plugins/chat/plugin.rb +++ b/plugins/chat/plugin.rb @@ -450,7 +450,7 @@ after_initialize do ) if creator.failure? - Rails.logger.warn "[discourse-automation] Chat message failed to send:\n#{creator.inspect_steps.inspect}\n#{creator.inspect_steps.error}" + Rails.logger.warn "[discourse-automation] Chat message failed to send:\n#{creator.inspect_steps}" end end end diff --git a/plugins/chat/spec/fabricators/chat_fabricator.rb b/plugins/chat/spec/fabricators/chat_fabricator.rb index fd12a489b7b..c9841af6b95 100644 --- a/plugins/chat/spec/fabricators/chat_fabricator.rb +++ b/plugins/chat/spec/fabricators/chat_fabricator.rb @@ -114,7 +114,7 @@ Fabricator(:chat_message_with_service, class_name: "Chat::CreateMessage") do if result.failure? raise RSpec::Expectations::ExpectationNotMetError.new( "Service `#{resolved_class}` failed, see below for step details:\n\n" + - result.inspect_steps.inspect, + result.inspect_steps, ) end diff --git a/plugins/chat/spec/plugin_helper.rb b/plugins/chat/spec/plugin_helper.rb index e7b365b7d87..9e1c2f88264 100644 --- a/plugins/chat/spec/plugin_helper.rb +++ b/plugins/chat/spec/plugin_helper.rb @@ -47,7 +47,7 @@ module ChatSystemHelpers }, ) - raise "#{creator.inspect_steps.inspect}\n\n#{creator.inspect_steps.error}" if creator.failure? + raise creator.inspect_steps if creator.failure? last_message = creator.message_instance end @@ -64,7 +64,7 @@ end module ChatSpecHelpers def service_failed!(result) raise RSpec::Expectations::ExpectationNotMetError.new( - "Service failed, see below for step details:\n\n" + result.inspect_steps.inspect, + "Service failed, see below for step details:\n\n" + result.inspect_steps, ) end diff --git a/spec/lib/service/steps_inspector_spec.rb b/spec/lib/service/steps_inspector_spec.rb index 26a185b7836..1bc577562bd 100644 --- a/spec/lib/service/steps_inspector_spec.rb +++ b/spec/lib/service/steps_inspector_spec.rb @@ -45,24 +45,28 @@ RSpec.describe Service::StepsInspector do end end - describe "#inspect" do - subject(:output) { inspector.inspect.strip } + describe "#execution_flow" do + subject(:output) { inspector.execution_flow.strip.gsub(%r{ \(\d+\.\d+ ms\)}, "") } context "when service runs without error" do it "outputs all the steps of the service" do expect(output).to eq <<~OUTPUT.chomp - [ 1/10] [options] 'default' ✅ - [ 2/10] [model] 'model' ✅ - [ 3/10] [policy] 'policy' ✅ - [ 4/10] [params] 'default' ✅ + [ 1/10] [options] default ✅ + [ 2/10] [model] model ✅ + [ 3/10] [policy] policy ✅ + [ 4/10] [params] default ✅ [ 5/10] [transaction] - [ 6/10] [step] 'in_transaction_step_1' ✅ - [ 7/10] [step] 'in_transaction_step_2' ✅ + [ 6/10] [step] in_transaction_step_1 ✅ + [ 7/10] [step] in_transaction_step_2 ✅ [ 8/10] [try] - [ 9/10] [step] 'might_raise' ✅ - [10/10] [step] 'final_step' ✅ + [ 9/10] [step] might_raise ✅ + [10/10] [step] final_step ✅ OUTPUT end + + it "outputs time taken by each step" do + expect(inspector.execution_flow).to match(/\d+\.\d+ ms/) + end end context "when the model step is failing" do @@ -76,16 +80,10 @@ RSpec.describe Service::StepsInspector do it "shows the failing step" do expect(output).to eq <<~OUTPUT.chomp - [ 1/10] [options] 'default' ✅ - [ 2/10] [model] 'model' ❌ - [ 3/10] [policy] 'policy' - [ 4/10] [params] 'default' - [ 5/10] [transaction] - [ 6/10] [step] 'in_transaction_step_1' - [ 7/10] [step] 'in_transaction_step_2' - [ 8/10] [try] - [ 9/10] [step] 'might_raise' - [10/10] [step] 'final_step' + [ 1/10] [options] default ✅ + [ 2/10] [model] model ❌ + + (8 more steps not shown as the execution flow was stopped before reaching them) OUTPUT end end @@ -101,16 +99,11 @@ RSpec.describe Service::StepsInspector do it "shows the failing step" do expect(output).to eq <<~OUTPUT.chomp - [ 1/10] [options] 'default' ✅ - [ 2/10] [model] 'model' ✅ - [ 3/10] [policy] 'policy' ❌ - [ 4/10] [params] 'default' - [ 5/10] [transaction] - [ 6/10] [step] 'in_transaction_step_1' - [ 7/10] [step] 'in_transaction_step_2' - [ 8/10] [try] - [ 9/10] [step] 'might_raise' - [10/10] [step] 'final_step' + [ 1/10] [options] default ✅ + [ 2/10] [model] model ✅ + [ 3/10] [policy] policy ❌ + + (7 more steps not shown as the execution flow was stopped before reaching them) OUTPUT end end @@ -120,16 +113,12 @@ RSpec.describe Service::StepsInspector do it "shows the failing step" do expect(output).to eq <<~OUTPUT.chomp - [ 1/10] [options] 'default' ✅ - [ 2/10] [model] 'model' ✅ - [ 3/10] [policy] 'policy' ✅ - [ 4/10] [params] 'default' ❌ - [ 5/10] [transaction] - [ 6/10] [step] 'in_transaction_step_1' - [ 7/10] [step] 'in_transaction_step_2' - [ 8/10] [try] - [ 9/10] [step] 'might_raise' - [10/10] [step] 'final_step' + [ 1/10] [options] default ✅ + [ 2/10] [model] model ✅ + [ 3/10] [policy] policy ✅ + [ 4/10] [params] default ❌ + + (6 more steps not shown as the execution flow was stopped before reaching them) OUTPUT end end @@ -145,16 +134,15 @@ RSpec.describe Service::StepsInspector do it "shows the failing step" do expect(output).to eq <<~OUTPUT.chomp - [ 1/10] [options] 'default' ✅ - [ 2/10] [model] 'model' ✅ - [ 3/10] [policy] 'policy' ✅ - [ 4/10] [params] 'default' ✅ + [ 1/10] [options] default ✅ + [ 2/10] [model] model ✅ + [ 3/10] [policy] policy ✅ + [ 4/10] [params] default ✅ [ 5/10] [transaction] - [ 6/10] [step] 'in_transaction_step_1' ✅ - [ 7/10] [step] 'in_transaction_step_2' ❌ - [ 8/10] [try] - [ 9/10] [step] 'might_raise' - [10/10] [step] 'final_step' + [ 6/10] [step] in_transaction_step_1 ✅ + [ 7/10] [step] in_transaction_step_2 ❌ + + (3 more steps not shown as the execution flow was stopped before reaching them) OUTPUT end end @@ -170,16 +158,17 @@ RSpec.describe Service::StepsInspector do it "shows the failing step" do expect(output).to eq <<~OUTPUT.chomp - [ 1/10] [options] 'default' ✅ - [ 2/10] [model] 'model' ✅ - [ 3/10] [policy] 'policy' ✅ - [ 4/10] [params] 'default' ✅ + [ 1/10] [options] default ✅ + [ 2/10] [model] model ✅ + [ 3/10] [policy] policy ✅ + [ 4/10] [params] default ✅ [ 5/10] [transaction] - [ 6/10] [step] 'in_transaction_step_1' ✅ - [ 7/10] [step] 'in_transaction_step_2' ✅ + [ 6/10] [step] in_transaction_step_1 ✅ + [ 7/10] [step] in_transaction_step_2 ✅ [ 8/10] [try] - [ 9/10] [step] 'might_raise' 💥 - [10/10] [step] 'final_step' + [ 9/10] [step] might_raise 💥 + + (1 more steps not shown as the execution flow was stopped before reaching them) OUTPUT end end @@ -190,16 +179,16 @@ RSpec.describe Service::StepsInspector do it "adapts its output accordingly" do expect(output).to eq <<~OUTPUT.chomp - [ 1/10] [options] 'default' ✅ - [ 2/10] [model] 'model' ✅ - [ 3/10] [policy] 'policy' ✅ ⚠️ <= expected to return false but got true instead - [ 4/10] [params] 'default' ✅ + [ 1/10] [options] default ✅ + [ 2/10] [model] model ✅ + [ 3/10] [policy] policy ✅ ⚠️ <= expected to return false but got true instead + [ 4/10] [params] default ✅ [ 5/10] [transaction] - [ 6/10] [step] 'in_transaction_step_1' ✅ - [ 7/10] [step] 'in_transaction_step_2' ✅ + [ 6/10] [step] in_transaction_step_1 ✅ + [ 7/10] [step] in_transaction_step_2 ✅ [ 8/10] [try] - [ 9/10] [step] 'might_raise' ✅ - [10/10] [step] 'final_step' ✅ + [ 9/10] [step] might_raise ✅ + [10/10] [step] final_step ✅ OUTPUT end end @@ -216,16 +205,11 @@ RSpec.describe Service::StepsInspector do it "adapts its output accordingly" do expect(output).to eq <<~OUTPUT.chomp - [ 1/10] [options] 'default' ✅ - [ 2/10] [model] 'model' ✅ - [ 3/10] [policy] 'policy' ❌ ⚠️ <= expected to return true but got false instead - [ 4/10] [params] 'default' - [ 5/10] [transaction] - [ 6/10] [step] 'in_transaction_step_1' - [ 7/10] [step] 'in_transaction_step_2' - [ 8/10] [try] - [ 9/10] [step] 'might_raise' - [10/10] [step] 'final_step' + [ 1/10] [options] default ✅ + [ 2/10] [model] model ✅ + [ 3/10] [policy] policy ❌ ⚠️ <= expected to return true but got false instead + + (7 more steps not shown as the execution flow was stopped before reaching them) OUTPUT end end @@ -325,8 +309,31 @@ RSpec.describe Service::StepsInspector do end it "returns an error related to the exception" do - expect(error).to match(/RuntimeError: BOOM/) + expect(error).to match(/BOOM \([^(]*RuntimeError[^)]*\)/) end end end + + describe "#inspect" do + let(:parameter) { nil } + + it "outputs the service class name, the steps results and the specific error" do + expect(inspector.inspect.gsub(%r{ \(\d+\.\d+ ms\)}, "")).to eq(<<~OUTPUT) + Inspecting DummyService result object: + + [ 1/10] [options] default ✅ + [ 2/10] [model] model ✅ + [ 3/10] [policy] policy ✅ + [ 4/10] [params] default ❌ + + (6 more steps not shown as the execution flow was stopped before reaching them) + + Why it failed: + + #]> + + Provided parameters: {"parameter"=>nil} + OUTPUT + end + end end diff --git a/spec/support/service_matchers.rb b/spec/support/service_matchers.rb index 17d328cecb2..eb4dd75cfef 100644 --- a/spec/support/service_matchers.rb +++ b/spec/support/service_matchers.rb @@ -26,8 +26,7 @@ module ServiceMatchers private def error_message_with_inspection(message) - inspector = Service::StepsInspector.new(result) - "#{message}\n\n#{inspector.inspect}\n\n#{inspector.error}" + "#{message}\n\n#{result.inspect_steps}" end end @@ -88,8 +87,7 @@ module ServiceMatchers end def error_message_with_inspection(message) - inspector = Service::StepsInspector.new(result) - "#{message}\n\n#{inspector.inspect}\n\n#{inspector.error}" + "#{message}\n\n#{result.inspect_steps}" end def set_unexpected_result @@ -161,7 +159,7 @@ module ServiceMatchers end def step_failed? - super && result[step].exception.is_a?(exception) + result[step]&.exception&.is_a?(exception) end def step_not_existing_message @@ -211,12 +209,4 @@ module ServiceMatchers def run_successfully RunServiceSuccessfully.new end - - def inspect_steps(result) - inspector = Service::StepsInspector.new(result) - puts "Steps:" - puts inspector.inspect - puts "\nFirst error:" - puts inspector.error - end end