ExecutionTimeAssertions works on cases where the code deadlocks, test… #842

peterekepeter · 2018-05-02T19:19:14Z

ExecutionTimeAssertions works on cases where the code deadlocks, tests finish as soon as conditions are met or failed instead of running indefinitely.

I implemented the feature where you can have test cases can run indefinitely or deadlock. The assertions will only wait until necessary for them to determine if test passes or fails, and they continue on. The only side effect is that if the thread runs indefinitely or deadlocks then the thread will stay hanging, but then again in these cases your test should fail.

IMPORTANT

The Pull Request is targeted at the master branch.
The code complies with the Coding Guidelines for C# 3.0, 4.0 and 5.0.
The changes are covered by a new or existing set of unit tests which follow the Arrange-Act-Assert syntax such as is used in this example.
If the contribution affects the documentation, please include your changes to documentation.md in this pull request so the documentation will appear on the website.

…s finish as soon as conditions are met or failed instead of running indefinitely.

peterekepeter · 2018-05-02T19:29:15Z

Looks like I have more work to do...

jnyrup · 2018-05-02T20:25:20Z

I like the idea to handle deadlocks and return early, when the criteria has been meet.
Maybe I'm missing out on something, but the code looks quite complicated and involving low-level stuff like Thread.

How about this approach:
In ExecutionTime wrap the Action inside a Task and expose it in an internal property.

internal Task Task { get; }

protected ExecutionTime(Action action, string actionDescription)
{
	ActionDescription = actionDescription;
	Task = Task.Run(action);
}

Add the following method to ExecutionTime;

internal TimeSpan Execute(TimeSpan timeout)
{
    var stopwatch = Stopwatch.StartNew();
    Task.Wait(timeout);
    stopwatch.Stop();

    return stopwatch.Elapsed;
}

Change ExecutionTimeAssertions to save the ExecutionTime object as a field instead of unwrapping it;

public ExecutionTimeAssertions(ExecutionTime executionTime)
{
    this.executionTime = executionTime;
}

In the assertion method like e.g. BeLessOrEqualTo we know for how long to run the task
run and wait the Task with a maximum timeout

public void BeLessOrEqualTo(TimeSpan maxDuration, string because = "", params object[] becauseArgs)
{
    TimeSpan duration = executionTime.Execute(maxDuration);

    Execute.Assertion
        .ForCondition(duration.CompareTo(maxDuration) <= 0)
    ...
}

peterekepeter · 2018-05-02T21:09:15Z

It seems to me you are assuming that there is only one condition can be applied to the ExectionTime. While that might be the case I can see that API is meant for multiple possible assertions on the same exection time, and I don't want to rerun the task for each of them, especially if it would end up blocking a thread or something.
But I will have to look for a Task based solution, the build failed because Thread cannot be used in one of the target platforms. I'll see if I can works something out based on your suggestion.

peterekepeter · 2018-05-02T21:35:46Z

I think I can make this work with Task I like most of your suggestion but assertion and execution are separate concerns, I don't want to specialize the execution for each type of assertion, it would unnecessarily complicate the code. And we don't just know for how long we need to run for BeLessOrEqualTo, we actually know it for all conditions.

peterekepeter · 2018-05-02T22:54:26Z

Ended up spending more time on this than expected, but build succeeded, verify the PR again and let me know if I should make other changes.

dennisdoomen · 2018-05-03T16:27:33Z

Tests/Shared.Specs/ExecutionTimeAssertionsSpecs.cs

+            //-----------------------------------------------------------------------------------------------------------
+            // Assert
+            //-----------------------------------------------------------------------------------------------------------
+            act.Should().Throw<XunitException>();


Shouldn't you at least verify part of the message. Because if your code doesn't work, you'll still get an XUnit exception if I'm not mistaken. Same for the other tests.

well, if my code doesnt work, the test never finishes to run, but fair enough, better to be safe

dennisdoomen · 2018-05-03T16:29:19Z

