Various time related fixes #178

nulltoken · 2025-01-25T12:56:11Z

Pull request description

Mostly fix TimeProvider isn't used everywhere #169
Additional freebies
- Cron expression helper for tests (built from most used expressions)
- Favor UTC over local date when logging
- Make JobRun.RunAt immutable

PR meta checklist

Pull request is targeted at main branch for code
Pull request is linked to all related issues, if any.

Code PR specific checklist

My code follows the code style of this project and AspNetCore coding guidelines.
My change requires a change to the documentation.
- I have updated the documentation accordingly.
I have updated the appropriate sub section in the CHANGELOG.md.
I have added, updated or removed tests to according to my changes.
- All tests passed.

codecov · 2025-01-25T13:00:50Z

Codecov Report

All modified and coverable lines are covered by tests ✅

Files with missing lines	Coverage Δ
src/NCronJob/Execution/StartupJobManager.cs	`94.11% <100.00%> (+0.17%)`	⬆️
src/NCronJob/Observer/ExecutionProgress.cs	`93.33% <100.00%> (+0.74%)`	⬆️
.../NCronJob/Observer/JobExecutionProgressObserver.cs	`96.07% <100.00%> (+0.33%)`	⬆️
src/NCronJob/Registry/IInstantJobRegistry.cs	`92.59% <100.00%> (+0.13%)`	⬆️
src/NCronJob/Registry/JobRun.cs	`98.71% <100.00%> (+0.08%)`	⬆️
src/NCronJob/Registry/JobState.cs	`77.77% <100.00%> (ø)`
src/NCronJob/Scheduler/JobProcessor.cs	`100.00% <100.00%> (ø)`
src/NCronJob/Scheduler/JobQueue.cs	`100.00% <100.00%> (+11.11%)`	⬆️
src/NCronJob/Scheduler/JobQueueManager.cs	`92.06% <100.00%> (-0.13%)`	⬇️
src/NCronJob/Scheduler/JobWorker.cs	`94.11% <100.00%> (+0.68%)`	⬆️

tests/NCronJob.Tests/NCronJobIntegrationTests.cs

linkdotnet

Really cool work @nulltoken !

src/NCronJob/Registry/JobRun.cs

src/NCronJob/Registry/JobState.cs

src/NCronJob/Scheduler/JobWorker.cs

tests/NCronJob.Tests/Cron.cs

linkdotnet · 2025-01-25T14:16:02Z

Interesting:WhileAwaitingJobTriggeringInstantJobShouldAnywayTriggerCronJob failed now twice in a row on the ubuntu runner (non-arm)

nulltoken · 2025-01-25T14:26:53Z

Interesting:WhileAwaitingJobTriggeringInstantJobShouldAnywayTriggerCronJob failed now twice in a row on the ubuntu runner (non-arm)

Seen this. I'm going to try and dig deeper in this test to understand where this comes from.

nulltoken · 2025-01-25T15:26:05Z

tests/NCronJob.Tests/NCronJobIntegrationTests.cs

@@ -317,6 +319,50 @@ public async Task WhileAwaitingJobTriggeringInstantJobShouldAnywayTriggerCronJob
        Assert.Equal(ExecutionState.OrchestrationCompleted, instantOrchestrationEvents[6].State);
        Assert.Equal(7, instantOrchestrationEvents.Count);

