From 26d4278eab19749e41cdbdcfc148d0a9d4d171e2 Mon Sep 17 00:00:00 2001 From: Joe Eli McIlvain Date: Wed, 23 Mar 2022 17:21:15 -0700 Subject: [PATCH] Add ability to test asynchronous actions. Resolves #5. Now, if you need to test that something asynchronous happens, you can call `@ctx.wait_for_action("my action")` to let the test runner know that the test isn't over until the action completes. After the asynchronous action is finished, you can mark it as such by calling `@ctx.finished_action("my action")` to let the test runner know that the action is complete. You can add new actions to wait for at any time during a test, but the names must be unique in order for them to be differentiated. Once all awaited actions are marked as finished, the asynchronous test example is done running. If one or more actions don't get marked as finished in a timely manner, an informational message will be printed every 5 seconds for all open actions that are still being awaited. If the whole test suite will time out after 30 seconds. These time intervals will be able to be configured at runtime using the constant override mechanism mentioned in this ticket: https://github.com/savi-lang/savi/issues/161 --- manifest.savi | 7 ++++ spec/Spec.Assert.Spec.savi | 22 ++++++++++-- src/Spec.Assert.savi | 22 +++++++++--- src/Spec.Context.savi | 28 ++++++++++++--- src/Spec.Process.savi | 73 ++++++++++++++++++++++++++++++------- src/Spec.Reporter.savi | 74 +++++++++++++++++++++++++++++++------- src/Spec.Run.savi | 20 ++--------- src/Spec.Status.savi | 56 +++++++++++++++++++++++++---- src/_Runner.savi | 30 ++++++++++++++++ src/_Timer.savi | 19 ++++++++++ 10 files changed, 291 insertions(+), 60 deletions(-) create mode 100644 src/_Runner.savi create mode 100644 src/_Timer.savi diff --git a/manifest.savi b/manifest.savi index d5bcb37..357c733 100644 --- a/manifest.savi +++ b/manifest.savi @@ -4,6 +4,13 @@ :dependency Map v0 :from "github:savi-lang/Map" + :dependency Time v0 + :from "github:savi-lang/Time" + + :dependency Timer v0 + :from "github:savi-lang/Timer" + :depends on Time + :manifest bin "spec" :copies Spec :sources "spec/*.savi" diff --git a/spec/Spec.Assert.Spec.savi b/spec/Spec.Assert.Spec.savi index 66ba1cb..26ba2cc 100644 --- a/spec/Spec.Assert.Spec.savi +++ b/spec/Spec.Assert.Spec.savi @@ -61,11 +61,27 @@ assert error: _MaybeError.yes! - :it "can be called from another type that holds the spec context" - _OtherTypeThatCanAssert.new(@ctx) + :it "can be called from a class that holds the spec context" + class = _ClassThatCanAssert.new(@ctx) + class.assert_something -:class _OtherTypeThatCanAssert + :it "can be called asynchronously from another actor with waiting" + @ctx.wait_for_action("actor finished 1") + @ctx.wait_for_action("actor finished 2") + actor = _ActorThatCanAssert.new(@ctx) + actor.assert_something + actor.finished_action("actor finished 1") + actor.finished_action("actor finished 2") + +:class _ClassThatCanAssert :is Spec.Context.Holder :let ctx Spec.Context :new (@ctx) :fun assert_something: assert: True + +:actor _ActorThatCanAssert + :is Spec.Context.Holder + :let ctx Spec.Context + :new (@ctx) + :be assert_something: assert: True + :be finished_action(action String): @ctx.finished_action(action) diff --git a/src/Spec.Assert.savi b/src/Spec.Assert.savi index db05914..55c1ee6 100644 --- a/src/Spec.Assert.savi +++ b/src/Spec.Assert.savi @@ -20,7 +20,7 @@ success pos ) - ctx.process.enqueue(assert) + ctx._process.enqueue(assert) :fun non relation( caller Spec.Context.Holder @@ -40,7 +40,7 @@ Inspect[lhs] Inspect[rhs] ) - ctx.process.enqueue(assert) + ctx._process.enqueue(assert) :fun non type_relation( caller Spec.Context.Holder @@ -60,7 +60,7 @@ Inspect[lhs] rhs ) - ctx.process.enqueue(assert) + ctx._process.enqueue(assert) :fun non has_error( caller Spec.Context.Holder @@ -76,7 +76,7 @@ pos expects_error ) - ctx.process.enqueue(assert) + ctx._process.enqueue(assert) :fun file_and_line String line = Inspect[@pos.row + 1] @@ -178,3 +178,17 @@ ], "\n")) None + +:class val Spec.Assert.WaitForAction + :is Spec.Assert + :let action String + :new val (@spec, @example, @action, @pos): @success = True + :fun print_failure(env Env) + None + +:class val Spec.Assert.FinishedAction + :is Spec.Assert + :let action String + :new val (@spec, @example, @action, @pos): @success = True + :fun print_failure(env Env) + None diff --git a/src/Spec.Context.savi b/src/Spec.Context.savi index f27d60a..f2ad38a 100644 --- a/src/Spec.Context.savi +++ b/src/Spec.Context.savi @@ -1,9 +1,29 @@ +:trait box Spec.Context.Holder + :fun ctx Spec.Context + :class val Spec.Context :let env Env - :let process Spec.Process :let spec String :let example String - :new (@env, @process, @spec, @example) + :let _process Spec.Process + :let _runner _Runner.Any + :new (@env, @spec, @example, @_process, @_runner) -:trait box Spec.Context.Holder - :fun ctx Spec.Context + :fun wait_for_action( + action String + pos = source_code_position_of_argument action + ) + @_process.enqueue( + Spec.Assert.WaitForAction.new(@spec, @example, action, pos) + ) + + :fun finished_action( + action String + pos = source_code_position_of_argument action + ) + @_process.enqueue( + Spec.Assert.FinishedAction.new(@spec, @example, action, pos) + ) + + :fun dispose_when_done(actor) + @_runner.dispose_when_done(actor) diff --git a/src/Spec.Process.savi b/src/Spec.Process.savi index ead35b8..0331832 100644 --- a/src/Spec.Process.savi +++ b/src/Spec.Process.savi @@ -4,13 +4,40 @@ :var spec_count USize :let statuses: Map.Ordered(String, Spec.Status).new + :const timed_ping_seconds U64: 5 + :const timeout_seconds U64: 30 + :let _timer: _Timer.new(@) + :new (@env, @spec_count) - @reporter = Spec.Reporter.Linear.new(@env, @statuses, Spec.Reporter.Full.new(@env)) + @reporter = Spec.Reporter.Linear.new(@env, @statuses + Spec.Reporter.Full.new(@env, @statuses) + ) :fun non run(env, runners Array(Spec.Run.Any)) // TODO: shouldn't need this indirection process = @new(env, runners.size) runners.each -> (runner | runner.run(process)) + :be _timed_ping + @statuses.each -> (spec, spec_status | + spec_status.examples.each -> (example, example_status | + next unless example_status.is_waiting_to_end + + @reporter.example_timed_ping(spec, example) + ) + ) + + :be _timed_out + @statuses.each -> (spec, spec_status | + spec_status.examples.each -> (example, example_status | + next unless example_status.is_waiting_to_end + + @reporter.example_timed_out(spec, example) + example_status._runner.dispose + _Log.fail(@env) + ) + ) + @overall_ended + :be spec_began(spec String, expected_examples USize) // TODO: complain if spec is empty or duplicate status = Spec.Status.new(spec) @@ -18,45 +45,65 @@ @statuses[spec] = status @reporter.spec_began(spec) + :fun ref overall_began + @reporter.overall_began + + :fun ref overall_ended + @reporter.overall_ended + @_timer.dispose + :fun ref spec_ended(spec String) try ( status = @statuses[spec]! - status.ended = True + status.is_ended = True status.examples.each -> (example, example_status | - if (example_status.ended.not) ( + if example_status.is_ended.not ( _Log.bug(@env, "spec_ended before all of its examples ended") ) ) @reporter.spec_ended(spec) + + // If now all specs have ended, then we know we've ended overall. + if (@statuses.has_all -> (_, s | s.is_ended)) @overall_ended | _Log.bug(@env, "spec_ended before the spec_began") ) - :be example_began(spec String, example String): + :be example_began(spec String, example String, runner _Runner.Any): // TODO: complain if example is empty or duplicate try ( - @statuses[spec]!.examples[example] = Spec.Status.ForExample.new(example) + @statuses[spec]!.examples[example] = + Spec.Status.ForExample.new(example, runner) @reporter.example_began(spec, example) | _Log.bug(@env, "example_began before the spec_began") ) - :be example_close(spec String, example String): @example_ended(spec, example) + :be example_close(spec String, example String) + try ( + status = @statuses[spec]!.examples[example]! + status.is_synchronous_portion_ended = True + if status.is_ready_to_end @example_ended(spec, example) + | + _Log.bug(@env, "example_close before the example_began") + ) + :fun ref example_ended(spec String, example String) try ( status = @statuses[spec]! example_status = status.examples[example]! - example_status.ended = True + example_status.is_ended = True + example_status._runner.dispose + + skip = example_status.events.size == 0 + @reporter.example_ended(spec, example, skip) if ( status.examples.size >= status.expected_examples - && status.examples.has_all -> (_, es | es.ended) + && status.examples.has_all -> (_, es | es.is_ended) ) ( @spec_ended(spec) ) - - skip = example_status.events.size == 0 - @reporter.example_ended(spec, example, skip) | _Log.bug(@env, "example_ended before the example_began") ) @@ -69,8 +116,10 @@ if !event.success _Log.fail(@env) try ( - @statuses[spec]!.examples[example]!.events << event + status = @statuses[spec]!.examples[example]! + status.events << event @reporter.event(spec, example, event) + if status.is_ready_to_end @example_ended(spec, example) | _Log.bug(@env, "assert before the example_began and/or spec_began") ) diff --git a/src/Spec.Reporter.savi b/src/Spec.Reporter.savi index d8c60e3..667de72 100644 --- a/src/Spec.Reporter.savi +++ b/src/Spec.Reporter.savi @@ -1,14 +1,19 @@ :trait Spec.Reporter + :fun ref overall_began: None + :fun ref overall_ended: None :fun ref spec_began(spec String): None :fun ref spec_ended(spec String): None :fun ref example_began(spec String, example String): None :fun ref example_ended(spec String, example String, skip Bool): None + :fun ref example_timed_ping(spec String, example String): None + :fun ref example_timed_out(spec String, example String): None :fun ref event(spec String, example String, event Spec.Assert): None :class Spec.Reporter.Dots :is Spec.Reporter :let env Env - :new (@env) + :let statuses Map.Ordered(String, Spec.Status) + :new (@env, @statuses) :fun ref spec_ended(spec String) @env.err.write(";") @@ -30,7 +35,8 @@ :class Spec.Reporter.Full :is Spec.Reporter :let env Env - :new (@env) + :let statuses Map.Ordered(String, Spec.Status) + :new (@env, @statuses) :fun ref spec_began(spec String) @env.err.print(spec) @@ -52,20 +58,60 @@ event.print_failure(@env) ) + :fun ref example_timed_ping(spec String, example String) + try ( + status = @statuses[spec]!.examples[example]! + status.each_waiting_action_event -> (event | + @env.out.write("\n waiting for action: ") + @env.out.print(Inspect[event.action]) + @env.out.print(event.file_and_line) + ) + | + _Log.bug(@env, "no status for this example") + ) + + :fun ref example_timed_out(spec String, example String) + try ( + status = @statuses[spec]!.examples[example]! + status.each_waiting_action_event -> (event | + @env.out.write("\n Timed out waiting for action: ") + @env.out.print(Inspect[event.action]) + @env.out.print(event.file_and_line) + ) + | + _Log.bug(@env, "no status for this example") + ) + + :class Spec.Reporter.Linear + :is Spec.Reporter :let env Env - :let statuses: Map.Ordered(String, Spec.Status).new + :let statuses Map.Ordered(String, Spec.Status) :let inner Spec.Reporter :var current_spec: "" :var current_example: "" :new (@env, @statuses, @inner) + :fun ref overall_began: @inner.overall_began + :fun ref overall_ended: @inner.overall_ended :fun ref spec_began(spec String): @_changed :fun ref spec_ended(spec String): @_changed :fun ref example_began(spec String, example String): @_changed :fun ref example_ended(spec String, example String, skip Bool): @_changed :fun ref event(spec String, example String, event Spec.Assert): @_changed + :fun ref example_timed_ping(spec String, example String) + @_changed + return unless (spec == @current_spec) + return unless (example == @current_example) + @inner.example_timed_ping(spec, example) + + :fun ref example_timed_out(spec String, example String) + @_changed + return unless (spec == @current_spec) + return unless (example == @current_example) + @inner.example_timed_out(spec, example) + :fun ref _changed None // TODO: be able to infer return type for maybe-recursive functions // If no spec and example are selected for linear reporting, pick them now. if @current_spec .is_empty @_choose_next_spec @@ -82,7 +128,7 @@ :fun ref _choose_next_spec Bool // Find the name of the first spec whose status is not yet reported. @statuses.each_until -> (spec, status | - if (status.reported.not) ( + if (status.is_reported.not) ( @current_spec = spec @current_example = "" @inner.spec_began(@current_spec) @@ -97,7 +143,7 @@ try ( status = @statuses[@current_spec]! status.examples.each_until -> (example, example_status | - if (example_status.reported.not) ( + if example_status.is_reported.not ( @current_example = example @inner.example_began(@current_spec, @current_example) True @@ -124,13 +170,15 @@ example_status.events_reported += 1 ) - // If the example has finished, but has not yet been reported, report now. - if (example_status.ended && example_status.reported.not) ( - skip = example_status.events.size == 0 - @inner.example_ended(@current_spec, @current_example, skip) - example_status.reported = True + if example_status.is_ended ( + // If the example has finished, but has not yet been reported, report now. + if example_status.is_reported.not ( + skip = example_status.events.size == 0 + @inner.example_ended(@current_spec, @current_example, skip) + example_status.is_reported = True + ) - // Since we've finished reporting this example, look to pick up another. + // Since we've finished this example, look to pick up another. // We'll recurse into this function as many times as we can, // reporting as many consecutive examples for this spec as are complete. if @_choose_next_example @_report_examples_from_current @@ -144,14 +192,14 @@ status = @statuses[@current_spec]! // If the spec is finished, but we haven't reported, report it now. - if (status.ended && status.reported.not) ( + if (status.is_ended && status.is_reported.not) ( // Try to find an example not yet reported, and report it. // This call will recurse until all examples in the spec are reported. if @_choose_next_example @_report_examples_from_current // Now that all examples are reported, report the end of the spec. @inner.spec_ended(@current_spec) - status.reported = True + status.is_reported = True // Since we've finished reporting this spec, look to pick up another. // We'll recurse into this function as many times as we can, diff --git a/src/Spec.Run.savi b/src/Spec.Run.savi index 6d6cfee..24060b3 100644 --- a/src/Spec.Run.savi +++ b/src/Spec.Run.savi @@ -8,7 +8,7 @@ // TODO: avoid this indirection :fun _new_spec(process) A - A.new(Spec.Context.new(@env, process, A.describes, "")) + A.new(Spec.Context.new(@env, A.describes, "", process, _Runner.None.new)) :: Run all spec features for the Spec type indicated by the type argument, :: using the given Env to construct an instance of that Spec type. @@ -24,21 +24,5 @@ process.spec_began(A.describes, features.size) features.each -> (feature | - SpecExampleRunner(A).new(@env, process, feature) + _Runner(A).new(@env, process, feature) ) - -:actor SpecExampleRunner(A Spec) - :let example ReflectionFeatureOfType(A) - - :new (env, process, @example) - helper = Spec.Context.new(env, process, A.describes, @example.name) - spec = A.new(helper) - - process.example_began(A.describes, @example.name) - - called = @example.maybe_call_mutator(spec) - if called.not ( - _Log.bug(env, "failed to call a spec feature") - ) - - process.example_close(A.describes, @example.name) diff --git a/src/Spec.Status.savi b/src/Spec.Status.savi index dcf4ece..7e6c38a 100644 --- a/src/Spec.Status.savi +++ b/src/Spec.Status.savi @@ -2,14 +2,58 @@ :let examples: Map.Ordered(String, Spec.Status.ForExample).new :var expected_examples USize: 0 :let name String - :var ended Bool: False - :var reported Bool: False + :var is_ended Bool: False + :var is_reported Bool: False :new (@name) :class Spec.Status.ForExample + :let name String + :let _runner _Runner.Any :let events: Array(Spec.Assert).new :var events_reported USize: 0 - :let name String - :var ended Bool: False - :var reported Bool: False - :new (@name) + :var is_synchronous_portion_ended Bool: False + :var is_ended Bool: False + :var is_reported Bool: False + :new (@name, @_runner) + + :fun is_waiting_to_end Bool + !@is_ended && @is_synchronous_portion_ended && @has_any_waiting_actions + + :fun is_ready_to_end Bool + !@is_ended && @is_synchronous_portion_ended && !@has_any_waiting_actions + + :fun _waiting_action_counts + counts = Map(String, I32).new + @events.each -> (event | + case event <: ( + | Spec.Assert.WaitForAction | + // TODO: A more streamlined method in Map for doing this "upsert": + counts[event.action] = try (counts[event.action]! + 1 | 1) + | Spec.Assert.FinishedAction | + // TODO: A more streamlined method in Map for doing this "upsert": + counts[event.action] = try (counts[event.action]! - 1 | -1) + ) + ) + counts + + :fun has_any_waiting_actions + @_waiting_action_counts.has_any -> (action, count | count > 0) + + :fun each_waiting_action_event + :yields Spec.Assert.WaitForAction for None + counts = @_waiting_action_counts + counts.each -> (action, count | + next if (count <= 0) + + yielded_count = 0 + @events.reverse_each -> (event | + if (event <: Spec.Assert.WaitForAction) ( + next unless (event.action == action) + + yield event + + yielded_count += 1 + break if (yielded_count == count) + ) + ) + ) diff --git a/src/_Runner.savi b/src/_Runner.savi new file mode 100644 index 0000000..994a0ca --- /dev/null +++ b/src/_Runner.savi @@ -0,0 +1,30 @@ +:actor _Runner(A Spec) + :is _Runner.Any + :let _example ReflectionFeatureOfType(A) + + :new (env, process, @_example) + helper = Spec.Context.new(env, A.describes, @_example.name, process, @) + spec = A.new(helper) + + process.example_began(A.describes, @_example.name, @) + + called = @_example.maybe_call_mutator(spec) + if called.not ( + _Log.bug(env, "failed to call a spec feature") + ) + + process.example_close(A.describes, @_example.name) + +:trait tag _Disposable + :be dispose + +:trait tag _Runner.Any + :let _disposables: Array(_Disposable).new + :be dispose_when_done(actor _Disposable) + @_disposables << actor + + :be dispose + @_disposables.each -> (actor | actor.dispose) + +:actor _Runner.None + :is _Runner.Any diff --git a/src/_Timer.savi b/src/_Timer.savi new file mode 100644 index 0000000..655afdf --- /dev/null +++ b/src/_Timer.savi @@ -0,0 +1,19 @@ +:actor _Timer + :is Timer.Actor + :let timer Timer.Engine + :let process Spec.Process + + :var elapsed_seconds U64: 0 + + :new(@process) + interval = Time.Duration.seconds(@process.timed_ping_seconds) + @timer = Timer.Engine.new(@, interval) + + :fun ref timer_react @ + @elapsed_seconds += @process.timed_ping_seconds + if (@elapsed_seconds < @process.timeout_seconds) ( + @process._timed_ping + | + @process._timed_out + ) + @