Src/FluentAssertions/Specialized/ExecutionTimeAssertions.cs

+                {
+                    break;
+                }
+                Task.Delay(rate).Wait();


I'm not sure this is safe in all environments. I've seen lockups on AppVeyor while waiting for Wait call. I would just use a Thread.Sleep instead.

yes, wanted to use that, originally and yes, .Result blocks a thread here, ill see if i can improve

Thread.Sleep() is available in net45+ and netstandard2.
For netstandard1.3 and netstandard1.6 there is System.Threading.Thread.

peterekepeter · 2018-05-03T20:15:55Z

So I think there is an even more elegant solution, the execution is already wrapped inside a Task.Run(), I just wait on it to finish with the polling rate as the timeout. If execution finishes earlier than that then the test finishes earlier as well, if not then the assertion passes or fail without needing for the execution to actually finish.

jnyrup · 2018-05-03T20:04:47Z

Src/FluentAssertions/Specialized/ExecutionTimeAssertions.cs

+
+        internal Exception Exception { get; private set; }
+
+        internal readonly Stopwatch Stopwatch;


I guess this should be private readonly Stopwatch stopwatch; so private and lowercase s.

jnyrup · 2018-05-03T20:11:20Z

Src/FluentAssertions/Specialized/ExecutionTimeAssertions.cs

+                {
+                    break;
+                }
+                Task.Delay(rate).Wait();


Thread.Sleep() is available in net45+ and netstandard2.
For netstandard1.3 and netstandard1.6 there is System.Threading.Thread.

jnyrup · 2018-05-03T20:15:12Z

Src/FluentAssertions/Specialized/ExecutionTimeAssertions.cs

+        /// <param name="condition">Condition to check un the current elapsed time.</param>
+        /// <param name="result">The expected result when polling is stopped.</param>
+        /// <param name="stopExecution">If polling is stopped then task execution is also stopped.</param>
+        /// <param name="rate">The rate at which the conition is re-checked.</param>


conition = condition

jnyrup · 2018-05-03T20:18:34Z

Src/FluentAssertions/Specialized/ExecutionTimeAssertions.cs

+        /// Checks the executing action if it satisfies a condition.
+        /// If the execution runs into an exeption, then this will rethrow it.
+        /// </summary>
+        /// <param name="condition">Condition to check un the current elapsed time.</param>


jnyrup · 2018-05-03T20:19:34Z

Src/FluentAssertions/Specialized/ExecutionTimeAssertions.cs

+        /// </summary>
+        /// <param name="condition">Condition to check un the current elapsed time.</param>
+        /// <param name="result">The expected result when polling is stopped.</param>
+        /// <param name="stopExecution">If polling is stopped then task execution is also stopped.</param>


stopExecution doesn't exists anymore?

jnyrup · 2018-05-03T20:19:36Z

Src/FluentAssertions/Specialized/ExecutionTimeAssertions.cs

+        /// <param name="rate">The rate at which the conition is re-checked.</param>
+        private void PollUntil(Func<TimeSpan, bool> condition, bool result, TimeSpan rate)
+        {
+            var forcedStop = false;


Is forcedStop ever set to true?

remnants from a feature that's not possible, I originally planned to use thread and kill it if not needed anymore :)

jnyrup · 2018-05-03T20:30:20Z

Src/FluentAssertions/Specialized/ExecutionTimeAssertions.cs

+                {
+                    break;
+                }
+                execution.Task.Wait(rate);


If the return value of Wait is intentionally ignored, yo could use _ = execution.Task.Wait(rate); to explicitly state the intention.

hah, this is a strange thing to do :)

I like to be explicit :)
I haven't tested it out, but this should help silence static analysers reporting unused return values, when I intentionally didn't use it.

peterekepeter · 2018-05-08T16:31:04Z

So it looks like everything is fixed! Is there anything more I should add?

dennisdoomen · 2018-05-08T20:41:25Z

As soon as @jnyrup approves the PR, it'll get merged.

jnyrup

Looks good, only one change needed.