+        /*


@linkdotnet Below the captured timestamps of a CI failing build.

I'm slightly puzzled by the 24.04 arm result (first below). And the tests don't fail consistently.

Just for comparison, the latest passing 24.04 arm passing build output:

s 0 2000-01-01T00:00:00.0000000+00:00 i 0 2000-01-01T00:00:01.0000000+00:00 s 3 2000-01-01T00:00:01.0000000+00:00 i 2 2000-01-01T00:00:01.0499600+00:00 s 4 2000-01-01T00:00:01.0000000+00:00 i 6 2000-01-01T00:00:01.2258700+00:00

Compared to the failing one

24.04 arm s 0 2000-01-01T00:00:00.0000000+00:00 i 0 2000-01-01T00:00:01.0000000+00:00 s 3 2000-01-01T00:00:01.0000000+00:00 i 2 2000-01-01T00:00:01.0000000+00:00 <----- s 4 2000-01-01T00:00:01.0000000+00:00 i 6 2000-01-01T00:00:01.1924400+00:00

Given i 6 entries values aren't that far one from from another, I can't explain why i 2 hasn't moved forward even a little bit in that case.

I've thought about potential concurrency related issues with the FakeTimeProvider, but that seems out of context now that we're running xUnit v3 (https://github.com/dotnet/extensions/blob/main/src/Libraries/Microsoft.Extensions.TimeProvider.Testing/README.md#xunit-v3)

Maybe we can give NCronJob some time here?

FakeTimer.Advance(TimeSpan.FromSeconds(1)); // Added here not in the source code: // To enable processing time await Task.Delay(100); Guid instantOrchestrationId = provider.GetRequiredService<IInstantJobRegistry>().RunInstantJob<SimpleJob>(token: CancellationToken);

@linkdotnet Ok. I've found a workaround.

Below the latest timings from 24.04 arm

s 0 2000-01-01T00:00:00.0020000+00:00 i 0 2000-01-01T00:00:00.0080000+00:00 s 3 2000-01-01T00:00:00.0100000+00:00 i 2 2000-01-01T00:00:00.0603800+00:00 s 4 2000-01-01T00:00:00.0100000+00:00 i 6 2000-01-01T00:00:00.2286500+00:00

I've tweaked the setup of FakeTimer to benefit from AutoAdvanceAmount. This more or less simulates time passing between clock access.

nulltoken · 2025-01-25T16:38:54Z

@linkdotnet Everything seem back to green, now.

Does the tweak to FakeTimer fit you?

linkdotnet · 2025-01-26T08:09:28Z

@linkdotnet Everything seem back to green, now.

Does the tweak to FakeTimer fit you?

Interesting. I am not sure why advancing 1ms will make it seemingly stable.

the example you showed also has entries in the sub millisecond precision. Where is this coming from?

nulltoken · 2025-01-26T13:41:56Z

@linkdotnet Everything seem back to green, now.
Does the tweak to FakeTimer fit you?

Interesting. I am not sure why advancing 1ms will make it seemingly stable.

It makes sense as this test is only interested in the order in which events are triggered, not how much time they really took.

In the real life, the compute done by the lib takes some time to be done. In this test context, time is frozen and controlled by the test through Advance().

As every call to GetUtcNow() performs a slight nudge to the time, this emulates behind the scene what happens in a deployed environment and we don't end up with identical timestamps (except when they make sense (Orchestration Started/Completed relatively to initial and final events of an orchestration)).

the example you showed also has entries in the sub millisecond precision. Where is this coming from?

Not everything depends on the FakeTimer.

Every call to WaitForOrchestrationCompletion()

spends some time copying over the new events
awaits for some time (Task.Delay being also dependent to the precision of the underlying system clock)

linkdotnet · 2025-01-26T16:58:09Z

I totally get where you are driving at - I am just "surprised" by those times. So if we use the TimeProvider everywhere (doesn't matter how often called) I'd expect only increments of milliseconds and higher.

Anyhow - feel free to merge. My approval still stands :D

nulltoken · 2025-01-26T22:01:19Z

So if we use the TimeProvider everywhere (doesn't matter how often called) I'd expect only increments of milliseconds and higher.

Unless it's moved further through Advance()

https://github.com/dotnet/extensions/blob/main/src/Libraries/Microsoft.Extensions.TimeProvider.Testing/FakeTimeProvider.cs#L127-L137

linkdotnet · 2025-01-27T07:31:17Z

Fair - not sure where this is called.

Refactor cron expression usage in tests

5c0b299

nulltoken force-pushed the ntk/timeprovider branch 2 times, most recently from 21ceaad to eabe5ce Compare January 25, 2025 12:59

nulltoken requested a review from linkdotnet January 25, 2025 13:06

nulltoken commented Jan 25, 2025

View reviewed changes

tests/NCronJob.Tests/NCronJobIntegrationTests.cs Outdated Show resolved Hide resolved

linkdotnet reviewed Jan 25, 2025

View reviewed changes

src/NCronJob/Registry/JobRun.cs Show resolved Hide resolved

src/NCronJob/Registry/JobState.cs Outdated Show resolved Hide resolved

src/NCronJob/Scheduler/JobWorker.cs Show resolved Hide resolved

tests/NCronJob.Tests/Cron.cs Show resolved Hide resolved

nulltoken force-pushed the ntk/timeprovider branch from eabe5ce to 8972628 Compare January 25, 2025 14:07

linkdotnet approved these changes Jan 25, 2025

View reviewed changes

nulltoken force-pushed the ntk/timeprovider branch 3 times, most recently from 8cd09d5 to 88ff3ed Compare January 25, 2025 14:24

nulltoken force-pushed the ntk/timeprovider branch 3 times, most recently from 089a055 to 0592032 Compare January 25, 2025 15:19

nulltoken commented Jan 25, 2025

View reviewed changes

nulltoken force-pushed the ntk/timeprovider branch 3 times, most recently from a36b29a to c441361 Compare January 25, 2025 16:04

nulltoken added 5 commits January 25, 2025 17:16

Make ExecutionProgress TimeProvider aware

a6d9901

Make JobRun TimeProvider aware

6818889

Make JobWorker TimeProvider aware

255e4e3

Favor UTC over local date time

37392f7

Make JobRun.RunAt immutable

8b880de

nulltoken force-pushed the ntk/timeprovider branch 3 times, most recently from 7b84054 to 36c0ea3 Compare January 25, 2025 16:33

Simplify CI test command line

f21ca76

nulltoken force-pushed the ntk/timeprovider branch from 36c0ea3 to f21ca76 Compare January 25, 2025 16:37

nulltoken merged commit aa7b584 into main Jan 26, 2025
5 checks passed

nulltoken deleted the ntk/timeprovider branch January 26, 2025 18:10

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Various time related fixes #178

Various time related fixes #178

nulltoken commented Jan 25, 2025 •

edited

Loading

codecov bot commented Jan 25, 2025 •

edited

Loading

linkdotnet left a comment

linkdotnet commented Jan 25, 2025

nulltoken commented Jan 25, 2025

nulltoken Jan 25, 2025 •

edited

Loading

nulltoken Jan 25, 2025

nulltoken Jan 25, 2025

linkdotnet Jan 25, 2025

nulltoken Jan 25, 2025

nulltoken commented Jan 25, 2025

linkdotnet commented Jan 26, 2025

nulltoken commented Jan 26, 2025

linkdotnet commented Jan 26, 2025

nulltoken commented Jan 26, 2025

linkdotnet commented Jan 27, 2025

Various time related fixes #178

Various time related fixes #178

Conversation

nulltoken commented Jan 25, 2025 • edited Loading

Pull request description

PR meta checklist

Code PR specific checklist

codecov bot commented Jan 25, 2025 • edited Loading

Codecov Report

linkdotnet left a comment

Choose a reason for hiding this comment

linkdotnet commented Jan 25, 2025

nulltoken commented Jan 25, 2025

nulltoken Jan 25, 2025 • edited Loading

Choose a reason for hiding this comment

nulltoken Jan 25, 2025

Choose a reason for hiding this comment

nulltoken Jan 25, 2025

Choose a reason for hiding this comment

linkdotnet Jan 25, 2025

Choose a reason for hiding this comment

nulltoken Jan 25, 2025

Choose a reason for hiding this comment

nulltoken commented Jan 25, 2025

linkdotnet commented Jan 26, 2025

nulltoken commented Jan 26, 2025

linkdotnet commented Jan 26, 2025

nulltoken commented Jan 26, 2025

linkdotnet commented Jan 27, 2025

nulltoken commented Jan 25, 2025 •

edited

Loading

codecov bot commented Jan 25, 2025 •

edited

Loading

nulltoken Jan 25, 2025 •

edited

Loading