Discource-C
/
discourse
mirror of https://github.com/discourse/discourse.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

DEV: Display better output when inspecting service steps 

This patch aims to improve the steps inspector output:
- The service class name is displayed at the top.
- Next to each step is displayed the time it took to run said step.
- Steps that didn’t run are hidden.
- `#inspect` automatically outputs the error when it is present.
This commit is contained in:
Loïc Guitaut 2024-12-03 18:15:54 +01:00 committed by Loïc Guitaut
parent 3ca7c5e438
commit a589b48f9a
8 changed files with 167 additions and 137 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

56
lib/service/base.rb
View File

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

2
lib/service/runner.rb
View File

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

63
lib/service/steps_inspector.rb
View File

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

2
plugins/chat/plugin.rb
View File

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

2
plugins/chat/spec/fabricators/chat_fabricator.rb
View File

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

4
plugins/chat/spec/plugin_helper.rb
View File

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

159
spec/lib/service/steps_inspector_spec.rb
View File

@ -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:
#<ActiveModel::Errors [#<ActiveModel::Error attribute=parameter, type=blank, options={}>]>
Provided parameters: {"parameter"=>nil}
OUTPUT
end
end
end

16
spec/support/service_matchers.rb
View File

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