-
Notifications
You must be signed in to change notification settings - Fork 1.1k
Fix timing race condition in AwaitAssertAsync causing premature timeouts #7976
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from all commits
5a234b6
09b82d7
181cf76
d63e738
2c177e2
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -14,9 +14,6 @@ | |
|
|
||
| namespace Akka.TestKit | ||
| { | ||
| /// <summary> | ||
| /// TBD | ||
| /// </summary> | ||
| public abstract partial class TestKitBase | ||
| { | ||
| /// <summary> | ||
|
|
@@ -37,7 +34,7 @@ public abstract partial class TestKitBase | |
| public void AwaitAssert(Action assertion, TimeSpan? duration=null, TimeSpan? interval=null, CancellationToken cancellationToken = default) | ||
| { | ||
| AwaitAssertAsync(assertion, duration, interval, cancellationToken) | ||
| .WaitAndUnwrapException(); | ||
| .WaitAndUnwrapException(cancellationToken); | ||
| } | ||
|
|
||
| /// <inheritdoc cref="AwaitAssert(Action, TimeSpan?, TimeSpan?, CancellationToken)"/> | ||
|
|
@@ -62,16 +59,19 @@ public async Task AwaitAssertAsync(Action assertion, TimeSpan? duration=null, Ti | |
| } | ||
| catch(Exception) | ||
| { | ||
| var stopped = Now + t; | ||
| if (stopped >= stop) | ||
| { | ||
| Sys.Log.Warning("AwaitAssert failed, timeout [{0}] is over after [{1}] attempts and [{2}] elapsed time", max, attempts, stopped - start); | ||
| throw; | ||
| } | ||
|
|
||
| // Check timeout after delay to avoid check-then-act race condition | ||
| } | ||
| attempts++; | ||
| await Task.Delay(t, cancellationToken); | ||
|
|
||
| // Check if we've exceeded the timeout AFTER sleeping | ||
| if (Now > stop) | ||
|
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Now, after the delay has been completed, even if we're overdue on time we still check one final time on exit. |
||
| { | ||
| Sys.Log.Warning("AwaitAssert failed, timeout [{0}] is over after [{1}] attempts and [{2}] elapsed time", max, attempts, Now - start); | ||
| // Re-run the assertion one final time to get the actual exception | ||
| assertion(); | ||
| } | ||
|
|
||
| t = (stop - Now).Min(intervalValue); | ||
| } | ||
| } | ||
|
|
@@ -96,9 +96,11 @@ public async Task AwaitAssertAsync(Func<Task> assertion, TimeSpan? duration=null | |
| var intervalValue = interval.GetValueOrDefault(TimeSpan.FromMilliseconds(100)); | ||
| if(intervalValue == Timeout.InfiniteTimeSpan) intervalValue = TimeSpan.MaxValue; | ||
| intervalValue.EnsureIsPositiveFinite("interval"); | ||
| var start = Now; | ||
| var max = RemainingOrDilated(duration); | ||
| var stop = Now + max; | ||
| var t = max.Min(intervalValue); | ||
| var attempts = 0; | ||
| while(true) | ||
| { | ||
| cancellationToken.ThrowIfCancellationRequested(); | ||
|
|
@@ -109,10 +111,26 @@ public async Task AwaitAssertAsync(Func<Task> assertion, TimeSpan? duration=null | |
| } | ||
| catch(Exception) | ||
| { | ||
| if(Now + t >= stop) | ||
| throw; | ||
| // Check timeout after delay to avoid check-then-act race condition | ||
| } | ||
| attempts++; | ||
| await Task.Delay(t, cancellationToken); | ||
|
|
||
| // Check if we've exceeded the timeout AFTER sleeping | ||
| if (Now > stop) | ||
| { | ||
| try | ||
| { | ||
| await assertion(); | ||
| return; | ||
| } | ||
| catch (Exception ex) | ||
| { | ||
| Sys.Log.Warning(ex, "AwaitAssert failed, timeout [{0}] is over after [{1}] attempts and [{2}] elapsed time", max, attempts, Now - start); | ||
| throw; | ||
| } | ||
| } | ||
|
Comment on lines
120
to
132
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. My only problem is that this code logs a fail warning regardless if the extra assertion invocation failed or not.
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Yeah we should remove that
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. There were some other errors with this code too, like if the final assertion succeeded we'd end up running again |
||
|
|
||
| t = (stop - Now).Min(intervalValue); | ||
| } | ||
| } | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The problem here is that we don't get 1 last chance to test the assertion if the first attempt failed and took too long