| | | 1 | | using System.Globalization; |
| | | 2 | | using Microsoft.Extensions.Hosting; |
| | | 3 | | using Microsoft.Extensions.Logging; |
| | | 4 | | |
| | | 5 | | namespace AsyncResponse; |
| | | 6 | | |
| | | 7 | | /// <summary>Per-schedule options for <c>WithScheduledFlow</c>.</summary> |
| | | 8 | | public sealed class ScheduledFlowOptions |
| | | 9 | | { |
| | | 10 | | /// <summary>The time zone the cron expression is evaluated in. Default: UTC.</summary> |
| | | 11 | | public TimeZoneInfo TimeZone { get; set; } = TimeZoneInfo.Utc; |
| | | 12 | | |
| | | 13 | | /// <summary> |
| | | 14 | | /// Whether this schedule runs. Default: <c>true</c>. Set <c>false</c> to keep the registration |
| | | 15 | | /// (and its flow-type routing) while pausing new occurrences — e.g. per environment. |
| | | 16 | | /// </summary> |
| | | 17 | | public bool Enabled { get; set; } = true; |
| | | 18 | | |
| | | 19 | | /// <summary> |
| | | 20 | | /// How long the scheduler waits between attempts to re-drive an occurrence whose start job |
| | | 21 | | /// could not be published (a broker outage outlasting the start's own in-process retry |
| | | 22 | | /// ladder). The publish is the start's commit point, so such an occurrence has <em>no |
| | | 23 | | /// ledger</em> yet; a re-drive is the same idempotent start — it publishes the job, and the |
| | | 24 | | /// executor creates the run from it — and repeats at this interval until the job is published |
| | | 25 | | /// or the run is seen to exist and to have executed (another replica started it). Default: |
| | | 26 | | /// 30 seconds. |
| | | 27 | | /// </summary> |
| | | 28 | | public TimeSpan RedriveInterval { get; set; } = TimeSpan.FromSeconds(30); |
| | | 29 | | |
| | | 30 | | /// <summary> |
| | | 31 | | /// How far back the scheduler looks at startup for occurrences of this schedule whose ledger |
| | | 32 | | /// exists, is still <see cref="FlowRunStatus.Running"/>, and has never been executed |
| | | 33 | | /// (<see cref="FlowState.Attempts"/> is zero) — the shape a process crash between the ledger |
| | | 34 | | /// commit and the job publish leaves behind, and the shape an in-process re-drive queue lost |
| | | 35 | | /// with its process. Each such occurrence is re-driven (at most the 64 most recent in the |
| | | 36 | | /// window). A run that is merely queued behind a busy worker looks the same and is re-driven |
| | | 37 | | /// too, harmlessly: the duplicate wake-up is deduplicated by the execution lease. Default: |
| | | 38 | | /// 1 hour; zero disables the probe. |
| | | 39 | | /// </summary> |
| | | 40 | | public TimeSpan StartupRedriveWindow { get; set; } = TimeSpan.FromHours(1); |
| | | 41 | | } |
| | | 42 | | |
| | | 43 | | /// <summary> |
| | | 44 | | /// One registered cron schedule: the parsed-on-registration expression, its options, and the |
| | | 45 | | /// statically-typed start route captured at registration (AOT-safe — no type names, no reflection). |
| | | 46 | | /// </summary> |
| | | 47 | | internal sealed class ScheduledFlowRegistration |
| | | 48 | | { |
| | | 49 | | public required string Name { get; init; } |
| | | 50 | | public required string CronExpression { get; init; } |
| | | 51 | | public required ScheduledFlowOptions Options { get; init; } |
| | | 52 | | public required Func<IDurableFlows, string, DateTimeOffset, CancellationToken, Task> StartOccurrenceAsync { get; ini |
| | | 53 | | } |
| | | 54 | | |
| | | 55 | | /// <summary> |
| | | 56 | | /// Hosted scheduler for <c>WithScheduledFlow</c> registrations. One loop per schedule computes the |
| | | 57 | | /// next occurrence in the schedule's time zone, sleeps on the engine clock, and starts the flow |
| | | 58 | | /// with a <b>deterministic occurrence id</b> (<c>sched:{name}:{occurrenceUtc}</c>). |
| | | 59 | | /// <para> |
| | | 60 | | /// <b>Exactly-once per occurrence across replicas, with no coordinator:</b> every replica runs the |
| | | 61 | | /// same loop and computes the same occurrence id; the flow store's atomic create accepts exactly |
| | | 62 | | /// one, and the losers re-enqueue the same run (a duplicate wake-up the execution lease already |
| | | 63 | | /// dedups). Occurrences missed while every replica was down are <em>skipped</em> — on restart the |
| | | 64 | | /// loop resumes from "now", by design (an at-most-once schedule; the run history shows the gap). |
| | | 65 | | /// A late timer fire (seconds) still starts its own occurrence — only occurrences whose successor |
| | | 66 | | /// is already due are skipped. |
| | | 67 | | /// </para> |
| | | 68 | | /// <para> |
| | | 69 | | /// <b>A due occurrence whose start could not be published is never abandoned.</b> Skipping |
| | | 70 | | /// applies only to occurrences the loop never reached. An occurrence whose start job could not be |
| | | 71 | | /// published (<see cref="DurableFlowNotDispatchedException"/>: the broker outage outlasted the |
| | | 72 | | /// start's retry ladder — nothing was persisted, the publish is the start's commit point) is kept |
| | | 73 | | /// in an in-process re-drive queue and its idempotent start repeated every |
| | | 74 | | /// <see cref="ScheduledFlowOptions.RedriveInterval"/> until the job is published. Because that |
| | | 75 | | /// queue dies with the process, each loop also probes |
| | | 76 | | /// <see cref="ScheduledFlowOptions.StartupRedriveWindow"/> of recent occurrences at startup and |
| | | 77 | | /// re-drives any whose ledger is Running with zero attempts — a run whose wake-up was lost in |
| | | 78 | | /// transit (an early-ACK worker subscriber, a broker that dropped it) and that nothing else will |
| | | 79 | | /// find. |
| | | 80 | | /// </para> |
| | | 81 | | /// </summary> |
| | 28 | 82 | | internal sealed class ScheduledFlowService( |
| | 28 | 83 | | IDurableFlows _flows, |
| | 28 | 84 | | IEnumerable<ScheduledFlowRegistration> _registrations, |
| | 28 | 85 | | ILogger<ScheduledFlowService> _logger, |
| | 28 | 86 | | TimeProvider? _timeProvider = null) : BackgroundService |
| | | 87 | | { |
| | | 88 | | /// <summary> |
| | | 89 | | /// Longest single sleep between checks. Chunking keeps every armed delay far under the BCL |
| | | 90 | | /// timer ceiling and re-reads the clock hourly, so a suspended laptop's clock jump is honored |
| | | 91 | | /// within an hour instead of after a season. Time-zone RULES are not re-read while waiting: |
| | | 92 | | /// occurrences convert through the <see cref="TimeZoneInfo"/> captured at parse, whose |
| | | 93 | | /// adjustment rules are immutable (and the BCL caches OS zone data for the process lifetime), |
| | | 94 | | /// so an OS tz-database update only takes effect after a process restart. |
| | | 95 | | /// </summary> |
| | 2 | 96 | | private static readonly TimeSpan MaxSleepChunk = TimeSpan.FromHours(1); |
| | | 97 | | |
| | | 98 | | protected override async Task ExecuteAsync(CancellationToken stoppingToken) |
| | | 99 | | { |
| | 28 | 100 | | var registrations = _registrations.ToArray(); |
| | 28 | 101 | | if (registrations.Length == 0) |
| | 0 | 102 | | return; |
| | | 103 | | |
| | | 104 | | // WithScheduledFlow rejects duplicate names at registration; this is the defensive backstop |
| | | 105 | | // for hand-registered ScheduledFlowRegistration instances. A BackgroundService fault would |
| | | 106 | | // surface only in logs, so log-and-drop the duplicates rather than half-starting. |
| | 112 | 107 | | var duplicate = registrations.GroupBy(r => r.Name, StringComparer.Ordinal).FirstOrDefault(g => g.Count() > 1); |
| | 28 | 108 | | if (duplicate is not null) |
| | | 109 | | { |
| | 0 | 110 | | _logger.LogError( |
| | 0 | 111 | | "Two scheduled flows share the name '{Schedule}'. Schedule names key the deterministic occurrence ids; n |
| | 0 | 112 | | duplicate.Key); |
| | 0 | 113 | | return; |
| | | 114 | | } |
| | | 115 | | |
| | 28 | 116 | | var loops = registrations |
| | 28 | 117 | | .Where(registration => |
| | 28 | 118 | | { |
| | 42 | 119 | | if (registration.Options.Enabled) |
| | 40 | 120 | | return true; |
| | 28 | 121 | | |
| | 2 | 122 | | _logger.LogInformation("Scheduled flow '{Schedule}' is disabled; not scheduling occurrences.", registrat |
| | 2 | 123 | | return false; |
| | 28 | 124 | | }) |
| | 40 | 125 | | .Select(registration => RunScheduleAsync(registration, stoppingToken)) |
| | 28 | 126 | | .ToArray(); |
| | | 127 | | |
| | | 128 | | // Fail fast: Task.WhenAll would sit on one faulted loop until every other loop ended at |
| | | 129 | | // shutdown, degrading "fail the host" into a silently dead schedule while the app reports |
| | | 130 | | // healthy. Await completions one at a time so the first fault propagates immediately. |
| | 28 | 131 | | var pending = new List<Task>(loops); |
| | 68 | 132 | | while (pending.Count > 0) |
| | | 133 | | { |
| | 40 | 134 | | var finished = await Task.WhenAny(pending).ConfigureAwait(false); |
| | 40 | 135 | | pending.Remove(finished); |
| | 40 | 136 | | if (finished.IsFaulted) |
| | | 137 | | { |
| | | 138 | | // The first fault propagates and fails the host; the sibling loops keep running |
| | | 139 | | // until shutdown cancels them, no longer awaited by anyone. Observe their outcomes |
| | | 140 | | // so a second fault in the same outage window is logged with its exception instead |
| | | 141 | | // of dying as a finalizer-time unobserved-task event with no schedule context. |
| | 0 | 142 | | foreach (var sibling in pending) |
| | | 143 | | { |
| | 0 | 144 | | _ = sibling.ContinueWith( |
| | 0 | 145 | | static (task, state) => ((ILogger)state!).LogError( |
| | 0 | 146 | | task.Exception?.GetBaseException(), |
| | 0 | 147 | | "A scheduled-flow loop faulted while the scheduler was already failing."), |
| | 0 | 148 | | _logger, |
| | 0 | 149 | | CancellationToken.None, |
| | 0 | 150 | | TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously, |
| | 0 | 151 | | TaskScheduler.Default); |
| | | 152 | | } |
| | | 153 | | } |
| | | 154 | | |
| | 40 | 155 | | await finished.ConfigureAwait(false); |
| | | 156 | | } |
| | 28 | 157 | | } |
| | | 158 | | |
| | | 159 | | /// <summary> |
| | | 160 | | /// Upper bound on the in-process re-drive queue per schedule. An outage long enough to queue |
| | | 161 | | /// this many undispatched occurrences (a per-minute schedule down for four hours) is an |
| | | 162 | | /// operator incident; beyond it the OLDEST entries are dropped with an error log naming the |
| | | 163 | | /// flow id, so they stay re-drivable by hand. |
| | | 164 | | /// </summary> |
| | | 165 | | internal const int MaxUndispatchedOccurrences = 256; |
| | | 166 | | |
| | | 167 | | /// <summary>Most recent occurrences inside <see cref="ScheduledFlowOptions.StartupRedriveWindow"/> the startup prob |
| | | 168 | | internal const int MaxStartupProbes = 64; |
| | | 169 | | |
| | | 170 | | private sealed class UndispatchedOccurrence |
| | | 171 | | { |
| | 36 | 172 | | public required string FlowId { get; init; } |
| | 16 | 173 | | public required DateTimeOffset Occurrence { get; init; } |
| | 28 | 174 | | public required DateTimeOffset DueUtc { get; set; } |
| | | 175 | | |
| | | 176 | | /// <summary> |
| | | 177 | | /// <c>true</c> when the occurrence's start job has never been published: the start's |
| | | 178 | | /// publish is its commit point, so NO ledger exists for it (the shape a |
| | | 179 | | /// <see cref="DurableFlowNotDispatchedException"/> leaves behind). A re-drive that finds no |
| | | 180 | | /// ledger must then start the occurrence again, not conclude that its run has expired. |
| | | 181 | | /// <c>false</c> for an entry the startup probe queued from an EXISTING never-executed |
| | | 182 | | /// ledger, where an absent ledger on re-drive really does mean expired or deleted. |
| | | 183 | | /// </summary> |
| | 12 | 184 | | public required bool AwaitingFirstPublish { get; init; } |
| | | 185 | | } |
| | | 186 | | |
| | | 187 | | private enum RedriveOutcome |
| | | 188 | | { |
| | | 189 | | /// <summary>The wake-up is published, or the run no longer needs one; drop the entry.</summary> |
| | | 190 | | Settled, |
| | | 191 | | |
| | | 192 | | /// <summary>Still undispatched; try again after <see cref="ScheduledFlowOptions.RedriveInterval"/>.</summary> |
| | | 193 | | Retry |
| | | 194 | | } |
| | | 195 | | |
| | | 196 | | private async Task RunScheduleAsync(ScheduledFlowRegistration registration, CancellationToken stoppingToken) |
| | | 197 | | { |
| | 40 | 198 | | var timeProvider = _timeProvider ?? TimeProvider.System; |
| | | 199 | | CronSchedule schedule; |
| | | 200 | | try |
| | | 201 | | { |
| | 40 | 202 | | schedule = CronSchedule.Parse(registration.CronExpression, registration.Options.TimeZone); |
| | 40 | 203 | | } |
| | 0 | 204 | | catch (FormatException ex) |
| | | 205 | | { |
| | | 206 | | // Registration already validated the expression; reaching this means the expression |
| | | 207 | | // text was mutated afterwards. Fail the host rather than silently never firing. |
| | 0 | 208 | | throw new InvalidOperationException($"Scheduled flow '{registration.Name}' has an invalid cron expression.", |
| | | 209 | | } |
| | | 210 | | |
| | 40 | 211 | | var next = schedule.GetNextOccurrence(timeProvider.GetUtcNow()); |
| | 40 | 212 | | _logger.LogInformation( |
| | 40 | 213 | | "Scheduled flow '{Schedule}' ({Cron}, {TimeZone}): first occurrence at {NextOccurrence}.", |
| | 40 | 214 | | registration.Name, registration.CronExpression, registration.Options.TimeZone.Id, next); |
| | | 215 | | |
| | 40 | 216 | | var undispatched = new List<UndispatchedOccurrence>(); |
| | | 217 | | try |
| | | 218 | | { |
| | 40 | 219 | | await ProbeUndispatchedAtStartupAsync(registration, schedule, undispatched, timeProvider, stoppingToken).Con |
| | | 220 | | |
| | 155 | 221 | | while (!stoppingToken.IsCancellationRequested) |
| | | 222 | | { |
| | 155 | 223 | | var now = timeProvider.GetUtcNow(); |
| | 155 | 224 | | if (next is { } occurrence && occurrence <= now) |
| | | 225 | | { |
| | 22 | 226 | | if (!await StartOccurrenceAsync(registration, occurrence, stoppingToken).ConfigureAwait(false)) |
| | 4 | 227 | | Enqueue(undispatched, registration, occurrence, timeProvider.GetUtcNow()); |
| | | 228 | | |
| | | 229 | | // Strictly after the fired occurrence, then skip anything already due (missed |
| | | 230 | | // occurrences are dropped by policy, not replayed in a burst). |
| | 22 | 231 | | var resumeFrom = timeProvider.GetUtcNow(); |
| | 22 | 232 | | next = schedule.GetNextOccurrence(occurrence > resumeFrom ? occurrence : resumeFrom); |
| | 22 | 233 | | continue; |
| | | 234 | | } |
| | | 235 | | |
| | 133 | 236 | | await RedriveDueAsync(registration, undispatched, timeProvider, stoppingToken).ConfigureAwait(false); |
| | | 237 | | |
| | 133 | 238 | | if (next is null && undispatched.Count == 0) |
| | | 239 | | { |
| | 0 | 240 | | _logger.LogWarning( |
| | 0 | 241 | | "Scheduled flow '{Schedule}' ({Cron}) has no future occurrence (unsatisfiable expression); stopp |
| | 0 | 242 | | registration.Name, registration.CronExpression); |
| | 0 | 243 | | return; |
| | | 244 | | } |
| | | 245 | | |
| | | 246 | | // Wake for whichever comes first: the next occurrence or the earliest re-drive. |
| | 133 | 247 | | var wakeAt = next ?? DateTimeOffset.MaxValue; |
| | 274 | 248 | | foreach (var entry in undispatched) |
| | | 249 | | { |
| | 4 | 250 | | if (entry.DueUtc < wakeAt) |
| | 4 | 251 | | wakeAt = entry.DueUtc; |
| | | 252 | | } |
| | | 253 | | |
| | 133 | 254 | | now = timeProvider.GetUtcNow(); |
| | 133 | 255 | | if (wakeAt > now) |
| | | 256 | | { |
| | 133 | 257 | | var sleep = wakeAt - now; |
| | 133 | 258 | | await Task.Delay(sleep <= MaxSleepChunk ? sleep : MaxSleepChunk, timeProvider, stoppingToken).Config |
| | | 259 | | } |
| | | 260 | | } |
| | 0 | 261 | | } |
| | 40 | 262 | | catch (OperationCanceledException) when (stoppingToken.IsCancellationRequested) |
| | | 263 | | { |
| | | 264 | | // Host shutdown. |
| | 40 | 265 | | } |
| | 40 | 266 | | } |
| | | 267 | | |
| | | 268 | | /// <summary> |
| | | 269 | | /// Starts one occurrence. Returns <c>false</c> only when the occurrence's ledger is committed |
| | | 270 | | /// but its worker job was not published — the one outcome the loop must keep re-driving. |
| | | 271 | | /// </summary> |
| | | 272 | | private async Task<bool> StartOccurrenceAsync( |
| | | 273 | | ScheduledFlowRegistration registration, |
| | | 274 | | DateTimeOffset occurrence, |
| | | 275 | | CancellationToken stoppingToken) |
| | | 276 | | { |
| | 22 | 277 | | var flowId = OccurrenceFlowId(registration.Name, occurrence); |
| | | 278 | | try |
| | | 279 | | { |
| | 22 | 280 | | await registration.StartOccurrenceAsync(_flows, flowId, occurrence, stoppingToken).ConfigureAwait(false); |
| | 14 | 281 | | _logger.LogInformation("Scheduled flow '{Schedule}' started occurrence {FlowId}.", registration.Name, flowId |
| | 14 | 282 | | } |
| | 0 | 283 | | catch (OperationCanceledException) when (stoppingToken.IsCancellationRequested) |
| | | 284 | | { |
| | 0 | 285 | | throw; |
| | | 286 | | } |
| | 2 | 287 | | catch (DurableFlowIdConflictException ex) |
| | | 288 | | { |
| | | 289 | | // The deterministic id already exists with a DIFFERENT input: another replica won the |
| | | 290 | | // create with a value this replica's input factory did not reproduce. The occurrence |
| | | 291 | | // ran (exactly once) — only the factory's determinism is at fault, so say exactly that. |
| | | 292 | | // ONLY the dedicated conflict type gets this benign reading: the delegate also runs |
| | | 293 | | // the user's input factory, and a plain InvalidOperationException from it (or from the |
| | | 294 | | // store) means nothing was started — that is the generic failure logged below. |
| | 2 | 295 | | _logger.LogWarning( |
| | 2 | 296 | | ex, |
| | 2 | 297 | | "Scheduled flow '{Schedule}' occurrence {FlowId} was already started with different input — the input fa |
| | 2 | 298 | | registration.Name, flowId); |
| | 2 | 299 | | } |
| | 4 | 300 | | catch (DurableFlowNotDispatchedException ex) |
| | | 301 | | { |
| | | 302 | | // The start's publish failed after retries, so the occurrence was NOT started (the |
| | | 303 | | // publish is the start's commit point; nothing was persisted). Unlike a plain failure |
| | | 304 | | // this one is worth re-driving on its own: the id is deterministic and the start |
| | | 305 | | // idempotent, so repeating it publishes the job once the broker is back — and if the |
| | | 306 | | // publish had landed ambiguously, the same id dedupes against the run it created. |
| | 4 | 307 | | _logger.LogError( |
| | 4 | 308 | | ex, |
| | 4 | 309 | | "Scheduled flow '{Schedule}' could not publish the start job for occurrence {FlowId}; the occurrence is |
| | 4 | 310 | | registration.Name, flowId, registration.Options.RedriveInterval); |
| | 4 | 311 | | return false; |
| | | 312 | | } |
| | 2 | 313 | | catch (Exception ex) |
| | | 314 | | { |
| | | 315 | | // A failed start (store or transport outage) is this occurrence's loss only; the loop |
| | | 316 | | // lives on for the next one. Another replica may still have started it. |
| | 2 | 317 | | _logger.LogError(ex, "Scheduled flow '{Schedule}' failed to start occurrence {FlowId}.", registration.Name, |
| | 2 | 318 | | } |
| | | 319 | | |
| | 18 | 320 | | return true; |
| | 22 | 321 | | } |
| | | 322 | | |
| | | 323 | | private void Enqueue(List<UndispatchedOccurrence> undispatched, ScheduledFlowRegistration registration, DateTimeOffs |
| | | 324 | | { |
| | 4 | 325 | | var flowId = OccurrenceFlowId(registration.Name, occurrence); |
| | 8 | 326 | | foreach (var existing in undispatched) |
| | | 327 | | { |
| | 0 | 328 | | if (string.Equals(existing.FlowId, flowId, StringComparison.Ordinal)) |
| | 0 | 329 | | return; |
| | | 330 | | } |
| | | 331 | | |
| | 4 | 332 | | while (undispatched.Count >= MaxUndispatchedOccurrences) |
| | | 333 | | { |
| | 0 | 334 | | var dropped = undispatched[0]; |
| | 0 | 335 | | undispatched.RemoveAt(0); |
| | 0 | 336 | | _logger.LogError( |
| | 0 | 337 | | "Scheduled flow '{Schedule}' has {Count} undispatched occurrences queued for re-drive; dropping the olde |
| | 0 | 338 | | registration.Name, MaxUndispatchedOccurrences, dropped.FlowId); |
| | | 339 | | } |
| | | 340 | | |
| | 4 | 341 | | undispatched.Add(new UndispatchedOccurrence |
| | 4 | 342 | | { |
| | 4 | 343 | | FlowId = flowId, |
| | 4 | 344 | | Occurrence = occurrence, |
| | 4 | 345 | | DueUtc = now + registration.Options.RedriveInterval, |
| | 4 | 346 | | AwaitingFirstPublish = true |
| | 4 | 347 | | }); |
| | 4 | 348 | | } |
| | | 349 | | |
| | | 350 | | private async Task RedriveDueAsync( |
| | | 351 | | ScheduledFlowRegistration registration, |
| | | 352 | | List<UndispatchedOccurrence> undispatched, |
| | | 353 | | TimeProvider timeProvider, |
| | | 354 | | CancellationToken stoppingToken) |
| | | 355 | | { |
| | 278 | 356 | | for (var i = 0; i < undispatched.Count;) |
| | | 357 | | { |
| | 12 | 358 | | var entry = undispatched[i]; |
| | 12 | 359 | | if (entry.DueUtc > timeProvider.GetUtcNow()) |
| | | 360 | | { |
| | 4 | 361 | | i++; |
| | 4 | 362 | | continue; |
| | | 363 | | } |
| | | 364 | | |
| | 8 | 365 | | if (await RedriveAsync(registration, entry, stoppingToken).ConfigureAwait(false) == RedriveOutcome.Retry) |
| | | 366 | | { |
| | 0 | 367 | | entry.DueUtc = timeProvider.GetUtcNow() + registration.Options.RedriveInterval; |
| | 0 | 368 | | i++; |
| | | 369 | | } |
| | | 370 | | else |
| | | 371 | | { |
| | 8 | 372 | | undispatched.RemoveAt(i); |
| | | 373 | | } |
| | 8 | 374 | | } |
| | 133 | 375 | | } |
| | | 376 | | |
| | | 377 | | private async Task<RedriveOutcome> RedriveAsync( |
| | | 378 | | ScheduledFlowRegistration registration, |
| | | 379 | | UndispatchedOccurrence entry, |
| | | 380 | | CancellationToken stoppingToken) |
| | | 381 | | { |
| | | 382 | | FlowState? state; |
| | | 383 | | try |
| | | 384 | | { |
| | 8 | 385 | | state = await _flows.GetStateAsync(entry.FlowId, stoppingToken).ConfigureAwait(false); |
| | 8 | 386 | | } |
| | 0 | 387 | | catch (OperationCanceledException) when (stoppingToken.IsCancellationRequested) |
| | | 388 | | { |
| | 0 | 389 | | throw; |
| | | 390 | | } |
| | 0 | 391 | | catch (Exception ex) |
| | | 392 | | { |
| | 0 | 393 | | _logger.LogWarning(ex, "Scheduled flow '{Schedule}' could not load occurrence {FlowId} to re-drive it; retry |
| | 0 | 394 | | return RedriveOutcome.Retry; |
| | | 395 | | } |
| | | 396 | | |
| | 8 | 397 | | if (state is null) |
| | | 398 | | { |
| | 4 | 399 | | if (!entry.AwaitingFirstPublish) |
| | | 400 | | { |
| | 0 | 401 | | _logger.LogWarning("Scheduled flow '{Schedule}' occurrence {FlowId} no longer has a ledger (expired or d |
| | 0 | 402 | | return RedriveOutcome.Settled; |
| | | 403 | | } |
| | | 404 | | |
| | | 405 | | // Publish-first start: the failed publish persisted NOTHING, so "no ledger" is the |
| | | 406 | | // expected shape of an occurrence still waiting for its first successful publish — not |
| | | 407 | | // evidence that its run expired. Settling here (the pre-fix reading, written for the |
| | | 408 | | // old create-then-publish order) permanently lost every occurrence that fell due during |
| | | 409 | | // a broker outage: the queue held the id, the ledger it looked for had never existed, |
| | | 410 | | // and the startup probe cannot find a run that was never persisted either. |
| | 4 | 411 | | _logger.LogInformation("Scheduled flow '{Schedule}' occurrence {FlowId} has no ledger because its start job |
| | | 412 | | } |
| | 4 | 413 | | else if (state.Status != FlowRunStatus.Running || state.Attempts > 0) |
| | | 414 | | { |
| | | 415 | | // Another replica re-drove it (or its own wake-up arrived after all) and the run |
| | | 416 | | // executed: nothing left to publish. |
| | 0 | 417 | | _logger.LogInformation("Scheduled flow '{Schedule}' occurrence {FlowId} has been picked up ({Status}, {Attem |
| | 0 | 418 | | return RedriveOutcome.Settled; |
| | | 419 | | } |
| | | 420 | | |
| | | 421 | | try |
| | | 422 | | { |
| | 8 | 423 | | await registration.StartOccurrenceAsync(_flows, entry.FlowId, entry.Occurrence, stoppingToken).ConfigureAwai |
| | 8 | 424 | | _logger.LogInformation("Scheduled flow '{Schedule}' re-drove occurrence {FlowId}: its worker job is publishe |
| | 8 | 425 | | return RedriveOutcome.Settled; |
| | | 426 | | } |
| | 0 | 427 | | catch (OperationCanceledException) when (stoppingToken.IsCancellationRequested) |
| | | 428 | | { |
| | 0 | 429 | | throw; |
| | | 430 | | } |
| | 0 | 431 | | catch (DurableFlowNotDispatchedException ex) |
| | | 432 | | { |
| | 0 | 433 | | _logger.LogWarning(ex, "Scheduled flow '{Schedule}' could not publish the worker job for occurrence {FlowId} |
| | 0 | 434 | | return RedriveOutcome.Retry; |
| | | 435 | | } |
| | 0 | 436 | | catch (DurableFlowIdConflictException ex) |
| | | 437 | | { |
| | 0 | 438 | | _logger.LogWarning(ex, "Scheduled flow '{Schedule}' occurrence {FlowId} cannot be re-driven: the input facto |
| | 0 | 439 | | return RedriveOutcome.Settled; |
| | | 440 | | } |
| | 0 | 441 | | catch (Exception ex) |
| | | 442 | | { |
| | 0 | 443 | | _logger.LogError(ex, "Scheduled flow '{Schedule}' failed to re-drive occurrence {FlowId}; retrying after {Re |
| | 0 | 444 | | return RedriveOutcome.Retry; |
| | | 445 | | } |
| | 8 | 446 | | } |
| | | 447 | | |
| | | 448 | | /// <summary> |
| | | 449 | | /// Finds recent occurrences whose ledger is committed and Running with zero attempts — never |
| | | 450 | | /// executed — and queues them for an immediate re-drive: a start whose job was published and |
| | | 451 | | /// then lost in transit (an early-ACK worker subscriber, a broker that dropped it), which |
| | | 452 | | /// nothing else would ever look for, because the store has no enumeration. The in-process |
| | | 453 | | /// re-drive queue above does not survive a restart, and an occurrence whose publish was still |
| | | 454 | | /// failing when the process died left nothing persisted — this probe cannot find it either, so |
| | | 455 | | /// it is skipped like any other occurrence missed while no replica was up (documented; the run |
| | | 456 | | /// history shows the gap). Best-effort: a failed load ends the probe (the loop starts |
| | | 457 | | /// regardless). |
| | | 458 | | /// </summary> |
| | | 459 | | private async Task ProbeUndispatchedAtStartupAsync( |
| | | 460 | | ScheduledFlowRegistration registration, |
| | | 461 | | CronSchedule schedule, |
| | | 462 | | List<UndispatchedOccurrence> undispatched, |
| | | 463 | | TimeProvider timeProvider, |
| | | 464 | | CancellationToken stoppingToken) |
| | | 465 | | { |
| | 40 | 466 | | var window = registration.Options.StartupRedriveWindow; |
| | 40 | 467 | | if (window <= TimeSpan.Zero) |
| | 0 | 468 | | return; |
| | | 469 | | |
| | 40 | 470 | | var now = timeProvider.GetUtcNow(); |
| | 40 | 471 | | var candidates = RecentOccurrences(schedule, now, window, MaxStartupProbes); |
| | | 472 | | |
| | 2171 | 473 | | foreach (var occurrence in candidates) |
| | | 474 | | { |
| | 1046 | 475 | | var flowId = OccurrenceFlowId(registration.Name, occurrence); |
| | | 476 | | FlowState? state; |
| | | 477 | | try |
| | | 478 | | { |
| | 1046 | 479 | | state = await _flows.GetStateAsync(flowId, stoppingToken).ConfigureAwait(false); |
| | 1045 | 480 | | } |
| | 1 | 481 | | catch (OperationCanceledException) when (stoppingToken.IsCancellationRequested) |
| | | 482 | | { |
| | 1 | 483 | | throw; |
| | | 484 | | } |
| | 0 | 485 | | catch (Exception ex) |
| | | 486 | | { |
| | 0 | 487 | | _logger.LogWarning(ex, "Scheduled flow '{Schedule}' could not probe occurrence {FlowId} for an undispatc |
| | 0 | 488 | | return; |
| | | 489 | | } |
| | | 490 | | |
| | 1045 | 491 | | if (state is not { Status: FlowRunStatus.Running, Attempts: 0 }) |
| | | 492 | | continue; |
| | | 493 | | |
| | 4 | 494 | | _logger.LogWarning( |
| | 4 | 495 | | "Scheduled flow '{Schedule}' found occurrence {FlowId} committed but never executed (Running, 0 attempts |
| | 4 | 496 | | registration.Name, flowId); |
| | 4 | 497 | | undispatched.Add(new UndispatchedOccurrence { FlowId = flowId, Occurrence = occurrence, DueUtc = now, Awaiti |
| | 4 | 498 | | } |
| | 39 | 499 | | } |
| | | 500 | | |
| | | 501 | | /// <summary>First look-back <see cref="RecentOccurrences"/> tries; doubled until it holds enough occurrences.</summ |
| | 2 | 502 | | private static readonly TimeSpan InitialProbeLookback = TimeSpan.FromHours(1); |
| | | 503 | | |
| | | 504 | | /// <summary> |
| | | 505 | | /// The <paramref name="max"/> most recent occurrences in <c>(now - window, now]</c>, oldest |
| | | 506 | | /// first. The schedule only enumerates FORWARD, and the probe used to walk the whole window |
| | | 507 | | /// from its far end to find the few occurrences at its near end: <paramref name="max"/> |
| | | 508 | | /// bounded the list, not the walk, and <c>StartupRedriveWindow</c> has no ceiling — a |
| | | 509 | | /// per-minute schedule with a one-year window cost 525,600 cron evaluations at every startup |
| | | 510 | | /// (29 million when the window reached the epoch clamp), all but 64 results discarded, in a |
| | | 511 | | /// synchronous stretch ahead of the schedule's first occurrence. The look-back now starts |
| | | 512 | | /// small and doubles until it holds <paramref name="max"/> occurrences or covers the window, |
| | | 513 | | /// so the walk is proportional to what the probe keeps: a dense schedule stops after the |
| | | 514 | | /// first hour or two, and a sparse one reaches the full window in about twenty doublings of |
| | | 515 | | /// near-empty walks. The most recent occurrences of a shorter look-back are, by construction, |
| | | 516 | | /// the most recent occurrences of the whole window. |
| | | 517 | | /// </summary> |
| | | 518 | | internal static List<DateTimeOffset> RecentOccurrences(CronSchedule schedule, DateTimeOffset now, TimeSpan window, i |
| | | 519 | | { |
| | 56 | 520 | | var sinceEpoch = now - DateTimeOffset.UnixEpoch; |
| | 56 | 521 | | var fullLookback = window >= sinceEpoch ? sinceEpoch : window; |
| | 56 | 522 | | var lookback = fullLookback < InitialProbeLookback ? fullLookback : InitialProbeLookback; |
| | | 523 | | |
| | 160 | 524 | | while (true) |
| | | 525 | | { |
| | 216 | 526 | | var candidates = new List<DateTimeOffset>(); |
| | 216 | 527 | | var cursor = now - lookback; |
| | 7256 | 528 | | while (schedule.GetNextOccurrence(cursor) is { } occurrence && occurrence <= now) |
| | | 529 | | { |
| | 7040 | 530 | | candidates.Add(occurrence); |
| | 7040 | 531 | | if (candidates.Count > max) |
| | 3872 | 532 | | candidates.RemoveAt(0); |
| | 7040 | 533 | | cursor = occurrence; |
| | 7040 | 534 | | } |
| | | 535 | | |
| | 216 | 536 | | if (candidates.Count >= max || lookback >= fullLookback) |
| | 56 | 537 | | return candidates; |
| | | 538 | | |
| | 160 | 539 | | lookback = lookback > fullLookback - lookback ? fullLookback : lookback + lookback; |
| | | 540 | | } |
| | | 541 | | } |
| | | 542 | | |
| | | 543 | | internal static string OccurrenceFlowId(string name, DateTimeOffset occurrence) |
| | | 544 | | // Invariant culture: interpolation formats with CurrentCulture, whose default calendar can |
| | | 545 | | // rewrite the digits (Buddhist 25730615, UmAlQura 14520214) — replicas with different |
| | | 546 | | // cultures would then mint different ids for the same occurrence and both would run. |
| | 1108 | 547 | | => string.Create(CultureInfo.InvariantCulture, $"sched:{name}:{occurrence.UtcDateTime:yyyyMMdd'T'HHmmss'Z'}"); |
| | | 548 | | } |