The minor and suggestions are up to you.

jnyrup · 2018-05-09T09:54:58Z

Tests/Shared.Specs/ExecutionTimeAssertionsSpecs.cs

+            //-----------------------------------------------------------------------------------------------------------
+            // Act
+            //-----------------------------------------------------------------------------------------------------------
+            Action act = () => someAction.ExecutionTime().Should().BeLessThan(100.Milliseconds());


BeLessOrEqualTo

done, looks like github didn't get my change, check the source peterekepeter@8ab0e1b#diff-dd0f96bbe45e01b1feafc897a60a299dL114

jnyrup · 2018-05-09T09:58:16Z

Src/FluentAssertions/Specialized/ExecutionTimeAssertions.cs

@@ -133,12 +164,14 @@ public void BeCloseTo(TimeSpan expectedDuration, TimeSpan precision, string beca
        {
            var minimumValue = expectedDuration - precision;
            var maximumValue = expectedDuration + precision;
+
+            PollUntil(condition: elapsed => elapsed.CompareTo(maximumValue) < 0, result: false, rate: maximumValue);


Minor: extract to local variable as in the other Assertions.

jnyrup · 2018-05-09T10:04:16Z

Tests/Shared.Specs/ExecutionTimeAssertionsSpecs.cs

+            //-----------------------------------------------------------------------------------------------------------
+            act
+                .Should().Throw<XunitException>()
+                .And.Message.Should().StartWith(


Suggestion: use WithMessage.
E.g. WithMessage("*action should be less than 0.100s, but it required*").

nice, did not know about this one

jnyrup · 2018-05-09T10:11:27Z

Src/FluentAssertions/Specialized/ExecutionTimeAssertions.cs

+        /// If the execution runs into an exeption, then this will rethrow it.
+        /// </summary>
+        /// <param name="condition">Condition to check on the current elapsed time.</param>
+        /// <param name="result">The expected result when polling is stopped.</param>


Minor:
Maybe it's just me, but result indicates a computed value to me, whereas this is a stop condition.
So maybe rename to something like stopCondition, expectedResult or?

…stead of less than equal to.

…to expectedResult.

peterekepeter · 2018-05-14T18:01:56Z

updated, also changed all assertions from that file to use WithMessage(), it looks readable that way, and it's consistent

jnyrup · 2018-05-14T20:07:17Z

@peterekepeter I tried to poke around with the PR and noticed two things:

If we break out of while before the Task has completed, the stopWatch is not stopped, is that intentional?
As executionTime.ElapsedTime is called several times afterwards I guess we could hit a case, where the failure condition and failure message are inconsistent.
Task already has a IsCompleted property, it seems we can use that instead of IsRunning?

No tests failed when changing these two things, so I conclude that they are either compatible or we are missing a test.
Any thoughts?

…rtion.

peterekepeter · 2018-05-14T20:55:22Z

Yes it's intentional, I've added a test. Nothing stops the client code from calling multiple time assertions, so it should give consistent results.
It might seem the same, but I get tests failing. The way Tasks are handled might not always be how one might expect, so I think it's better to take the safe side with try finally and a boolean variable.

dennisdoomen · 2018-05-18T13:02:11Z

@jnyrup I assume you're taking care of this PR, right?

jnyrup · 2018-05-18T13:55:03Z

@dennisdoomen I will. I've just been short on spare time, but hope to review the last part during the weekend.

dennisdoomen · 2018-05-18T16:23:59Z

Don't worry. Was just checking you were not waiting for me.

jnyrup · 2018-05-20T15:31:26Z

As we can now break early from a long running action, the failure message is now a bit misleading if we broke out early.

E.g.

Action act = () => Thread.Sleep(10.Seconds());
act.ExecutionTime().Should().BeLessThan(50.Milliseconds());

Execution of the action should be less than 0.050s, but it required 0.052s and 30.7µs.

But we don't know how long it will take, we just know that it required more than 50 ms.

Maybe adjust parts of the failure message based on execution.IsRunning.
If task completed, keep the current failure message,
otherwise: adjust it to e.g. "Execution of the action should be less than 0.050s, but it did not finish after 0.052s and 30.7µs.".
I'm not sure whether to prefer "did not finish after" or "had not finished after", hopefully someone with better English skills than me can answer that.

…still running. Refactored PollUntil to return elapsed time and wether the action is still running or not.

peterekepeter · 2018-05-22T09:43:18Z

Okay, I've added a "more than" in case there is an early exit, and the message will contain "exactly" if it's not an early exit. This way it does not break existing tests. So you get messages like:
Execution of the action should be less than 0.100s, but it required more than 0.200s.
and in case it's not an early exit:
Execution of the action should be less than 0.100s, but it required exactly 0.200s.

peterekepeter · 2018-05-22T09:46:26Z

I don't understand AppVeyor's error message. I did not touch the test which failed.

jnyrup · 2018-05-24T19:38:55Z

@peterekepeter, thanks for the contribution to Fluent Assertions!
We appreciate the time you've put into reworking this PR to its merged shape.

peterekepeter · 2018-05-26T06:37:29Z

@jnyrup It was a long process, but finally!

dennisdoomen · 2018-05-26T06:49:40Z

So? Time for another release?

ExecutionTimeAssertions works on cases where the code deadlocks, test…

c1c3c99

…s finish as soon as conditions are met or failed instead of running indefinitely.

Reimplemented ExecutionTime with Task instead of Thread.

cd9a4b0

dennisdoomen reviewed May 3, 2018

View reviewed changes

peterekepeter added 2 commits May 3, 2018 23:01

Added exception messages to assertions.

dd0d13a

Reimplemented execution time pollin using Task.Wait(timeout)

a8e1334

jnyrup reviewed May 3, 2018

View reviewed changes

Coding style fixes, removed unused variable.

c5a31c2

jnyrup requested changes May 9, 2018

View reviewed changes

peterekepeter added 2 commits May 14, 2018 20:44

Changed tests to use WithMessage, fixed a test that used less than in…

8ab0e1b

…stead of less than equal to.

Moved condition to separate function in BeCloseTo and renamed result …

6443192

…to expectedResult.

jnyrup approved these changes May 14, 2018

View reviewed changes

Added test for checking if execution is stopped after first time asse…

57b6266

…rtion.

Updated exception messages to differentiate between actions that are …

0a83fd1

…still running. Refactored PollUntil to return elapsed time and wether the action is still running or not.

jnyrup merged commit 59bc1cd into fluentassertions:master May 24, 2018


		internal Exception Exception { get; private set; }

		internal readonly Stopwatch Stopwatch;

ExecutionTimeAssertions works on cases where the code deadlocks, test… #842

ExecutionTimeAssertions works on cases where the code deadlocks, test… #842

Conversation

peterekepeter commented May 2, 2018 • edited

IMPORTANT

peterekepeter commented May 2, 2018

jnyrup commented May 2, 2018

peterekepeter commented May 2, 2018 • edited

peterekepeter commented May 2, 2018

peterekepeter commented May 2, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

peterekepeter May 3, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

peterekepeter commented May 3, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

peterekepeter commented May 8, 2018

dennisdoomen commented May 8, 2018

jnyrup left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

peterekepeter May 14, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

peterekepeter commented May 14, 2018

jnyrup commented May 14, 2018

peterekepeter commented May 14, 2018

dennisdoomen commented May 18, 2018

jnyrup commented May 18, 2018

dennisdoomen commented May 18, 2018

jnyrup commented May 20, 2018

peterekepeter commented May 22, 2018

peterekepeter commented May 22, 2018

jnyrup commented May 24, 2018

peterekepeter commented May 26, 2018

dennisdoomen commented May 26, 2018

peterekepeter commented May 2, 2018 •

edited

peterekepeter commented May 2, 2018 •

edited

peterekepeter May 3, 2018 •

edited

peterekepeter May 14, 2018 •

edited