diff --git a/Directory.Build.props b/Directory.Build.props index 411c957..70a6ee8 100644 --- a/Directory.Build.props +++ b/Directory.Build.props @@ -55,6 +55,14 @@ CyberDrain https://github.com/CyberDrain/CRAFT git + + 0.0.0-dev diff --git a/Services/Bridges/WorkerMetricsBridge.cs b/Services/Bridges/WorkerMetricsBridge.cs index 33c341b..c095126 100644 --- a/Services/Bridges/WorkerMetricsBridge.cs +++ b/Services/Bridges/WorkerMetricsBridge.cs @@ -692,6 +692,27 @@ public static int CancelRun(string runName) public static bool DeleteJob(string jobId) => s_jobManager?.DeleteJob(jobId) ?? false; + /// + /// Empty the durable job queue — a maintenance/reset primitive. Returns the number of queue rows + /// removed, or -1 if the orchestrator is unavailable or the clear failed. In-flight work is + /// unaffected and Pending tasks may be re-driven, so pair with when the + /// intent is to STOP work rather than clear a wedged or corrupted queue. + /// PS usage: [Craft.Services.WorkerMetricsBridge]::ClearQueue(). + /// + public static int ClearQueue() + { + if (s_orchestrator is not { } orchestrator) return -1; + try + { + return Task.Run(() => orchestrator.ClearQueueAsync(CancellationToken.None)).GetAwaiter().GetResult(); + } + catch (Exception ex) + { + s_logger?.LogWarning(ex, "[WorkerMetrics] ClearQueue failed"); + return -1; + } + } + /// /// Change a queued job's priority. In the local buffer this re-enqueues at the new priority; for an /// unclaimed durable row it moves the row to the new priority bucket (keeping its age) and records diff --git a/Services/Configuration/CraftSettings.cs b/Services/Configuration/CraftSettings.cs index d429d8a..897d0ae 100644 --- a/Services/Configuration/CraftSettings.cs +++ b/Services/Configuration/CraftSettings.cs @@ -106,4 +106,7 @@ public class CraftSettings /// Realtime SSE channel (/.craft/events). See . public RealtimeSettings Realtime { get; set; } = new(); + + /// Startup phone-home usage telemetry. Off by default. See . + public TelemetrySettings Telemetry { get; set; } = new(); } diff --git a/Services/Configuration/OrchestratorSettings.cs b/Services/Configuration/OrchestratorSettings.cs index d49004f..437c14b 100644 --- a/Services/Configuration/OrchestratorSettings.cs +++ b/Services/Configuration/OrchestratorSettings.cs @@ -19,6 +19,16 @@ public class OrchestratorSettings /// public bool BatchStatusWrites { get; set; } = true; + /// + /// Coalesce SMALL task results (those that fit one Azure Table property) through the batched status + /// writer instead of a per-task upsert on the fan-out critical path. Each result is written BEFORE + /// its task's terminal marker in the same flush, so a result is always durable before the task is + /// counted done (and therefore before finalize/post-execution reads it). Large results keep the + /// directly-awaited chunked path. Default true; only applies when is + /// also true. Set false to fall back to the original per-task awaited result write. + /// + public bool BatchResultWrites { get; set; } = true; + /// /// When batching status writes, write the pre-invoke "Running" marker under a synchronous barrier so it /// is durable BEFORE the task invokes (batched with other concurrently-starting tasks). Preserves the diff --git a/Services/Configuration/RateLimitSettings.cs b/Services/Configuration/RateLimitSettings.cs index 2fb3ca9..c168026 100644 --- a/Services/Configuration/RateLimitSettings.cs +++ b/Services/Configuration/RateLimitSettings.cs @@ -25,8 +25,44 @@ public class RateLimitSettings /// public int QueueLimit { get; set; } + /// + /// Maximum requests a single app-only API client (client-credentials caller) may have occupying + /// the HTTP worker system at once — counting both those queued waiting for a runspace and those + /// already executing, since the limiter's lease spans the whole downstream pipeline. Keyed per + /// client (its AppId), so one automation cannot monopolise the pool and starve the interactive UI, + /// which is never limited by this. Over-limit requests are rejected immediately with 429 (no + /// concurrency queue); the caller retries on Retry-After. + /// + /// + /// 0 (default) = unlimited: the feature is off until a value is set. Distinct from + /// , which is a request-RATE cap; this is a simultaneous-in-flight cap. + /// Interactive (browser) callers are classified as UI and never counted here. + /// + /// + /// Env override: CRAFT_API_CONCURRENCY_LIMIT. + /// + public int ApiConcurrencyLimit { get; set; } + /// Resolved enabled state, honouring the CRAFT_RATELIMIT_ENABLED environment override. public bool IsEnabled => Enabled || string.Equals(Environment.GetEnvironmentVariable("CRAFT_RATELIMIT_ENABLED"), "true", StringComparison.OrdinalIgnoreCase); + + /// + /// Resolved per-client API concurrency cap, honouring the CRAFT_API_CONCURRENCY_LIMIT + /// environment override (which wins when it parses to a non-negative integer). 0 = unlimited/off. + /// + public int ResolvedApiConcurrencyLimit => + int.TryParse(Environment.GetEnvironmentVariable("CRAFT_API_CONCURRENCY_LIMIT"), + System.Globalization.NumberStyles.Integer, System.Globalization.CultureInfo.InvariantCulture, + out var fromEnv) && fromEnv >= 0 + ? fromEnv + : ApiConcurrencyLimit; + + /// + /// Whether the rate-limiter middleware needs to run at all: either the per-client rate limiter is + /// enabled, or an API concurrency cap is configured. When both are off, the middleware is skipped + /// entirely (no per-request limiter cost). + /// + public bool RequiresLimiterMiddleware => IsEnabled || ResolvedApiConcurrencyLimit > 0; } diff --git a/Services/Configuration/SkuProfile.cs b/Services/Configuration/SkuProfile.cs index 83ce805..6d2717d 100644 --- a/Services/Configuration/SkuProfile.cs +++ b/Services/Configuration/SkuProfile.cs @@ -32,4 +32,25 @@ public class SkuProfile /// Background worker pool size to apply when this profile matches. public int BgPoolSize { get; set; } + + /// + /// Optional GC heap hard limit, in MB, to apply when this profile matches. Three-way, mirroring the + /// CRAFT_GC_HEAP_LIMIT_MB override: + /// + /// Omitted / null (or negative) = no opinion, keep the process baseline (typically + /// the DOTNET_GCHeapHardLimit env var baked into the image for the smallest tier). + /// 0 = disable the cap entirely, so the GC uses the container's own memory + /// allowance — for tiers with more memory than the baked limit lets them use. + /// > 0 = set that many MB. + /// + /// The baked env var is consumed by the CLR before any managed code runs, so this is applied after + /// the fact via — raising or removing the limit is always + /// safe; a positive value the heap has already outgrown is refused and logged. + /// + /// Per-instance override: the CRAFT_GC_HEAP_LIMIT_MB env var wins over this value (a positive + /// value sets the cap; 0 disables the cap entirely), so an operator can hand-tune one host + /// without editing the fleet-wide profile list. + /// + /// + public int? GCHeapHardLimitMB { get; set; } } diff --git a/Services/Configuration/TelemetrySettings.cs b/Services/Configuration/TelemetrySettings.cs new file mode 100644 index 0000000..aa180a4 --- /dev/null +++ b/Services/Configuration/TelemetrySettings.cs @@ -0,0 +1,41 @@ +namespace Craft.Configuration; + +/// +/// Startup phone-home telemetry (App:Telemetry:*). One usage report per process start, storm +/// guarded so a crash loop cannot flood the ingest. See StartupTelemetryService. +/// +/// +/// Off by default: nothing is sent until an operator both enables it and supplies an +/// and an . The CRAFT_TELEMETRY_OPTOUT=1 environment +/// variable forces it off regardless of configuration. +/// +/// +public class TelemetrySettings +{ + /// Master switch. Off by default (privacy posture is an operator decision). + public bool Enabled { get; set; } + + /// Ingest URL, e.g. https://reporting.example.com/API/TelemetryIngest. No send without it. + public string? Endpoint { get; set; } + + /// Application id for this image (cipp, geoipdb, …). No send without it. + public string? AppId { get; set; } + + /// Storm-guard floor: at most one report per this many hours per instance. Floored at 1. + public int MinIntervalHours { get; set; } = 6; + + /// Outbound POST timeout in seconds. No retry — the next boot is the retry. + public int TimeoutSeconds { get; set; } = 10; + + /// Lower bound of the jittered startup delay, in seconds. + public int MinStartupDelaySeconds { get; set; } = 60; + + /// Upper bound of the jittered startup delay, in seconds. + public int MaxStartupDelaySeconds { get; set; } = 300; + + /// Table holding the per-instance storm-guard state (instanceId, lastSentUtc). + public string GuardTable { get; set; } = "CraftTelemetryGuard"; + + /// Optional shared token sent as X-Telemetry-Token to a token-gated ingest. + public string? Token { get; set; } +} diff --git a/Services/Configuration/WorkerSettings.cs b/Services/Configuration/WorkerSettings.cs index 7ed4dba..3317079 100644 --- a/Services/Configuration/WorkerSettings.cs +++ b/Services/Configuration/WorkerSettings.cs @@ -35,6 +35,23 @@ public class WorkerSettings /// public bool IgnoreSkuProfiles { get; set; } + /// + /// A second SkuProfiles matrix, selected when the env var named by is + /// present (set to a non-empty value); otherwise is used. Lets a deployment + /// ship one config with two sizings — e.g. a smaller per-instance matrix for instances packed onto a + /// shared App Service Plan — and pick between them with a single env var. Same matching rules as + /// . Ignored (falls back to ) when empty. + /// + public List SkuProfilesAlt { get; set; } = []; + + /// + /// Name of the env var whose presence selects instead of + /// (e.g. "CIPP_HOSTED"). Null/empty = the second matrix is never used. + /// Only presence matters — set the var (to any non-empty value) on the instances that should use the + /// second matrix, and leave it unset on the rest. Configurable so each app picks its own flag. + /// + public string? SkuProfilesAltEnv { get; set; } + /// /// Minimum .NET thread-pool worker/completion threads. 0 (default) = derive from the pool /// sizes, which is almost always what you want; set a number only to pin it. @@ -75,6 +92,29 @@ public class WorkerSettings /// public int BgTimeoutSeconds { get; set; } + /// + /// How long an incoming HTTP request waits for a free PowerShell runspace when every worker in the + /// HTTP pool is already busy, before it is shed with 503 "Server busy, please retry". + /// + /// + /// This is a load-shedding bound, NOT a capacity or execution knob. It does not add throughput — + /// under sustained saturation it only changes how long callers wait before the 503 (longer waits + /// hold connections and lengthen the tail). Its value is in absorbing brief bursts: a + /// request that would have got a worker a few seconds later completes instead of failing spuriously. + /// When 503s appear under steady load the levers are / + /// / a larger host, not this. + /// + /// + /// + /// Distinct from (which bounds how long a request may execute + /// once it holds a worker). 0 or negative = the built-in default of 30 seconds. + /// + /// + /// Env override: CRAFT_HTTP_QUEUE_TIMEOUT (seconds), which wins over this setting. + /// Resolved by CraftHostBuilderExtensions.ResolveHttpQueueTimeout. + /// + public int HttpQueueTimeoutSeconds { get; set; } + /// /// Environment variables to inject into every PowerShell runspace. /// Use "{ApiBasePath}" as a placeholder — it will be replaced with the resolved API directory at startup. diff --git a/Services/Hosting/CallerClassifier.cs b/Services/Hosting/CallerClassifier.cs new file mode 100644 index 0000000..daa62b6 --- /dev/null +++ b/Services/Hosting/CallerClassifier.cs @@ -0,0 +1,31 @@ +namespace Craft.Hosting; + +/// +/// Classifies a request as an app-only API client versus an interactive (UI) caller, from the +/// normalised principal headers writes. +/// +/// The distinction is load-bearing for the API concurrency cap: app-only automation must not be able +/// to monopolise the shared worker pool and starve interactive users, who are never limited by it. +/// The rule is exactly the one the hosted app already keys off — a client-credentials caller arrives +/// with x-ms-client-principal-idp: aad and its AppId (a GUID) as the principal name, whereas an +/// interactive Entra user is normalised to azureStaticWebApps. Both conditions are required so a +/// stray aad idp on a non-GUID principal is never misread as an API client. +/// +/// +public static class CallerClassifier +{ + /// + /// True when is an app-only API client (idp is aad and the + /// principal name parses as a GUID AppId). Depends on running after . + /// + public static bool IsApiClient(HttpContext context) + { + ArgumentNullException.ThrowIfNull(context); + + var idp = context.Request.Headers["x-ms-client-principal-idp"].ToString(); + if (!string.Equals(idp, "aad", StringComparison.OrdinalIgnoreCase)) return false; + + var name = context.Request.Headers["x-ms-client-principal-name"].ToString(); + return Guid.TryParse(name, out _); + } +} diff --git a/Services/Hosting/CraftHostBuilderExtensions.cs b/Services/Hosting/CraftHostBuilderExtensions.cs index a331e3d..8e7b5ab 100644 --- a/Services/Hosting/CraftHostBuilderExtensions.cs +++ b/Services/Hosting/CraftHostBuilderExtensions.cs @@ -11,6 +11,7 @@ using Craft.Services; using Craft.Setup; using Craft.Storage; +using Craft.Telemetry; using Microsoft.AspNetCore.ResponseCompression; using Microsoft.AspNetCore.Server.Kestrel.Core; using Microsoft.Extensions.Logging.Console; @@ -74,6 +75,31 @@ public static int ResolveMinThreads(CraftSettings settings) return Math.Max(baseline, forPools); } + /// The built-in HTTP worker-checkout wait when nothing overrides it. + public const int DefaultHttpQueueTimeoutSeconds = 30; + + /// + /// Resolves how long an HTTP request waits for a free runspace before it is shed with 503: + /// the CRAFT_HTTP_QUEUE_TIMEOUT env var (seconds) wins, then an explicit + /// Worker:HttpQueueTimeoutSeconds, otherwise the built-in + /// . See + /// for why this is a load-shedding bound and not a capacity knob. + /// + public static TimeSpan ResolveHttpQueueTimeout(WorkerSettings worker) + { + ArgumentNullException.ThrowIfNull(worker); + + if (int.TryParse( + Environment.GetEnvironmentVariable("CRAFT_HTTP_QUEUE_TIMEOUT"), + NumberStyles.Integer, CultureInfo.InvariantCulture, out var fromEnv) && fromEnv > 0) + return TimeSpan.FromSeconds(fromEnv); + + if (worker.HttpQueueTimeoutSeconds > 0) + return TimeSpan.FromSeconds(worker.HttpQueueTimeoutSeconds); + + return TimeSpan.FromSeconds(DefaultHttpQueueTimeoutSeconds); + } + /// /// Kestrel limits: request timeouts, HTTP/2 tuning, and the DoS-relevant caps (body size, /// connection count, slow-loris minimum data rates). The caps apply regardless of the timeout. @@ -243,6 +269,15 @@ public static IServiceCollection AddCraftServices(this IServiceCollection servic return new ContainerHealthMonitor(logger, health); }); + // Startup telemetry emitter. Registered on EVERY node (not just Background) so a frontend+api + // node still reports; the service self-gates on role, config, and the persisted storm guard, + // and fires at most once per process. The roles are made injectable here for it to report + // host.roles, and IHttpClientFactory for the single outbound POST. + services.AddSingleton(roles); + services.AddHttpClient(); + services.AddSingleton(); + services.AddHostedService(sp => sp.GetRequiredService()); + return services; } @@ -268,9 +303,16 @@ public static int ResolveRetryAfterSeconds(RateLimitLease lease, TimeSpan window } /// - /// Per-client fixed-window rate limiter so a single caller cannot exhaust the small HTTP worker - /// pool. Enabled by default; turn off with App:RateLimit:Enabled=false. Throttled requests - /// get a 429 carrying Retry-After. + /// The request limiter, a chain of up to two partitioned limiters sharing one 429 + Retry-After + /// rejection path: + /// + /// A per-client fixed-window rate limiter (on by default) so a single + /// caller cannot exhaust the small HTTP worker pool; turn off with App:RateLimit:Enabled=false. + /// A per-client concurrency cap on app-only API callers + /// (App:RateLimit:ApiConcurrencyLimit, off by default) so one automation cannot hold every + /// runspace at once and starve the interactive UI, which is never capped. + /// + /// The middleware is skipped entirely when neither is active. /// public static IServiceCollection AddCraftRateLimiter( this IServiceCollection services, CraftSettings settings) @@ -278,9 +320,10 @@ public static IServiceCollection AddCraftRateLimiter( ArgumentNullException.ThrowIfNull(services); ArgumentNullException.ThrowIfNull(settings); - if (!settings.RateLimit.IsEnabled) return services; + var rl = settings.RateLimit; + if (!rl.RequiresLimiterMiddleware) return services; - var window = TimeSpan.FromSeconds(Math.Max(1, settings.RateLimit.WindowSeconds)); + var window = TimeSpan.FromSeconds(Math.Max(1, rl.WindowSeconds)); services.AddRateLimiter(options => { @@ -291,22 +334,77 @@ public static IServiceCollection AddCraftRateLimiter( // honour unprompted, so emitting it is what makes the limit self-documenting. options.OnRejected = (context, _) => { + var retryAfter = ResolveRetryAfterSeconds(context.Lease, window); context.HttpContext.Response.Headers.RetryAfter = - ResolveRetryAfterSeconds(context.Lease, window) - .ToString(CultureInfo.InvariantCulture); + retryAfter.ToString(CultureInfo.InvariantCulture); + + // A 429 is otherwise invisible — the caller sees it, the operator does not. Log the + // client the limit fired for (the same partition key the limiter counts against) so a + // throttled integration or a runaway loop can be identified. Warning, not Error: this + // is an expected, client-caused outcome, but one worth surfacing. Resolved per + // rejection because service registration has no built provider yet; CreateLogger is + // cheap and the factory caches per category. Never let logging break the response. + try + { + context.HttpContext.RequestServices.GetService()? + .CreateLogger("Craft.Hosting.RateLimiter") + .LogWarning( + "Rate limit exceeded — 429 for {Client} on {Method} {Path}; Retry-After {RetryAfter}s", + RateLimitPartitionKey.Resolve(context.HttpContext), + context.HttpContext.Request.Method, + context.HttpContext.Request.Path.Value, + retryAfter); + } + catch { /* logging must never turn a throttle into a 500 */ } + return ValueTask.CompletedTask; }; - options.GlobalLimiter = PartitionedRateLimiter.Create(context => - RateLimitPartition.GetFixedWindowLimiter( - RateLimitPartitionKey.Resolve(context), - _ => new FixedWindowRateLimiterOptions - { - PermitLimit = Math.Max(1, settings.RateLimit.PermitPerWindow), - Window = window, - QueueLimit = Math.Max(0, settings.RateLimit.QueueLimit), - QueueProcessingOrder = QueueProcessingOrder.OldestFirst, - })); + // Built as a chain so a request must satisfy every active limiter. Order is immaterial — + // rejection by either sheds the request through the one OnRejected above. + var limiters = new List>(2); + + if (rl.IsEnabled) + { + // Per-client request RATE. Partition key is the authenticated principal (else address). + limiters.Add(PartitionedRateLimiter.Create(context => + RateLimitPartition.GetFixedWindowLimiter( + RateLimitPartitionKey.Resolve(context), + _ => new FixedWindowRateLimiterOptions + { + PermitLimit = Math.Max(1, rl.PermitPerWindow), + Window = window, + QueueLimit = Math.Max(0, rl.QueueLimit), + QueueProcessingOrder = QueueProcessingOrder.OldestFirst, + }))); + } + + var apiConcurrency = rl.ResolvedApiConcurrencyLimit; + if (apiConcurrency > 0) + { + // Per-client CONCURRENCY on app-only API callers only. The lease is held for the whole + // downstream pipeline, so a permit covers both the wait for a runspace and execution — + // that is what makes this cap "in flight + queued for a worker" rather than just one. + limiters.Add(PartitionedRateLimiter.Create(context => + { + if (!CallerClassifier.IsApiClient(context)) + return RateLimitPartition.GetNoLimiter("ui"); + + // Keyed on the AppId so each client's budget is its own, not shared across clients. + return RateLimitPartition.GetConcurrencyLimiter( + context.Request.Headers["x-ms-client-principal-name"].ToString(), + _ => new ConcurrencyLimiterOptions + { + PermitLimit = apiConcurrency, + QueueLimit = 0, // fail fast: the excess is rejected, not parked + QueueProcessingOrder = QueueProcessingOrder.OldestFirst, + }); + })); + } + + options.GlobalLimiter = limiters.Count == 1 + ? limiters[0] + : PartitionedRateLimiter.CreateChained(limiters.ToArray()); }); return services; diff --git a/Services/Hosting/Endpoints/JobEndpoints.cs b/Services/Hosting/Endpoints/JobEndpoints.cs deleted file mode 100644 index 8aaa277..0000000 --- a/Services/Hosting/Endpoints/JobEndpoints.cs +++ /dev/null @@ -1,117 +0,0 @@ -using Craft.Orchestration; -using Craft.PowerShellHost; - -namespace Craft.Hosting.Endpoints; - -/// -/// Job and run status API. Served directly from C# against the in-memory job manager, deliberately -/// bypassing the PowerShell pool — these are polled by dashboards during a fan-out, exactly when the -/// worker pool is busiest and least able to spare a runspace. -/// -public static class JobEndpoints -{ - /// Maps the /API/jobs/* and /API/runs/* routes. - public static WebApplication MapCraftJobEndpoints(this WebApplication app) - { - ArgumentNullException.ThrowIfNull(app); - - var jobManager = app.Services.GetRequiredService(); - var orchestrator = app.Services.GetRequiredService(); - var bgLimiter = app.Services.GetRequiredService(); - var pool = app.Services.GetRequiredService(); - var queueStatus = app.Services.GetRequiredService(); - - app.MapGet("/API/jobs/summary", async (HttpContext context, CancellationToken ct) => - { - context.Response.ContentType = "application/json"; - return Results.Ok(await queueStatus.GetSummaryAsync(ct)); - }); - - // Worker-allocation snapshot: JobManager queue/active, the concurrency limiter's live gate, and - // the BG pool's busy/idle workers. Poll it during a fan-out to watch the ramp, worker - // utilisation and I/O idle over time. Polled at 4 Hz by the perf harness, so the durable-queue - // numbers come from the cached snapshot (GetCached never blocks on storage). - app.MapGet("/API/jobs/allocation", () => - { - var durable = queueStatus.GetCached(); - return Results.Json(new - { - jm = new - { - active = jobManager.ActiveCount, - queued = jobManager.QueuedCount, - maxConcurrency = jobManager.MaxConcurrency, - }, - queue = new - { - unclaimed = durable?.Unclaimed ?? 0, - claimed = durable?.Claimed ?? 0, - total = durable?.Total ?? 0, - ageSeconds = durable?.AgeSeconds, - }, - limiter = new - { - currentMax = bgLimiter.CurrentMax, - effectiveMax = bgLimiter.EffectiveMax, - overSubscribe = bgLimiter.OverSubscribe, - burst = bgLimiter.BurstToCeiling, - active = bgLimiter.Active, - waiting = bgLimiter.Waiting, - httpThrottled = bgLimiter.IsHttpThrottled, - }, - pool = new - { - bgBusy = pool.BgPoolSize - pool.BgAvailable, - bgTotal = pool.BgPoolSize, - bgAvail = pool.BgAvailable, - httpAvail = pool.HttpAvailable, - }, - }); - }); - - app.MapGet("/API/jobs/runs", async (HttpContext context, CancellationToken ct) => - { - context.Response.ContentType = "application/json"; - return Results.Ok(await queueStatus.GetRunSummariesAsync(ct)); - }); - - app.MapGet("/API/jobs/list", async (HttpContext context, CancellationToken ct) => - { - var runName = context.Request.Query["runName"].ToString(); - var status = context.Request.Query["status"].ToString(); - var limit = int.TryParse(context.Request.Query["limit"].ToString(), out var l) ? l : 100; - - var jobs = await queueStatus.GetJobDetailsAsync( - string.IsNullOrEmpty(runName) ? null : runName, - string.IsNullOrEmpty(status) ? null : status, - limit, ct); - - context.Response.ContentType = "application/json"; - return Results.Ok(jobs); - }); - - app.MapPost("/API/runs/cancel", async (HttpContext context) => - { - var name = context.Request.Query["name"].ToString(); - if (string.IsNullOrEmpty(name)) - return Results.BadRequest(new { error = "name parameter is required" }); - - var (found, cancelledCount) = await orchestrator.CancelRunAsync(name); - - // Callers usually pass the bare orchestration name; the registered run is the cmdlet that - // starts it, so retry with the conventional Start- prefix before giving up. - if (!found) (found, cancelledCount) = await orchestrator.CancelRunAsync($"Start-{name}"); - - if (!found) return Results.NotFound(new { error = $"No run found for '{name}'" }); - - return Results.Ok(new - { - name, - cancelled = cancelledCount, - message = $"Cancelled {cancelledCount} pending tasks", - }); - }); - - return app; - } -} diff --git a/Services/Hosting/GcHeapLimit.cs b/Services/Hosting/GcHeapLimit.cs new file mode 100644 index 0000000..89ca774 --- /dev/null +++ b/Services/Hosting/GcHeapLimit.cs @@ -0,0 +1,111 @@ +using System.Globalization; +using Craft.Configuration; + +namespace Craft.Hosting; + +/// +/// Host-tier GC heap sizing — the companion to . +/// +/// The image bakes a conservative DOTNET_GCHeapHardLimit sized for the smallest supported +/// tier, and the CLR consumes that env var before any managed code runs — a tier with more memory +/// to give can only raise the limit after startup. .NET 8 provides exactly that hatch: +/// under the GCHeapHardLimit key, then +/// , which re-reads the limit configuration (AppContext data +/// takes precedence over the startup env var — the runtime deliberately won't re-read that var) and +/// applies it to the running GC. +/// +/// +/// Because that AppContext write overrides DOTNET_GCHeapHardLimit, a fleet-wide profile value +/// would otherwise silently countermand a limit an operator hand-set on a single instance. The +/// CRAFT_GC_HEAP_LIMIT_MB env var is the per-instance escape hatch that restores that control, +/// following the same pattern as CRAFT_API_CONCURRENCY_LIMIT and CRAFT_HTTP_QUEUE_TIMEOUT: +/// when set it wins over the matched profile. A value of 0 disables the cap entirely (refresh to +/// the container's own memory allowance, discarding the baked limit). +/// +/// +/// Best-effort under the same contract as pool sizing: any failure — including +/// refusing a limit below what the heap has already +/// committed — logs and keeps the baseline rather than taking the host down over a sizing hint. +/// +/// +public static class GcHeapLimit +{ + /// + /// Applies a GC heap hard limit: the CRAFT_GC_HEAP_LIMIT_MB env override if set, otherwise + /// from the matched profile. + /// + /// The profile matched, or null. + /// Sink for the operator-facing before/after line. + /// The actual limit change, injectable for tests; null = the real + /// AppContext + path. + /// Reader for CRAFT_GC_HEAP_LIMIT_MB, injectable for tests; null = + /// the real process environment. + /// when a limit change was applied. + public static bool Apply(SkuProfile? profile, Action log, Action? refresh = null, + Func? readEnv = null) + { + ArgumentNullException.ThrowIfNull(log); + + // Per-instance escape hatch. CRAFT_GC_HEAP_LIMIT_MB, when it parses to a non-negative integer, + // wins over the fleet-wide profile — same shape as ResolvedApiConcurrencyLimit / ResolveHttpQueueTimeout. + // > 0 : set that many MB, overriding the profile. + // 0 : disable the cap entirely — refresh to the container's own memory allowance, discarding + // the image-baked DOTNET_GCHeapHardLimit. Removing the cap only ever raises the limit, so + // it cannot trip RefreshMemoryLimit's "below committed heap" guard. + // unset / negative / unparseable : defer to the profile. + readEnv ??= () => Environment.GetEnvironmentVariable("CRAFT_GC_HEAP_LIMIT_MB"); + var envMB = int.TryParse(readEnv(), NumberStyles.Integer, CultureInfo.InvariantCulture, out var e) && e >= 0 + ? e + : (int?)null; + + int mb; + string source; + if (envMB is int fromEnv) + { + mb = fromEnv; + source = "CRAFT_GC_HEAP_LIMIT_MB"; + } + else + { + source = "SkuProfile"; + // A profile carries the same three-way meaning as the env override above: + // null / omitted / negative : no opinion — keep the process baseline (like unused SkuProfiles). + // 0 : disable the cap entirely, identical to CRAFT_GC_HEAP_LIMIT_MB=0 (a large tier that has + // more memory to give than the baked limit lets it use container/physical memory). + // > 0 : set that many MB. + var profileMB = profile?.GCHeapHardLimitMB; + if (profileMB is null or < 0) return false; + mb = profileMB.Value; + } + + refresh ??= SetAndRefresh; + var beforeMB = GC.GetGCMemoryInfo().TotalAvailableMemoryBytes / (1024 * 1024); + try + { + refresh((ulong)mb * 1024 * 1024); + var afterMB = GC.GetGCMemoryInfo().TotalAvailableMemoryBytes / (1024 * 1024); + var what = mb == 0 + ? $"GC heap hard limit disabled by {source} — deferring to container/physical memory" + : $"GC heap hard limit set to {mb} MB by {source}"; + log($"[System] {what} (TotalAvailableMemory {beforeMB} MB -> {afterMB} MB)"); + return true; + } + catch (Exception ex) + { + // Same contract as pool sizing: a sizing hint must never prevent startup. + var target = mb == 0 ? "disable" : $"{mb} MB"; + log($"[System] GC heap hard limit change ({target}) by {source} failed " + + $"({ex.GetType().Name}: {ex.Message}); keeping {beforeMB} MB"); + return false; + } + } + + /// Convenience overload writing to the console, like SkuProfileSelector.Apply(settings). + public static bool Apply(SkuProfile? profile) => Apply(profile, Console.WriteLine); + + private static void SetAndRefresh(ulong bytes) + { + AppContext.SetData("GCHeapHardLimit", bytes); + GC.RefreshMemoryLimit(); + } +} diff --git a/Services/Hosting/SkuProfileSelector.cs b/Services/Hosting/SkuProfileSelector.cs index 8f6daf0..5e10731 100644 --- a/Services/Hosting/SkuProfileSelector.cs +++ b/Services/Hosting/SkuProfileSelector.cs @@ -1,3 +1,4 @@ +using System.Globalization; using Craft.Configuration; namespace Craft.Hosting; @@ -7,25 +8,40 @@ namespace Craft.Hosting; /// actually landed on and overwrites Worker.HttpPoolSize / Worker.BgPoolSize with its /// values. /// +/// A second matrix is supported: when the env var named by +/// is present (non-empty), is matched instead of +/// (when non-empty), so a deployment can ship one config with +/// two sizings and pick between them with a single env var — e.g. a smaller per-instance matrix for +/// instances packed onto a shared App Service Plan. +/// +/// +/// A per-instance escape hatch beats both matrices: CRAFT_HTTP_POOL_SIZE / CRAFT_BG_POOL_SIZE, +/// when set to a non-negative integer, win over the matched profile (and baseline), following the same +/// shape as CRAFT_GC_HEAP_LIMIT_MB. +/// +/// /// This runs as a PostConfigure on , so it must apply before any /// consumer resolves the options — a worker pool that reads its size before the profile lands would /// silently size itself for the wrong tier. /// /// /// Detection is best-effort by design: any failure logs and leaves the baseline sizes untouched -/// rather than taking the host down over a pool-sizing hint. +/// rather than taking the host down over a pool-sizing hint. The returned profile may also carry a +/// ; applying that is a process-wide side effect and lives in +/// , not here. /// /// public static class SkuProfileSelector { /// - /// Applies the matching profile to , mutating it in place. + /// Applies the matching profile (and any pool-size env overrides) to , + /// mutating it in place. /// /// Settings to adjust. /// CPU count to match profiles against. - /// Environment lookup for each profile's . + /// Environment lookup for SkuEnv, the second-matrix flag, and the pool-size overrides. /// Sink for the operator-facing explanation of what matched and why. - /// The profile that was applied, or if the baseline was kept. + /// The profile that was applied, or if no profile matched. public static SkuProfile? Apply(CraftSettings settings, int processorCount, Func env, Action log) { @@ -34,60 +50,120 @@ public static class SkuProfileSelector ArgumentNullException.ThrowIfNull(log); var worker = settings.Worker; + SkuProfile? matched = null; if (worker.IgnoreSkuProfiles) { log($"[System] SkuProfile evaluation skipped: IgnoreSkuProfiles=true; " + $"using baseline HttpPoolSize={worker.HttpPoolSize} BgPoolSize={worker.BgPoolSize}"); - return null; + } + else + { + try + { + matched = MatchAndApply(worker, processorCount, env, log); + } + catch (Exception ex) + { + // Deliberately broad: pool sizing is a hint, and no failure mode here justifies refusing + // to start. The baseline sizes are already valid. + log($"[System] SkuProfile detection failed ({ex.GetType().Name}: {ex.Message}); " + + $"using baseline HttpPoolSize={worker.HttpPoolSize} BgPoolSize={worker.BgPoolSize}"); + } } - // Feature not configured — stay silent rather than logging on every start. - if (worker.SkuProfiles.Count == 0) return null; + // Per-instance escape hatch, applied last and unconditionally so it wins over profile/baseline: + // CRAFT_HTTP_POOL_SIZE / CRAFT_BG_POOL_SIZE, same shape as CRAFT_GC_HEAP_LIMIT_MB. + ApplyPoolSizeEnvOverrides(worker, env, log); - try + return matched; + } + + /// Selects the default vs hosted matrix, matches it, and applies the winner. Returns the + /// applied profile, or null when the baseline was kept. + private static SkuProfile? MatchAndApply(WorkerSettings worker, int processorCount, + Func env, Action log) + { + var altSelected = !string.IsNullOrWhiteSpace(worker.SkuProfilesAltEnv) + && !string.IsNullOrWhiteSpace(env(worker.SkuProfilesAltEnv)); + + List profiles; + string matrix; + if (altSelected && worker.SkuProfilesAlt.Count > 0) + { + profiles = worker.SkuProfilesAlt; + matrix = "alt"; + } + else + { + profiles = worker.SkuProfiles; + matrix = "default"; + if (altSelected && worker.SkuProfilesAlt.Count == 0) + log($"[System] Second SkuProfiles matrix selected ({worker.SkuProfilesAltEnv} is set) but " + + $"SkuProfilesAlt is empty; using the default SkuProfiles matrix."); + } + + // Feature not configured for the selected matrix — stay silent rather than logging on every start. + if (profiles.Count == 0) return null; + + foreach (var profile in profiles) { - foreach (var profile in worker.SkuProfiles) + string? skuValue = null; + bool skuMatch; + if (string.IsNullOrWhiteSpace(profile.SkuEnv)) { - string? skuValue = null; - bool skuMatch; - if (string.IsNullOrWhiteSpace(profile.SkuEnv)) - { - skuMatch = true; - } - else - { - skuValue = env(profile.SkuEnv) ?? ""; - skuMatch = string.Equals(skuValue, profile.Sku ?? "", StringComparison.OrdinalIgnoreCase); - } - - // Cpu unset or 0 means "any CPU count". - var cpuMatch = profile.Cpu is null or 0 || profile.Cpu == processorCount; - - if (!skuMatch || !cpuMatch) continue; - - log($"[System] SkuProfile matched (SkuEnv='{profile.SkuEnv}' Sku='{profile.Sku}' " + - $"Cpu={profile.Cpu}) for runtime ({profile.SkuEnv}='{skuValue}' " + - $"ProcessorCount={processorCount}); " + - $"applying HttpPoolSize={profile.HttpPoolSize} BgPoolSize={profile.BgPoolSize}"); - - worker.HttpPoolSize = profile.HttpPoolSize; - worker.BgPoolSize = profile.BgPoolSize; - return profile; + skuMatch = true; + } + else + { + skuValue = env(profile.SkuEnv) ?? ""; + skuMatch = string.Equals(skuValue, profile.Sku ?? "", StringComparison.OrdinalIgnoreCase); } - log($"[System] No SkuProfile matched runtime (ProcessorCount={processorCount}, " + - $"checked {worker.SkuProfiles.Count} profile(s)); " + - $"using baseline HttpPoolSize={worker.HttpPoolSize} BgPoolSize={worker.BgPoolSize}"); - return null; + // Cpu unset or 0 means "any CPU count". + var cpuMatch = profile.Cpu is null or 0 || profile.Cpu == processorCount; + + if (!skuMatch || !cpuMatch) continue; + + log($"[System] SkuProfile matched [{matrix}] (SkuEnv='{profile.SkuEnv}' Sku='{profile.Sku}' " + + $"Cpu={profile.Cpu}) for runtime ({profile.SkuEnv}='{skuValue}' ProcessorCount={processorCount}); " + + $"applying HttpPoolSize={profile.HttpPoolSize} BgPoolSize={profile.BgPoolSize}"); + + worker.HttpPoolSize = profile.HttpPoolSize; + worker.BgPoolSize = profile.BgPoolSize; + return profile; } - catch (Exception ex) + + log($"[System] No SkuProfile matched runtime in the {matrix} matrix (ProcessorCount={processorCount}, " + + $"checked {profiles.Count} profile(s)); using baseline HttpPoolSize={worker.HttpPoolSize} BgPoolSize={worker.BgPoolSize}"); + return null; + } + + private static void ApplyPoolSizeEnvOverrides(WorkerSettings worker, Func env, Action log) + { + if (TryReadEnvInt(env, "CRAFT_HTTP_POOL_SIZE", out var http)) { - // Deliberately broad: pool sizing is a hint, and no failure mode here justifies refusing - // to start. The baseline sizes are already valid. - log($"[System] SkuProfile detection failed ({ex.GetType().Name}: {ex.Message}); " + - $"using baseline HttpPoolSize={worker.HttpPoolSize} BgPoolSize={worker.BgPoolSize}"); - return null; + log($"[System] HttpPoolSize overridden to {http} by CRAFT_HTTP_POOL_SIZE (was {worker.HttpPoolSize})"); + worker.HttpPoolSize = http; + } + if (TryReadEnvInt(env, "CRAFT_BG_POOL_SIZE", out var bg)) + { + log($"[System] BgPoolSize overridden to {bg} by CRAFT_BG_POOL_SIZE (was {worker.BgPoolSize})"); + worker.BgPoolSize = bg; + } + } + + // Non-negative int env override, robust to a throwing env lookup (pool sizing must never break startup). + private static bool TryReadEnvInt(Func env, string name, out int value) + { + value = 0; + try + { + return int.TryParse(env(name), NumberStyles.Integer, CultureInfo.InvariantCulture, out value) && value >= 0; + } + catch + { + return false; } } diff --git a/Services/Orchestration/JobManager.cs b/Services/Orchestration/JobManager.cs index 154afb3..9ab490e 100644 --- a/Services/Orchestration/JobManager.cs +++ b/Services/Orchestration/JobManager.cs @@ -320,7 +320,13 @@ protected override async Task ExecuteAsync(CancellationToken stoppingToken) // Anything else — a throw out of the queue lock, the limiter or the semaphore — used to // escape ExecuteAsync and silently end dispatch for the life of the process. One bad // iteration must not stop every future job. - _logger.LogError(ex, "[JobManager] Dispatch iteration failed; continuing"); + // + // The log is guarded too: under a pegged GC hard limit LogError can itself throw OOM, and + // this catch is the last frame before ExecuteAsync — an escape here faults the loop and, + // with the host's default StopHost behaviour, takes the container down mid-run. A failed + // log is never worth dispatch. (BackgroundTaskLimiter guards its logs for the same reason.) + try { _logger.LogError(ex, "[JobManager] Dispatch iteration failed; continuing"); } + catch { /* logging is never worth the loop */ } } finally { diff --git a/Services/Orchestration/JobQueuePump.cs b/Services/Orchestration/JobQueuePump.cs index 1562552..76b3ca5 100644 --- a/Services/Orchestration/JobQueuePump.cs +++ b/Services/Orchestration/JobQueuePump.cs @@ -31,9 +31,18 @@ public class JobQueuePump : BackgroundService private readonly TimeSpan _pollInterval; private readonly TimeSpan _idlePollInterval; + /// Renew a claim only once its lease has less than this left. The lease is set comfortably + /// longer than a task can run, so most claims finish without ever needing a renewal; this is the tail + /// (a deep buffer, or a genuinely long task) that has been held long enough to approach expiry. + private readonly TimeSpan _renewWhenWithin; + /// Rows claimed by this instance, by the job id they were handed to the JobManager under. private readonly Dictionary _inFlight = new(StringComparer.Ordinal); + /// UTC lease expiry per in-flight job id, so renewal can skip claims with plenty of lease + /// left instead of re-reading every row every tick. + private readonly Dictionary _leaseExpiry = new(StringComparer.Ordinal); + public JobQueuePump(ILogger logger, JobQueueStore queue, JobManager jobs, IConfiguration configuration, CraftSettings settings) { @@ -56,6 +65,10 @@ public JobQueuePump(ILogger logger, JobQueueStore queue, JobManage // would hand its work to a second worker. _lease = TimeSpan.FromSeconds(Math.Max(60, configuration.GetValue("JobQueueLeaseSeconds", 1800))); + // Renew in the last third of the lease. Below the lease length by construction, so a claim is + // never renewed on the same tick it was taken. + _renewWhenWithin = TimeSpan.FromTicks(_lease.Ticks / 3); + _pollInterval = TimeSpan.FromMilliseconds( Math.Max(100, configuration.GetValue("JobQueuePollIntervalMs", 1000))); @@ -80,6 +93,11 @@ protected override async Task ExecuteAsync(CancellationToken stoppingToken) var claimedAny = false; try { + // Ensure the queue schema is migrated before this pump ever claims. It is a cheap bool + // check after the first success; before it, claiming could hand out a row the one-time + // key migration is still rewriting. Idempotent and shared with the enqueue paths. + await _queue.InitializeAsync(stoppingToken); + await ReleaseFinishedAsync(stoppingToken); claimedAny = await RefillAsync(stoppingToken); await RenewAsync(stoppingToken); @@ -92,7 +110,14 @@ protected override async Task ExecuteAsync(CancellationToken stoppingToken) { // One bad cycle must not end the pump; the next tick tries again. A pump that dies // silently would look exactly like an empty queue. - _logger.LogError(ex, "[JobQueuePump] Cycle failed; continuing"); + // + // The log itself is guarded: under a pegged GC hard limit even LogError allocates and can + // throw OOM, and this catch is the last frame before ExecuteAsync — an escape here faults + // the service and, with the host's default StopHost behaviour, restarts the container + // mid-run. A failed log is never worth the pump. (BackgroundTaskLimiter guards its logs + // past the point of commitment for the same reason.) + try { _logger.LogError(ex, "[JobQueuePump] Cycle failed; continuing"); } + catch { /* logging is never worth the loop */ } } // Idle means this pump has nothing: it claimed nothing AND holds nothing. Note what is @@ -106,7 +131,12 @@ protected override async Task ExecuteAsync(CancellationToken stoppingToken) if (claimedAny || _inFlight.Count > 0) idleTicks = 0; else idleTicks++; - try { await Task.Delay(NextDelay(idleTicks), stoppingToken); } + // Wait for the poll interval OR an enqueue signal, whichever comes first. The signal is what + // makes a freshly-queued run start now instead of on the next tick — a cold system had backed + // the interval off toward its idle ceiling, so without this the first task of a quiet-time + // orchestration waited up to that ceiling just to be claimed. The interval stays as the + // backstop (a missed signal, cross-instance work, freed leases), so this only removes the wait. + try { await _queue.WaitForWorkAsync(NextDelay(idleTicks), stoppingToken); } catch (OperationCanceledException) { break; } } @@ -125,15 +155,20 @@ private async Task ReleaseFinishedAsync(CancellationToken ct) if (_inFlight.Count == 0) return; var finished = _inFlight.Where(kv => !_jobs.IsQueuedOrRunning(kv.Key)).ToList(); + if (finished.Count == 0) return; - foreach (var (jobId, claim) in finished) + // One transaction per partition rather than two point deletes per task. Tracking is cleared only + // after the storage delete lands, so a failure here throws, the cycle guard logs it, and the same + // claims are retried next tick (the delete is idempotent — a row already gone is tolerated). + await _queue.RemoveBatchAsync(finished.Select(kv => kv.Value).ToList(), ct); + + foreach (var (jobId, _) in finished) { - await _queue.RemoveAsync(claim, ct); _inFlight.Remove(jobId); + _leaseExpiry.Remove(jobId); } - if (finished.Count > 0) - _logger.LogDebug("[JobQueuePump] Released {Count} finished job(s)", finished.Count); + _logger.LogDebug("[JobQueuePump] Released {Count} finished job(s)", finished.Count); } /// @@ -166,6 +201,7 @@ private async Task RefillAsync(CancellationToken ct) var claimed = await _queue.ClaimBatchAsync(_owner, _batchSize, _lease, ct); if (claimed.Count == 0) return false; + var leaseExpiry = DateTime.UtcNow + _lease; foreach (var job in claimed) { // Enqueued by identity, the way the orchestrator already does it, so the work is rebuilt at @@ -173,6 +209,9 @@ private async Task RefillAsync(CancellationToken ct) var name = $"{job.RunName}-{job.TaskId}"; var jobId = _jobs.Enqueue(new JobDescriptor(job.RunName, job.TaskId, job.Priority), name); _inFlight[jobId] = job; + // Slightly earlier than the lease storage actually recorded (claimed a moment before this), + // so renewal errs toward being early rather than late. + _leaseExpiry[jobId] = leaseExpiry; } _logger.LogDebug("[JobQueuePump] Claimed {Count} job(s) ({Queued} queued after refill)", @@ -190,7 +229,23 @@ private async Task RenewAsync(CancellationToken ct) { if (_inFlight.Count == 0) return; - if (!await _queue.RenewAsync(_inFlight.Values.ToList(), _owner, _lease, ct)) + // Only the claims whose lease is actually running low. Everything else has ample lease left and + // does not need a storage round-trip this tick — the old code re-read every in-flight row every + // tick regardless of how much lease remained. + var now = DateTime.UtcNow; + var dueIds = _inFlight.Keys + .Where(id => !_leaseExpiry.TryGetValue(id, out var expiry) || expiry - now < _renewWhenWithin) + .ToList(); + if (dueIds.Count == 0) return; + + var due = dueIds.Select(id => _inFlight[id]).ToList(); + if (!await _queue.RenewAsync(due, _owner, _lease, ct)) + { _logger.LogWarning("[JobQueuePump] One or more leases could not be renewed — work may have been reclaimed"); + return; + } + + var renewedExpiry = now + _lease; + foreach (var id in dueIds) _leaseExpiry[id] = renewedExpiry; } } diff --git a/Services/Orchestration/OrchestratorService.cs b/Services/Orchestration/OrchestratorService.cs index 53c8f8c..28ce4d9 100644 --- a/Services/Orchestration/OrchestratorService.cs +++ b/Services/Orchestration/OrchestratorService.cs @@ -792,9 +792,19 @@ private async Task DispatchPendingTasksAsync(OrchestratorRun run, string taskPat // permanent, which is a worse failure than the premature finalize it exists to prevent. var timer = new Timer(_ => { - LogRunStatus(run); - RedrivePendingTasks(run); - lock (_lock) { CheckRunCompletion(run); } + // A System.Threading.Timer callback that throws crashes the process. This periodic + // maintenance tick must never take the host down on a transient error — a dependency + // disposed during shutdown, a race on run state — so it logs and waits for the next tick. + try + { + LogRunStatus(run); + RedrivePendingTasks(run); + lock (_lock) { CheckRunCompletion(run); } + } + catch (Exception ex) + { + _logger?.LogWarning(ex, "[Scheduler] Run status tick failed for {Name}", run?.Name); + } }, null, TimeSpan.FromSeconds(60), TimeSpan.FromSeconds(60)); if (!_runStatusTimers.TryAdd(run.Name, timer)) @@ -1086,8 +1096,15 @@ private Func BuildTaskWork(OrchestratorRun run, Orchest "[Scheduler] Task {TaskId} in {Run} returned {Chars} chars (~{ApproxKB:F1} KB in memory)", task.Id, run.Name, output?.Length ?? 0, (output?.Length ?? 0) * 2 / 1024.0); - if (!string.IsNullOrEmpty(output)) + if (!string.IsNullOrEmpty(output) && !_writer.TryQueueResult(run.Name, task.Id, output)) + { + // Large result, or result-batching off: keep the directly-awaited chunked path. + // Either way this awaits BEFORE the task is marked Completed below, so the result + // is durable before the run can finalize. Small results instead ride the status + // writer (TryQueueResult == true), which writes them before this task's terminal + // marker in the same flush — same guarantee, off the slot-held critical path. await _store.StoreResultAsync(run.Name, task.Id, output); + } } else { @@ -1344,6 +1361,13 @@ private void CheckRunCompletion(OrchestratorRun run) { try { + // Flush before the counter read below. The batched status writer decrements the counter + // only when a terminal write flushes, so an unflushed read sees the pre-decrement value + // and defers a finalize that is due — a single GET beats the drain+decrement every time, + // stalling every run until the 60s timer. Same flush FinalizeRunCoreAsync relies on, just + // ahead of the veto read; bounded by the barrier timeout, so it cannot hang. + await _writer.FlushAsync(); + // The in-memory graph proposes, storage disposes. Finalizing is irreversible - it // writes the aggregate and cleans the run up - so it must not run while storage still // shows work outstanding, which is exactly the case when terminal writes have not yet @@ -1889,6 +1913,14 @@ internal static void AddTaskFromElement(List tasks, HashSe return _psRunner.FindScript($"Invoke-{baseName}Task"); } + /// + /// Empty the durable job queue (maintenance/reset). Delegates to + /// — see its remarks: in-flight work is unaffected and Pending tasks may be re-driven, so pair this + /// with when the intent is to STOP work rather than clear a wedged queue. + /// Returns the number of queue rows removed. + /// + public Task ClearQueueAsync(CancellationToken ct = default) => _queue.ClearAllAsync(ct); + /// /// Cancel a running orchestrator run. Pending tasks are marked Cancelled immediately. /// Already-running tasks are allowed to finish (no force-kill). diff --git a/Services/Orchestration/OrchestratorStatusWriter.cs b/Services/Orchestration/OrchestratorStatusWriter.cs index 10dd3e7..99008be 100644 --- a/Services/Orchestration/OrchestratorStatusWriter.cs +++ b/Services/Orchestration/OrchestratorStatusWriter.cs @@ -25,7 +25,13 @@ public sealed class OrchestratorStatusWriter : IDisposable private readonly ILogger _logger; private readonly bool _enabled; private readonly bool _durableBarrier; + private readonly bool _batchResults; private readonly int _flushIntervalMs; + + /// Results at or below this many chars fit a single Azure Table property and can be coalesced + /// here; larger ones need the chunked multi-row path and are written directly by the caller. Matches + /// OrchestratorTableStore's single-property fast-path bound. + private const int SmallResultMaxChars = 30_000; private readonly TimeSpan _barrierTimeout; private readonly TimeSpan _flushTimeout; private readonly int _flushConcurrency; @@ -36,11 +42,16 @@ public sealed class OrchestratorStatusWriter : IDisposable private readonly object _lock = new(); private Dictionary _pendingTasks = new(); // key: runName  taskId (last-wins coalesce) private Dictionary _pendingRuns = new(); // key: runName + private Dictionary _pendingResults = new(); // key: run + task private TaskCompletionSource _barrier = new(TaskCreationOptions.RunContinuationsAsynchronously); private readonly SemaphoreSlim _signal = new(0, int.MaxValue); private readonly CancellationTokenSource _cts = new(); private readonly Task _drainLoop; + /// Set first in so a status enqueue racing shutdown drops its wake + /// instead of throwing ObjectDisposedException into a job that already succeeded. + private volatile bool _disposed; + public bool Enabled => _enabled; public OrchestratorStatusWriter(OrchestratorTableStore store, ILogger logger, CraftSettings settings) @@ -49,6 +60,7 @@ public OrchestratorStatusWriter(OrchestratorTableStore store, ILoggerQueue a run's status — non-blocking, coalesced, flushed by the drain loop. @@ -143,7 +155,21 @@ public void QueueRun(OrchestratorRun run) { if (!_enabled) { _ = _store.UpsertRunAsync(run); return; } lock (_lock) { _pendingRuns[run.Name] = run; } - _signal.Release(); + Signal(); + } + + /// + /// Try to coalesce a task result. Returns true if it was queued (written before this task's terminal + /// marker in the next flush, so it is durable before the task is counted done); false if the caller + /// must write it directly — because batching or result-batching is off, or the result is too large + /// for a single table property and needs the chunked path. + /// + public bool TryQueueResult(string runName, string taskId, string resultJson) + { + if (!_enabled || !_batchResults || resultJson.Length > SmallResultMaxChars) return false; + lock (_lock) { _pendingResults[Key(runName, taskId)] = new ResultWrite(runName, taskId, resultJson); } + Signal(); + return true; } /// Flush all currently-pending writes and await their persistence. Call before finalizing a run @@ -153,7 +179,7 @@ public async Task FlushAsync(CancellationToken ct = default) if (!_enabled) return; Task barrier; lock (_lock) { barrier = _barrier.Task; } - _signal.Release(); + Signal(); // Bounded for the same reason as the Running marker: this is awaited by FinalizeRunAsync, and an // unbounded wait meant no run could finalize while a flush was stuck. Requeue-on-failure means a @@ -204,12 +230,13 @@ private async Task FlushOnceAsync(TimeSpan timeout, bool ignoreShutdown = false) { Dictionary tasks; Dictionary runs; + Dictionary results; TaskCompletionSource done; lock (_lock) { done = _barrier; _barrier = new(TaskCreationOptions.RunContinuationsAsynchronously); - if (_pendingTasks.Count == 0 && _pendingRuns.Count == 0) + if (_pendingTasks.Count == 0 && _pendingRuns.Count == 0 && _pendingResults.Count == 0) { // Nothing to flush — still release barrier waiters (e.g. FlushAsync on an already-drained run). done.TrySetResult(); @@ -217,6 +244,7 @@ private async Task FlushOnceAsync(TimeSpan timeout, bool ignoreShutdown = false) } tasks = _pendingTasks; _pendingTasks = new(); runs = _pendingRuns; _pendingRuns = new(); + results = _pendingResults; _pendingResults = new(); } using var cts = ignoreShutdown @@ -229,8 +257,27 @@ private async Task FlushOnceAsync(TimeSpan timeout, bool ignoreShutdown = false) try { + // Results FIRST, and a run whose result did not land withholds that run's terminal task and + // run-status writes THIS flush. A terminal marker must never persist ahead of its result: a + // crash in between would leave a task counted done with no result for post-execution to read. + var failedResultRuns = new HashSet(StringComparer.Ordinal); + if (results.Count > 0) + { + var failedResults = await _store.WriteResultBatchAsync(results.Values.ToList(), _flushConcurrency, cts.Token); + foreach (var run in failedResults) failedResultRuns.Add(run); + unwritten.AddRange(failedResults); + } + if (tasks.Count > 0) - unwritten.AddRange(await _store.WriteTaskStatusBatchAsync(tasks.Values.ToList(), _flushConcurrency, cts.Token)); + { + var toWrite = failedResultRuns.Count == 0 + ? tasks.Values.ToList() + : tasks.Values.Where(t => !failedResultRuns.Contains(t.RunName)).ToList(); + unwritten.AddRange(await _store.WriteTaskStatusBatchAsync(toWrite, _flushConcurrency, cts.Token)); + // Tasks held back because their run's result failed: requeue so they retry with the result. + if (failedResultRuns.Count > 0) + unwritten.AddRange(tasks.Values.Where(t => failedResultRuns.Contains(t.RunName)).Select(t => t.RunName)); + } // Batched, not one await per run. Run rows all share the "Run" partition key, so N of them // cost ceil(N/100) transactions; the previous per-run loop cost N round-trips inside a flush @@ -238,22 +285,30 @@ private async Task FlushOnceAsync(TimeSpan timeout, bool ignoreShutdown = false) // budget and then the durable barrier. The store isolates a poison row by retrying a failed // chunk individually, so a single bad run no longer discards the other 99. if (runs.Count > 0) - unwritten.AddRange(await _store.WriteRunStatusBatchAsync(runs.Values.ToList(), cts.Token)); + { + var toWrite = failedResultRuns.Count == 0 + ? runs.Values.ToList() + : runs.Values.Where(r => !failedResultRuns.Contains(r.Name)).ToList(); + unwritten.AddRange(await _store.WriteRunStatusBatchAsync(toWrite, cts.Token)); + if (failedResultRuns.Count > 0) + unwritten.AddRange(runs.Values.Where(r => failedResultRuns.Contains(r.Name)).Select(r => r.Name)); + } } catch (Exception ex) { // Timed out or the store threw wholesale — treat EVERYTHING in this snapshot as unwritten. failure = ex; + unwritten.AddRange(results.Values.Select(r => r.RunName)); unwritten.AddRange(tasks.Values.Select(t => t.RunName)); unwritten.AddRange(runs.Keys); - _logger.LogError(ex, "[Orchestrator] Status flush failed ({Tasks} tasks, {Runs} runs) — requeued for retry", - tasks.Count, runs.Count); + _logger.LogError(ex, "[Orchestrator] Status flush failed ({Results} results, {Tasks} tasks, {Runs} runs) — requeued for retry", + results.Count, tasks.Count, runs.Count); } // Durability: anything that did not reach storage goes back on the pending set. Dropping it // (the previous behaviour on any exception) silently lost terminal task states — a completed // task would look Pending forever and be re-run by the next recovery. - if (unwritten.Count > 0) Requeue(tasks, runs, unwritten); + if (unwritten.Count > 0) Requeue(results, tasks, runs, unwritten); // The barrier may ONLY report success when this batch actually persisted. Waiters cannot tell // which run in the batch was theirs, so any un-persisted write has to fail all of them — a @@ -274,14 +329,21 @@ private async Task FlushOnceAsync(TimeSpan timeout, bool ignoreShutdown = false) /// NEWER state for the same task may have arrived while the flush was in flight, and the retry of a /// stale snapshot must never overwrite it. /// - private void Requeue(Dictionary tasks, Dictionary runs, - List unwrittenRuns) + private void Requeue(Dictionary results, Dictionary tasks, + Dictionary runs, List unwrittenRuns) { var retry = new HashSet(unwrittenRuns, StringComparer.OrdinalIgnoreCase); var restored = 0; lock (_lock) { + // Results before tasks, mirroring the flush order: a result put back must be in the pending + // set before the terminal marker it guards is retried. + foreach (var (key, write) in results) + { + if (!retry.Contains(write.RunName)) continue; + if (_pendingResults.TryAdd(key, write)) restored++; + } foreach (var (key, write) in tasks) { if (!retry.Contains(write.RunName)) continue; @@ -296,14 +358,28 @@ private void Requeue(Dictionary tasks, Dictionary 0) { - _signal.Release(); // make sure the next flush actually runs + Signal(); // make sure the next flush actually runs _logger.LogWarning("[Orchestrator] Requeued {Count} un-persisted status writes across {Runs} runs", restored, retry.Count); } } + /// + /// Wake the drain loop. Guarded so a status enqueue that races — an in-flight + /// job finishing after shutdown began — drops the wake instead of throwing ObjectDisposedException. + /// By the time a task queues its terminal status its data is already persisted, so a lost coalesced + /// wake on the way down is harmless; a task falsely marked Failed because the release threw is not. + /// + private void Signal() + { + if (_disposed) return; + try { _signal.Release(); } + catch (ObjectDisposedException) { /* shutting down; the drain loop has already stopped */ } + } + public void Dispose() { + _disposed = true; _cts.Cancel(); try { _drainLoop.Wait(TimeSpan.FromSeconds(5)); } catch { /* best effort final drain */ } _cts.Dispose(); diff --git a/Services/PowerShellHost/PipelineExecutionContext.cs b/Services/PowerShellHost/PipelineExecutionContext.cs new file mode 100644 index 0000000..7234317 --- /dev/null +++ b/Services/PowerShellHost/PipelineExecutionContext.cs @@ -0,0 +1,54 @@ +namespace Craft.PowerShellHost; + +/// +/// Clears per-invocation AsyncLocal state that would otherwise leak across invocations on a +/// worker's reused pipeline thread (PSThreadOptions.ReuseThread). An AsyncLocal value lives in +/// the thread's ; runspace SessionState (module +/// $script: variables, ModuleInjections caches) and process env do NOT — so restoring a clean +/// baseline ExecutionContext drops the per-request AsyncLocal state while leaving persisted per-worker +/// state untouched. +/// +/// A captured ExecutionContext is an immutable snapshot, not thread-bound, so a single clean baseline +/// captured once (at worker init, before any request context exists) can be restored onto every +/// worker's pipeline thread. Uses only the public, supported +/// / +/// (public +/// since net8). Both entry points must run ON the pipeline thread (i.e. via a pipeline invocation). +/// +public static class PipelineExecutionContext +{ + private static System.Threading.ExecutionContext? s_baseline; + private static volatile bool s_captured; + + /// True once a baseline has been captured for the pool (worker init ran at least once). + public static bool Captured => s_captured; + + /// True if the captured baseline is the runtime default (Capture() returned null), in which + /// case is a no-op — there is no public way to Restore the default context. + public static bool BaselineIsDefault => s_captured && s_baseline is null; + + /// + /// Capture the clean baseline once, from the calling (pipeline) thread. Idempotent — only the first + /// call captures. Call at worker init, after warmup, before serving invocations. + /// + public static void CaptureBaselineIfNeeded() + { + if (s_captured) return; + s_baseline = System.Threading.ExecutionContext.Capture(); // clean, post-warmup context (no per-request AsyncLocals) + s_captured = true; // volatile write publishes s_baseline + } + + /// + /// Restore the clean baseline onto the calling (pipeline) thread, dropping any AsyncLocal set during + /// the invocation. Throws if no baseline was ever captured; the caller catches, logs and continues. + /// + public static void Reset() + { + if (!s_captured) + throw new InvalidOperationException("ExecutionContext baseline was never captured for this worker pool."); + var baseline = s_baseline; + if (baseline is not null) + System.Threading.ExecutionContext.Restore(baseline); // public API (net8+) + // else: warmup context was the runtime default; nothing to Restore via the public API. + } +} diff --git a/Services/PowerShellHost/PowerShellRunnerService.cs b/Services/PowerShellHost/PowerShellRunnerService.cs index 1c9b872..6863f25 100644 --- a/Services/PowerShellHost/PowerShellRunnerService.cs +++ b/Services/PowerShellHost/PowerShellRunnerService.cs @@ -26,6 +26,10 @@ public class PowerShellRunnerService : IDisposable private readonly AuthSettings _authSettings; private readonly ScriptRepoSettings _scriptsSettings; + // How long an HTTP request waits for a free runspace before it is shed with 503. Resolved once + // (env override → Worker:HttpQueueTimeoutSeconds → built-in default) — see ResolveHttpQueueTimeout. + private readonly TimeSpan _httpQueueTimeout; + // Static JsonSerializerOptions — allocated once, reused everywhere private static readonly JsonSerializerOptions s_jsonOptions = new() { WriteIndented = false }; @@ -45,6 +49,7 @@ public PowerShellRunnerService( _workerSettings = settings.Worker; _authSettings = settings.Auth; _scriptsSettings = settings.Scripts; + _httpQueueTimeout = CraftHostBuilderExtensions.ResolveHttpQueueTimeout(settings.Worker); } /// @@ -90,7 +95,7 @@ public async Task ExecuteHttpEndpoint(string endpoint, Hashtable r EventHandler? onVerbose = null; try { - worker = _pool.CheckoutHttp(TimeSpan.FromSeconds(30)); + worker = _pool.CheckoutHttp(_httpQueueTimeout); if (worker == null) { return new ScriptResult @@ -278,11 +283,12 @@ private async Task ExecuteHttpScriptInternal(string route, Hashtab var checkoutStart = timing != null ? Stopwatch.GetTimestamp() : 0; if (isHttp) { - worker = _pool.CheckoutHttp(TimeSpan.FromSeconds(30)); + worker = _pool.CheckoutHttp(_httpQueueTimeout); if (timing != null) timing.CheckoutTicks = Stopwatch.GetTimestamp() - checkoutStart; if (worker == null) { - _logger.LogWarning("HTTP pool exhausted — no worker available within 30s for {Route}", route); + _logger.LogWarning("HTTP pool exhausted — no worker available within {Timeout:0}s for {Route}", + _httpQueueTimeout.TotalSeconds, route); return new ScriptResult { StatusCode = 503, diff --git a/Services/PowerShellHost/PowerShellWorker.cs b/Services/PowerShellHost/PowerShellWorker.cs index fe3a832..33a0be5 100644 --- a/Services/PowerShellHost/PowerShellWorker.cs +++ b/Services/PowerShellHost/PowerShellWorker.cs @@ -216,6 +216,20 @@ public void Initialize(ScriptRepository repo, string apiBasePath, CraftSettings catch (Exception ex) { _logger.LogWarning("Post-init script failed: {Error}", ex.Message); } } + // Capture the clean ExecutionContext baseline once (shared across the pool) so Cleanup can reset + // per-invocation AsyncLocal state on the reused pipeline thread. Runs on the pipeline thread via + // RunScript. Never fail worker init over this. + try + { + RunScript("[Craft.PowerShellHost.PipelineExecutionContext]::CaptureBaselineIfNeeded()"); + if (PipelineExecutionContext.BaselineIsDefault) + _logger.LogWarning("Worker{Id}: ExecutionContext baseline captured as the runtime default; per-invocation reset will no-op.", Id); + } + catch (Exception ex) + { + _logger.LogWarning(ex, "Worker{Id}: failed to capture ExecutionContext baseline; per-invocation reset will be skipped.", Id); + } + _initialized = true; _logger.LogInformation("Worker{Id}: {Count} functions deployed", Id, deployed); } @@ -418,10 +432,35 @@ private void Cleanup() { _pwsh.Commands.Clear(); _pwsh.Streams.ClearStreams(); + ResetPipelineExecutionContext(); CleanupGlobalVariables(); CleanupJobs(); } + /// + /// Reset the reused pipeline thread's ExecutionContext to the clean baseline, dropping any AsyncLocal + /// set during the invocation (which would otherwise leak to the next invocation on this worker). Runs + /// as a minimal pipeline so it executes ON the pipeline + /// thread. SessionState (module $script: vars, injected caches) is not in the ExecutionContext, so it + /// is unaffected. Never fail an invocation over this — catch, log, continue. + /// + private void ResetPipelineExecutionContext() + { + try + { + _pwsh.AddScript("[Craft.PowerShellHost.PipelineExecutionContext]::Reset()").Invoke(); + } + catch (Exception ex) + { + _logger.LogWarning(ex, "Worker{Id}: per-invocation ExecutionContext reset failed; continuing.", Id); + } + finally + { + _pwsh.Commands.Clear(); + _pwsh.Streams.ClearStreams(); + } + } + private void CleanupGlobalVariables() { if (s_builtinGlobalVars == null) return; diff --git a/Services/Program.cs b/Services/Program.cs index 2bfdcb5..4c627a7 100644 --- a/Services/Program.cs +++ b/Services/Program.cs @@ -16,8 +16,10 @@ // Bind App section to CraftSettings builder.Services.Configure(builder.Configuration.GetSection("App")); -// Apply SkuProfiles override (host-tier pool sizing) before any consumer resolves the options -builder.Services.PostConfigure(s => SkuProfileSelector.Apply(s)); +// Apply SkuProfiles override (host-tier pool sizing + GC heap limit) before any consumer resolves +// the options — the heap limit lands via GC.RefreshMemoryLimit, so it must run before the worker +// pools start growing the heap. +builder.Services.PostConfigure(s => GcHeapLimit.Apply(SkuProfileSelector.Apply(s))); // Also register a singleton accessor for non-DI contexts builder.Services.AddSingleton(sp => sp.GetRequiredService>().Value); @@ -73,6 +75,9 @@ LoggerFactory.Create(b => b.AddSimpleConsole()).CreateLogger("Craft.Endpoints")); builder.Services.AddCraftServices(roles); +// The discovered catalog, injectable so the startup telemetry emitter can report a native route count +// without re-scanning. Registered even when empty so the dependency always resolves. +builder.Services.AddSingleton(nativeCatalog); if (!nativeCatalog.IsEmpty) builder.Services.AddNativeEndpoints(nativeCatalog, builder.Configuration); builder.Services.AddCraftRateLimiter(craftSettings); @@ -382,7 +387,7 @@ void RunInitialization() // counting those against the caller's budget could throttle a user for opening a page. // Left outside the capHttp block on purpose: a frontend-only node has no auth middleware and no // worker pool, but should still be protected, partitioned by origin address as before. -if (CraftSettings.RateLimit.IsEnabled) +if (CraftSettings.RateLimit.RequiresLimiterMiddleware) app.UseRateLimiter(); // Concurrent request tracking for diagnostics. A holder object, not an int: the dispatch endpoint @@ -410,10 +415,11 @@ void RunInitialization() if (capHttp) { - // Setup wizard API and job/run status API — both plain C#, no PowerShell involved. - // See Services/Hosting/Endpoints/. + // Setup wizard API — plain C#, no PowerShell involved. See Services/Hosting/Endpoints/. + // Job/run status and queue maintenance are intentionally NOT HTTP endpoints here: CRAFT exposes them + // as bridge methods (WorkerMetricsBridge / QueueStatusBridge) and a downstream app wraps whichever it + // needs into its own endpoints — the perf-harness's PerfApi module (Invoke-PerfAllocation) is one. app.MapCraftSetupEndpoints(CraftSettings); - app.MapCraftJobEndpoints(); // Native C# endpoints. Mapped before the PowerShell dispatcher, though ASP.NET route precedence // would put a literal segment ahead of /API/{endpoint} regardless — which is what lets an app diff --git a/Services/Storage/AzureTableStore.cs b/Services/Storage/AzureTableStore.cs index a2693e1..e994093 100644 --- a/Services/Storage/AzureTableStore.cs +++ b/Services/Storage/AzureTableStore.cs @@ -262,8 +262,50 @@ private async Task SubmitAsync(string table, TableClient client, List rowKeys, + CancellationToken ct = default) + { + if (rowKeys.Count == 0) return; + var client = Client(table); + + for (int i = 0; i < rowKeys.Count; i += MaxBatch) + { + var chunk = rowKeys.Skip(i).Take(MaxBatch).ToList(); + var batch = chunk + .Select(rk => new TableTransactionAction(TableTransactionActionType.Delete, new TableEntity(partitionKey, rk))) + .ToList(); + try + { + await client.SubmitTransactionAsync(batch, ct); + } + catch (RequestFailedException ex) when (ex.Status == 404) + { + // A transaction is all-or-nothing, so one already-deleted row (or a missing table) 404s + // the whole chunk. Fall back to per-row deletes, which tolerate a missing row (and a + // missing table) individually — the removal is idempotent either way. + foreach (var rk in chunk) + await DeleteAsync(table, partitionKey, rk, ct); + } } } diff --git a/Services/Storage/ICraftTableStore.cs b/Services/Storage/ICraftTableStore.cs index 9a8f883..2d7ab0d 100644 --- a/Services/Storage/ICraftTableStore.cs +++ b/Services/Storage/ICraftTableStore.cs @@ -86,6 +86,21 @@ IAsyncEnumerable QueryTableAsync(string table, string? filter, IReadOn /// Delete a single row. A missing row is not an error. Task DeleteAsync(string table, string partitionKey, string rowKey, CancellationToken ct = default); + /// + /// Delete many rows that share a partition key, in as few round-trips as the backend allows. A + /// missing row is never an error. + /// + /// This default keeps a backend that cannot batch correct by deleting one row at a time; + /// overrides it with a per-partition transaction. Callers may pass + /// more than a single transaction can hold — implementations chunk internally. + /// + async Task DeleteBatchAsync(string table, string partitionKey, IReadOnlyList rowKeys, + CancellationToken ct = default) + { + foreach (var rowKey in rowKeys) + await DeleteAsync(table, partitionKey, rowKey, ct); + } + /// Delete every row in a partition. Task DeletePartitionAsync(string table, string partitionKey, CancellationToken ct = default); } diff --git a/Services/Storage/JobQueueStore.cs b/Services/Storage/JobQueueStore.cs index 4585fe3..d895f17 100644 --- a/Services/Storage/JobQueueStore.cs +++ b/Services/Storage/JobQueueStore.cs @@ -47,10 +47,10 @@ namespace Craft.Storage; /// RowKey "{bucket}|{queue row key}" — enough to address the queue row directly /// /// Every run-scoped method below is now a single-partition read followed by point operations, and the -/// claim path is untouched. The index is maintained by the enqueue/remove paths, and built once for a -/// pre-existing queue by . +/// claim path is untouched. The index is maintained by the enqueue/remove paths, and built (and, from +/// schema v2, re-keyed) once for a pre-existing queue by . /// -public class JobQueueStore +public sealed class JobQueueStore : IDisposable { private readonly ILogger _logger; private readonly ICraftTableStore _store; @@ -58,6 +58,33 @@ public class JobQueueStore private readonly string _indexTable; private bool _initialized; + /// + /// Wakes the the moment claimable rows appear, instead + /// of it discovering them only on its next poll tick. Bounded at one pending permit: many enqueues + /// between two pump cycles coalesce into a single wake, because one refill claims a whole batch anyway. + /// The pump keeps polling on its (idle-backing-off) interval as the backstop — this signal only + /// removes the wait, it does not replace the loop. Same-instance only, which is all that is needed: + /// the pump and the enqueue paths share this singleton, and a lease keeps cross-instance work safe. + /// + private readonly SemaphoreSlim _pumpWake = new(0, 1); + + /// Signal the pump that new claimable rows exist. Never throws and never exceeds one permit. + private void WakePump() + { + try { _pumpWake.Release(); } + catch (SemaphoreFullException) { /* a wake is already pending; the pump will claim the batch */ } + catch (ObjectDisposedException) { /* shutting down; the pump loop has already stopped */ } + } + + public void Dispose() => _pumpWake.Dispose(); + + /// + /// Block until the pump is woken by an enqueue or elapses, whichever + /// comes first. Returns true if woken (new work signalled), false on the poll timeout. + /// + public Task WaitForWorkAsync(TimeSpan pollInterval, CancellationToken ct = default) => + _pumpWake.WaitAsync(pollInterval, ct); + /// Priorities above this share the lowest bucket. Callers use 0-6; the cap only bounds the key. private const int MaxPriorityBucket = 99; @@ -65,12 +92,22 @@ public class JobQueueStore private const int BucketKeyLength = 3; /// - /// Where the backfill marker lives. '$' is legal in a key and no run name starts with it — run names + /// Where the schema marker lives. '$' is legal in a key and no run name starts with it — run names /// are "{OrchestratorName}-{tenant}-{guid}" or "{OrchestratorName}_{...}". /// private const string SchemaPartition = "$schema"; private const string SchemaRowKey = "queue-index"; - private const int SchemaVersion = 1; + + /// + /// Current on-disk schema version, applied once per storage account by : + /// 1 — the run index exists (see the RUN INDEX note above). + /// 2 — queue RowKeys are deterministic per (run, task) — {run}|{task} — instead of + /// time-prefixed, so re-dispatching a task UPDATES its row instead of writing a second one + /// (the duplicate-execution class). Enqueue time moves to the QueuedUtc property. + /// A single forward migration takes any older account straight to this version; there is no + /// backward-compatible dual-read — after the migration only the new key scheme is used. + /// + private const int SchemaVersion = 2; /// /// Rows buffered before the backfill flushes. Bounds peak memory on a very large queue — the @@ -93,17 +130,63 @@ public async Task InitializeAsync(CancellationToken ct = default) if (_initialized) return; await _store.EnsureTableAsync(_queueTable, ct); await _store.EnsureTableAsync(_indexTable, ct); - await BackfillIndexAsync(ct); + await MigrateSchemaAsync(ct); _initialized = true; } internal static string Bucket(int priority) => "P" + Math.Clamp(priority, 0, MaxPriorityBucket).ToString("D2", CultureInfo.InvariantCulture); - internal static string BuildRowKey(DateTime queuedUtc, string runName, string taskId) => - // D19 so ticks sort lexically the way they sort numerically — without the padding a queue that - // straddles a tick-digit boundary would silently reorder. - $"{queuedUtc.Ticks.ToString("D19", CultureInfo.InvariantCulture)}-{runName}-{taskId}"; + /// + /// The queue RowKey: deterministic per (run, task), so re-dispatching a task upserts its one row + /// instead of writing a second, time-prefixed one — the cause of a task running 2-6× (schema v2). + /// + /// Both components are escaped so the key is legal and the '|' separator is unambiguous; the row + /// itself carries RunName/TaskId as properties, so nothing needs to parse the key back apart. + /// + /// The trade: within a priority bucket Azure now returns rows in run|task order rather than + /// oldest-first. Priority still orders across buckets, and a fan-out enqueues its tasks together, so + /// sub-priority FIFO fairness is the only thing given up — cheap next to never running a task twice. + /// + internal static string BuildRowKey(string runName, string taskId) => + $"{EscapeKeyComponent(runName)}|{EscapeKeyComponent(taskId)}"; + + /// + /// Escape a run or task id for use inside a queue RowKey: the Azure-illegal key characters plus '|' + /// (the separator) and '%' (the escape marker itself), percent-encoded. Reversible and injective, so + /// distinct (run, task) pairs never collide, and ordinary names pass through untouched. + /// + private static string EscapeKeyComponent(string value) + { + var needsEscape = false; + foreach (var c in value) + { + if (c is '/' or '\\' or '#' or '?' or '%' or '|' || char.IsControl(c)) { needsEscape = true; break; } + } + if (!needsEscape) return value; + + var sb = new System.Text.StringBuilder(value.Length + 8); + foreach (var c in value) + { + if (c is '/' or '\\' or '#' or '?' or '%' or '|' || char.IsControl(c)) + sb.Append('%').Append(((int)c).ToString("X2", CultureInfo.InvariantCulture)); + else + sb.Append(c); + } + return sb.ToString(); + } + + /// The enqueue time embedded in a legacy (v1) row key — {ticks:D19}-{run}-{task} — or + /// null for a key that is not in that format. Used only by the one-time migration to carry the old + /// key's timestamp into the new row's QueuedUtc property. + internal static DateTime? ParseLegacyQueuedUtc(string rowKey) + { + if (rowKey.Length < 20 || rowKey[19] != '-') return null; + if (!long.TryParse(rowKey.AsSpan(0, 19), NumberStyles.None, CultureInfo.InvariantCulture, out var ticks)) + return null; + if (ticks <= 0 || ticks > DateTime.MaxValue.Ticks) return null; + return new DateTime(ticks, DateTimeKind.Utc); + } /// /// A run name as an index partition key. Azure Tables rejects '/', '\', '#', '?' and control @@ -163,7 +246,7 @@ public async Task EnqueueAsync(string runName, string taskId, int priority, Date CancellationToken ct = default) { var bucket = Bucket(priority); - var rowKey = BuildRowKey(queuedUtc, runName, taskId); + var rowKey = BuildRowKey(runName, taskId); await _store.UpsertAsync(_queueTable, new StoreRow(bucket, rowKey) { @@ -174,10 +257,15 @@ public async Task EnqueueAsync(string runName, string taskId, int priority, Date ["Priority"] = priority, ["Owner"] = "", ["LeaseUntil"] = (DateTimeOffset?)null, + // Enqueue time is a property now that it is no longer in the key (schema v2), so age and + // status reporting keep working while the key stays deterministic per (run, task). + ["QueuedUtc"] = new DateTimeOffset(queuedUtc, TimeSpan.Zero), } }, ct); await _store.UpsertAsync(_indexTable, IndexRow(runName, taskId, bucket, rowKey), ct); + + WakePump(); } /// Queue many tasks for one run. Chunked by the caller's priority into per-bucket batches. @@ -192,7 +280,8 @@ public async Task EnqueueBatchAsync(string runName, IReadOnlyList<(string TaskId foreach (var byBucket in tasks.GroupBy(t => Bucket(t.Priority))) { - var rows = byBucket.Select(t => new StoreRow(byBucket.Key, BuildRowKey(queuedUtc, runName, t.TaskId)) + var queuedOffset = new DateTimeOffset(queuedUtc, TimeSpan.Zero); + var rows = byBucket.Select(t => new StoreRow(byBucket.Key, BuildRowKey(runName, t.TaskId)) { Properties = { @@ -201,17 +290,20 @@ public async Task EnqueueBatchAsync(string runName, IReadOnlyList<(string TaskId ["Priority"] = t.Priority, ["Owner"] = "", ["LeaseUntil"] = (DateTimeOffset?)null, + ["QueuedUtc"] = queuedOffset, } }).ToList(); await _store.UpsertBatchAsync(_queueTable, byBucket.Key, rows, ct); indexRows.AddRange(byBucket.Select(t => - IndexRow(runName, t.TaskId, byBucket.Key, BuildRowKey(queuedUtc, runName, t.TaskId)))); + IndexRow(runName, t.TaskId, byBucket.Key, BuildRowKey(runName, t.TaskId)))); } if (indexRows.Count > 0) await _store.UpsertBatchAsync(_indexTable, IndexPartition(runName), indexRows, ct); + + if (tasks.Count > 0) WakePump(); } /// A queued task this worker now owns, with the row key needed to release it. @@ -325,6 +417,29 @@ public async Task RemoveAsync(ClaimedJob job, CancellationToken ct = default) await _store.DeleteAsync(_queueTable, job.Bucket, job.RowKey, ct); } + /// + /// Remove many finished tasks at once. The pump releases a whole claimed batch per cycle, so this + /// turns what was 2 point deletes per task (index + queue, one each) into + /// one transaction per partition: index rows share a run's partition, queue rows share a bucket. + /// + /// Ordering matches at the batch level: ALL index rows first, then the + /// queue rows. A crash in between leaves queue rows whose tasks are finished — claimed once more and + /// dropped as stale descriptors, an already-handled path — whereas deleting the queue rows first + /// would leave the index advertising work that no longer exists and stall those runs. + /// + public async Task RemoveBatchAsync(IReadOnlyList jobs, CancellationToken ct = default) + { + if (jobs.Count == 0) return; + + foreach (var byRun in jobs.GroupBy(j => IndexPartition(j.RunName))) + await _store.DeleteBatchAsync(_indexTable, byRun.Key, + byRun.Select(j => IndexRowKey(j.Bucket, j.RowKey)).ToList(), ct); + + foreach (var byBucket in jobs.GroupBy(j => j.Bucket)) + await _store.DeleteBatchAsync(_queueTable, byBucket.Key, + byBucket.Select(j => j.RowKey).ToList(), ct); + } + /// /// This run's index rows. One single-partition read — the operation every run-scoped method below /// used to perform as a full-table scan. @@ -392,6 +507,56 @@ public async Task RemoveRunAsync(string runName, CancellationToken ct = default) await _store.DeletePartitionAsync(_indexTable, IndexPartition(runName), ct); } + /// + /// Empty the durable queue: delete every queue row and every index row (keeping only the schema + /// marker). Returns the number of queue rows removed. + /// + /// A maintenance/reset primitive. It drops the BACKLOG, not in-flight work — a row a worker is already + /// running finishes, and the pump's later removal of it simply 404s. Tasks still Pending in the + /// orchestrator's own tables can be re-driven onto the queue by recovery, so pair this with cancelling + /// the runs when the intent is to STOP work rather than to clear a wedged or corrupted queue. + /// Deletes are streamed in bounded windows, so this holds a fixed amount of memory on any queue size. + /// + public async Task ClearAllAsync(CancellationToken ct = default) + { + await InitializeAsync(ct); + + var removed = await ClearTableAsync(_queueTable, keepSchema: false, ct); + await ClearTableAsync(_indexTable, keepSchema: true, ct); + + _logger.LogWarning("[JobQueue] Durable queue cleared — {Count} queue row(s) removed", removed); + return removed; + } + + /// Delete every row of one table (optionally sparing the schema marker), batched per + /// partition and flushed in bounded windows so a huge table never lands in memory at once. + private async Task ClearTableAsync(string table, bool keepSchema, CancellationToken ct) + { + var removed = 0; + var pending = new Dictionary>(StringComparer.Ordinal); + var buffered = 0; + + async Task FlushAsync() + { + foreach (var (partition, keys) in pending) + await _store.DeleteBatchAsync(table, partition, keys, ct); + removed += buffered; + pending.Clear(); + buffered = 0; + } + + await foreach (var row in _store.QueryTableAsync(table, ct)) + { + if (keepSchema && row.PartitionKey == SchemaPartition) continue; + if (!pending.TryGetValue(row.PartitionKey, out var keys)) pending[row.PartitionKey] = keys = []; + keys.Add(row.RowKey); + if (++buffered >= BackfillFlushThreshold) await FlushAsync(); + } + + await FlushAsync(); + return removed; + } + /// /// Hand back every claim on a run's rows, making them immediately claimable again. Returns how many /// were released. @@ -421,6 +586,10 @@ public async Task ReleaseRunClaimsAsync(string runName, CancellationToken c released++; } + // Freed claims are claimable again — wake the pump to pick them up rather than waiting for the + // recovery-path re-drive on its own timer. + if (released > 0) WakePump(); + return released; } @@ -429,17 +598,13 @@ public sealed record QueuedRow(string RunName, string TaskId, int Priority, Date bool Claimed, string Owner, string Bucket, string RowKey); /// - /// The enqueue timestamp a row key was built from, or null for a key that predates the format. - /// The inverse of 's D19 tick prefix. + /// A row's enqueue time: the QueuedUtc property (schema v2), falling back to the timestamp a + /// legacy v1 key was built from, then to now. For age/status reporting only. /// - internal static DateTime? ParseQueuedUtc(string rowKey) - { - if (rowKey.Length < 20 || rowKey[19] != '-') return null; - if (!long.TryParse(rowKey.AsSpan(0, 19), NumberStyles.None, CultureInfo.InvariantCulture, out var ticks)) - return null; - if (ticks <= 0 || ticks > DateTime.MaxValue.Ticks) return null; - return new DateTime(ticks, DateTimeKind.Utc); - } + private static DateTime QueuedUtcOf(StoreRow row) => + row.GetDateTimeOffset("QueuedUtc")?.UtcDateTime + ?? ParseLegacyQueuedUtc(row.RowKey) + ?? DateTime.UtcNow; /// /// Every row currently in the queue, in storage order (highest priority bucket first, oldest first @@ -461,7 +626,7 @@ public async Task> ListQueuedAsync(CancellationToken ct row.GetString("RunName") ?? "", row.GetString("TaskId") ?? "", row.GetInt32("Priority") ?? 0, - ParseQueuedUtc(row.RowKey) ?? DateTime.UtcNow, + QueuedUtcOf(row), !IsClaimable(row, now), row.GetString("Owner") ?? "", row.PartitionKey, @@ -529,7 +694,7 @@ public async Task ReprioritizeTaskAsync(string runName, string taskId, int await _store.DeleteAsync(_indexTable, partition, IndexRowKey(row.PartitionKey, row.RowKey), ct); await _store.DeleteAsync(_queueTable, row.PartitionKey, row.RowKey, ct); - var queuedUtc = ParseQueuedUtc(row.RowKey) ?? DateTime.UtcNow; + var queuedUtc = QueuedUtcOf(row); await EnqueueAsync(runName, taskId, newPriority, queuedUtc, ct); moved++; } @@ -564,38 +729,67 @@ public async Task> GetQueuedTaskIdsAsync(string runName, Cancell } /// - /// Build the run index for a queue that predates it. Runs at most once per storage account, ever: - /// the marker row written at the end is checked first, so every later start is a single point read. + /// Bring the queue tables up to , once per storage account. The marker row + /// written at the end is checked first, so every later start is a single point read. + /// + /// v1 built the run index; v2 additionally re-keys every queue row to the deterministic + /// {run}|{task} scheme () and moves the enqueue timestamp into the + /// QueuedUtc property. One forward pass takes any older account straight to the current + /// version — there is no dual-read, and after the pass only the new key scheme is used. /// - /// Awaited by rather than backgrounded, because the run-scoped reads - /// are only correct once it has finished. A half-built index under-reports, the orphan re-drive - /// reads that as "this task has no queue row", and re-queueing a task that already has one is how - /// the same task gets executed twice — the failure this queue exists to prevent. + /// Rows are rewritten new-key-first, old-key-deleted-after, so a crash mid-pass leaves the marker + /// unset and the next start finishes the job (a row already in the new scheme is re-written harmlessly + /// and not deleted). The pump awaits before it claims — and every + /// enqueue path calls it too — so no row is ever claimed or written while the migration is only + /// half-applied. /// - /// Concurrency needs no lock. Two instances starting together both scan and both write the same - /// deterministic rows, so the duplicated work is wasted but not wrong, and neither serves traffic - /// until its own scan completed. Rows enqueued during the scan are indexed by the enqueue path. + /// Awaited by InitializeAsync rather than backgrounded: the run-scoped reads and the deterministic + /// keys are only correct once it has finished. /// - private async Task BackfillIndexAsync(CancellationToken ct) + private async Task MigrateSchemaAsync(CancellationToken ct) { var marker = await _store.GetAsync(_indexTable, SchemaPartition, SchemaRowKey, ct); if ((marker?.GetInt32("Version") ?? 0) >= SchemaVersion) return; var started = DateTime.UtcNow; - _logger.LogInformation("[JobQueue] Building the run index for the first time — one full pass over {Table}", _queueTable); + _logger.LogInformation( + "[JobQueue] Migrating queue schema to v{Version} — one full pass over {Table}", SchemaVersion, _queueTable); - var pending = new Dictionary>(StringComparer.Ordinal); + var newQueue = new Dictionary>(StringComparer.Ordinal); // by bucket + var newIndex = new Dictionary>(StringComparer.Ordinal); // by run partition + var oldQueue = new Dictionary>(StringComparer.Ordinal); // bucket -> old row keys + var oldIndex = new Dictionary>(StringComparer.Ordinal); // run partition -> old index keys var buffered = 0; - var indexed = 0; + var migrated = 0; + var rekeyed = 0; var skipped = 0; + static void AddRow(Dictionary> map, string key, StoreRow row) + { + if (!map.TryGetValue(key, out var list)) map[key] = list = []; + list.Add(row); + } + static void AddKey(Dictionary> map, string key, string rowKey) + { + if (!map.TryGetValue(key, out var list)) map[key] = list = []; + list.Add(rowKey); + } + async Task FlushAsync() { - foreach (var (partition, rows) in pending) + // New rows first, so a crash before the deletes leaves BOTH and the re-run converges — never + // the index advertising a queue row that no longer exists. + foreach (var (bucket, rows) in newQueue) + await _store.UpsertBatchAsync(_queueTable, bucket, rows, ct); + foreach (var (partition, rows) in newIndex) await _store.UpsertBatchAsync(_indexTable, partition, rows, ct); + foreach (var (bucket, keys) in oldQueue) + await _store.DeleteBatchAsync(_queueTable, bucket, keys, ct); + foreach (var (partition, keys) in oldIndex) + await _store.DeleteBatchAsync(_indexTable, partition, keys, ct); - indexed += buffered; - pending.Clear(); + migrated += buffered; + newQueue.Clear(); newIndex.Clear(); oldQueue.Clear(); oldIndex.Clear(); buffered = 0; } @@ -605,17 +799,40 @@ async Task FlushAsync() var taskId = row.GetString("TaskId"); if (string.IsNullOrEmpty(runName) || string.IsNullOrEmpty(taskId)) { skipped++; continue; } - var partition = IndexPartition(runName); - if (!pending.TryGetValue(partition, out var rows)) - pending[partition] = rows = []; + var bucket = row.PartitionKey; + var newKey = BuildRowKey(runName, taskId); + var runPartition = IndexPartition(runName); + + // The new-scheme row: same bucket + claim state + priority, key deterministic, enqueue time as + // a property (from the row, or the legacy key, or now). + AddRow(newQueue, bucket, new StoreRow(bucket, newKey) + { + Properties = + { + ["RunName"] = runName, + ["TaskId"] = taskId, + ["Priority"] = row.GetInt32("Priority") ?? 0, + ["Owner"] = row.GetString("Owner") ?? "", + ["LeaseUntil"] = row.GetDateTimeOffset("LeaseUntil"), + ["QueuedUtc"] = new DateTimeOffset(QueuedUtcOf(row), TimeSpan.Zero), + } + }); + AddRow(newIndex, runPartition, IndexRow(runName, taskId, bucket, newKey)); - rows.Add(IndexRow(runName, taskId, row.PartitionKey, row.RowKey)); + // Delete the legacy row + index entry, UNLESS its key is already the new scheme (a re-run over + // already-migrated rows just re-writes them — deleting would drop what we just wrote). + if (row.RowKey != newKey) + { + rekeyed++; + AddKey(oldQueue, bucket, row.RowKey); + AddKey(oldIndex, runPartition, IndexRowKey(bucket, row.RowKey)); + } buffered++; if (buffered >= BackfillFlushThreshold) { await FlushAsync(); - _logger.LogInformation("[JobQueue] Run index backfill: {Indexed:N0} rows so far", indexed); + _logger.LogInformation("[JobQueue] Schema migration: {Migrated:N0} rows so far", migrated); } } @@ -627,13 +844,13 @@ async Task FlushAsync() { ["Version"] = SchemaVersion, ["BuiltUtc"] = new DateTimeOffset(started, TimeSpan.Zero), - ["RowsIndexed"] = indexed, + ["RowsIndexed"] = migrated, } }, ct); _logger.LogInformation( - "[JobQueue] Run index built: {Indexed:N0} rows in {Seconds:N0}s{Skipped} — this will not run again", - indexed, (DateTime.UtcNow - started).TotalSeconds, + "[JobQueue] Queue schema at v{Version}: {Migrated:N0} row(s) processed, {Rekeyed:N0} re-keyed, in {Seconds:N0}s{Skipped} — this will not run again", + SchemaVersion, migrated, rekeyed, (DateTime.UtcNow - started).TotalSeconds, skipped > 0 ? $", {skipped:N0} malformed row(s) skipped" : ""); } } diff --git a/Services/Storage/OrchestratorTableStore.cs b/Services/Storage/OrchestratorTableStore.cs index 75b6523..b096f41 100644 --- a/Services/Storage/OrchestratorTableStore.cs +++ b/Services/Storage/OrchestratorTableStore.cs @@ -222,12 +222,15 @@ public async Task> ListRunSummariesAsync() // Scanning instead is not an option: Azure Table cannot count server-side, so "is this run done" // would be a 7,000-row read per check. // - // The row lives in the TASKS table, in the run's own partition, and that placement is the whole - // design. A counter decremented separately from the task's terminal write is not idempotent — the - // status writer retries failed runs, so a replayed batch would decrement twice and strand a run that - // had actually finished. Sharing the partition lets CompleteTaskAsync mark the task terminal AND - // decrement the counter in ONE conditional transaction: exactly-once by construction, because a - // replay finds the task's ETag already moved on and the whole transaction is rejected. + // The row lives in the TASKS table, in the run's own partition, and that placement is deliberate: a + // task's terminal write and the counter decrement can then share ONE conditional transaction where + // exactly-once matters most — the cancel-a-run path (CancelPendingTaskAsync) uses exactly that, so a + // cancel racing a task's real completion cannot decrement the counter twice. + // + // The hot fan-out path decrements SEPARATELY (DecrementRemainingAsync), by design: the batched status + // writer coalesces terminal writes, and decrementing once per group after it lands keeps the write + // batched. Idempotency there rests on the writer never re-sending a group that landed, backstopped by + // ReconcileRemainingAsync (a full-partition recount) whenever a decrement is lost. // // The reserved row key cannot collide with a task id — task ids are caller-supplied names like // "CIPPStandard_IntuneTemplate__", never a control character. @@ -328,47 +331,6 @@ public Task InitRemainingAsync(string runName, int total, CancellationToken ct = return outstanding; } - /// - /// Mark one task terminal and decrement its run's outstanding count, atomically. - /// - /// Both rows share the run's partition, so this is a single conditional transaction guarded by both - /// ETags. That is what makes it exactly-once: a replay of the same completion finds the task row's - /// ETag already advanced, the transaction is rejected, and the counter is not decremented a second - /// time. A caller seeing false should re-read — either someone else completed this task, or the - /// counter moved under it and the decrement needs re-applying. - /// - /// The new outstanding count, or null if the transaction was rejected or rows are missing. - public async Task CompleteTaskAsync(string runName, OrchestratorTaskItem task, - CancellationToken ct = default) - { - for (var attempt = 0; attempt < CounterAttempts; attempt++) - { - var counter = await _store.GetAsync(_tasksTable, runName, CounterRowKey, ct); - var existing = await _store.GetAsync(_tasksTable, runName, task.Id, ct); - if (counter == null || existing == null) return null; - - // Already terminal in storage — this is a replay. The ETag guard alone does not catch it, - // because each attempt re-reads the CURRENT row and would happily guard against the - // post-completion version and decrement a second time. Completing a completed task is a - // no-op, not another decrement: report the count and leave it alone. - if (IsTerminal(existing.GetString("Status"))) - return counter.GetInt32("Remaining") ?? 0; - - var taskRow = BuildTaskRow(runName, task); - // Guard on the row as it stands now; a concurrent writer invalidates this and we re-read. - var guarded = new StoreRow(runName, task.Id) { ETag = existing.ETag, Properties = taskRow.Properties }; - - counter["Remaining"] = Math.Max(0, (counter.GetInt32("Remaining") ?? 0) - 1); - - if (await _store.TryReplaceBatchAsync(_tasksTable, runName, [guarded, counter], ct)) - return (int)counter["Remaining"]!; - } - - _logger.LogWarning("[OrchestratorStore] Could not complete {Task} in {Run} after {Attempts} attempts", - task.Id, runName, CounterAttempts); - return null; - } - /// What a status-guarded cancel actually did, so the caller can keep its view honest. public sealed record CancelWriteResult(bool Cancelled, string? CurrentStatus); @@ -528,6 +490,55 @@ public async Task> WriteTaskStatusBatchAsync(IReadOnlyList private const int MaxPropertyChars = 30_000; private const int MaxEntityChars = 450_000; + /// + /// Write a set of coalesced SMALL task results (single-property rows) to the Results table, grouped + /// by run (partition) and chunked to the backend's transaction limits by the store. The batched + /// counterpart to for results that fit one property; larger results + /// still go through StoreResultAsync's multi-row chunking path. + /// + /// + /// The run names whose results did NOT persist. The caller must retry these AND withhold those runs' + /// terminal task markers this flush, or a task could be counted done while its result is lost. + /// An empty list means everything landed. + /// + public async Task> WriteResultBatchAsync(IReadOnlyList results, + int maxConcurrency = 8, CancellationToken ct = default) + { + var groups = results.GroupBy(r => r.RunName).ToList(); + if (groups.Count == 0) return []; + + var failed = new System.Collections.Concurrent.ConcurrentBag(); + using var gate = new SemaphoreSlim(Math.Max(1, maxConcurrency)); + + var tasks = groups.Select(async group => + { + await gate.WaitAsync(ct); + try + { + var rows = group.Select(r => new StoreRow(r.RunName, r.TaskId) + { + Properties = { ["ResultJson"] = r.ResultJson } + }).ToList(); + await _store.UpsertBatchAsync(_resultsTable, group.Key, rows, ct); + } + catch (Exception ex) + { + // One run's failure must not discard the others. Record it; the caller requeues just this + // run's results and holds its terminal markers until they land together. + failed.Add(group.Key); + _logger.LogWarning(ex, "[OrchestratorStore] Result write failed for run {Run} ({Count} results) — will retry", + group.Key, group.Count()); + } + finally + { + gate.Release(); + } + }); + + await Task.WhenAll(tasks); + return failed.ToList(); + } + /// Store a single task result, chunking large JSON across properties/rows as needed. public async Task StoreResultAsync(string runName, string taskId, string resultJson) { diff --git a/Services/Storage/ResultWrite.cs b/Services/Storage/ResultWrite.cs new file mode 100644 index 0000000..dbc8e6a --- /dev/null +++ b/Services/Storage/ResultWrite.cs @@ -0,0 +1,10 @@ +namespace Craft.Storage; + +/// +/// A small task result queued for the coalescing status writer. Only results that fit a single Azure +/// Table property travel this way; larger results keep the chunked, directly-awaited +/// path. Written to the Results table before the +/// task's terminal status marker in the same flush, so a result is always durable before its task is +/// counted done. +/// +public record ResultWrite(string RunName, string TaskId, string ResultJson); diff --git a/Services/Telemetry/StartupReport.cs b/Services/Telemetry/StartupReport.cs new file mode 100644 index 0000000..c1a59e1 --- /dev/null +++ b/Services/Telemetry/StartupReport.cs @@ -0,0 +1,22 @@ +namespace Craft.Telemetry; + +// The boot-inventory envelope. Serialized with web defaults (camelCase). The ingest is tolerant, so +// this stays a small, stable core; new report types ride the same surface via reportType. +internal sealed record StartupReport( + int SchemaVersion, + string ReportType, + string ReportId, + string InstanceId, + DateTimeOffset SentUtc, + AppInfo App, + CraftInfo Craft, + HostInfo Host, + SurfaceInfo Surface); + +internal sealed record AppInfo(string Id, string? Version, string? Commit, string? ImageTag); + +internal sealed record CraftInfo(string? Version); + +internal sealed record HostInfo(string? Sku, string[] Roles, string Platform, string? Region); + +internal sealed record SurfaceInfo(int RouteCount, int ScheduledTaskCount); diff --git a/Services/Telemetry/StartupTelemetryService.cs b/Services/Telemetry/StartupTelemetryService.cs new file mode 100644 index 0000000..7e19a5b --- /dev/null +++ b/Services/Telemetry/StartupTelemetryService.cs @@ -0,0 +1,251 @@ +using System.Reflection; +using System.Text; +using System.Text.Json; +using Craft.Configuration; +using Craft.Endpoints; +using Craft.Hosting; +using Craft.Orchestration; +using Craft.PowerShellHost; +using Craft.Storage; +using Microsoft.Extensions.Options; + +namespace Craft.Telemetry; + +/// +/// Fires ONCE per process start: after readiness and a jittered delay, POSTs a small usage +/// "boot inventory" to a reporting ingest, storm-guarded so a crash loop cannot flood it. +/// +/// +/// Runtime-level, so every Craft-based app reports with zero app work. It must never affect the host: +/// every failure path logs at debug/info and swallows. The storm guard is persisted in table storage +/// (outside the container, so it survives crash loops) and is fail-closed — if the guard state cannot +/// be read, nothing is sent. +/// +/// +internal sealed class StartupTelemetryService( + IOptions settings, + ICraftTableStore store, + StorageHealthMonitor storageHealth, + ScriptRepository scriptRepo, + SchedulerService scheduler, + NativeEndpointCatalog nativeCatalog, + CraftRoles roles, + IHttpClientFactory httpFactory, + IHostApplicationLifetime lifetime, + ILogger logger) : BackgroundService +{ + private static readonly JsonSerializerOptions s_json = new(JsonSerializerDefaults.Web); + private const string GuardPartition = "guard"; + private const string ColInstanceId = "InstanceId"; + private const string ColLastSent = "LastSentUtc"; + + protected override async Task ExecuteAsync(CancellationToken stoppingToken) + { + try + { + await RunAsync(stoppingToken); + } + catch (OperationCanceledException) when (stoppingToken.IsCancellationRequested) + { + // Shutting down before the delay elapsed — the next boot is the retry. + } + catch (Exception ex) + { + // The emitter must never take the host down. Swallow everything. + logger.LogDebug(ex, "[Telemetry] Startup emitter failed; swallowed"); + } + } + + private async Task RunAsync(CancellationToken ct) + { + var t = settings.Value.Telemetry; + + if (OptOut()) + { + logger.LogInformation("[Telemetry] CRAFT_TELEMETRY_OPTOUT is set — not sending"); + return; + } + if (!t.Enabled) + { + logger.LogDebug("[Telemetry] Disabled (App:Telemetry:Enabled=false)"); + return; + } + + var appId = t.AppId?.Trim(); + if (string.IsNullOrEmpty(appId) || string.IsNullOrWhiteSpace(t.Endpoint)) + { + logger.LogInformation("[Telemetry] Enabled but AppId/Endpoint unset — not sending"); + return; + } + + // The guard lives in storage, which a frontend-only node never resolves. + if (!(roles.Http || roles.Background)) + { + logger.LogDebug("[Telemetry] Node carries no storage role — not sending"); + return; + } + + await WaitForStartedAsync(ct); + if (!await storageHealth.WaitUntilReadyAsync(TimeSpan.FromSeconds(60), ct)) + { + logger.LogInformation("[Telemetry] Storage not ready — fail-closed, not sending"); + return; + } + + // Read or mint the storm-guard row. Fail-closed: never emit unguarded. + var guardKey = TableKeys.Sanitize($"{appId}:{SiteName()}"); + GuardState guard; + try + { + guard = await ReadOrMintGuardAsync(t.GuardTable, guardKey, ct); + } + catch (Exception ex) + { + logger.LogInformation(ex, "[Telemetry] Guard state unreadable — fail-closed, not sending"); + return; + } + + // Storm guard: at most one report per MinIntervalHours per instance. + var minInterval = TimeSpan.FromHours(Math.Max(1, t.MinIntervalHours)); + if (guard.LastSentUtc is { } last && DateTimeOffset.UtcNow - last < minInterval) + { + logger.LogDebug("[Telemetry] Within the min-interval window — skipping this boot"); + return; + } + + // Jittered, deterministic-per-instance delay. A fast crash loop dies inside this window and + // never reaches the send; it also keeps telemetry out of the cold-start window on Basic SKUs. + await Task.Delay(JitterDelay(guard.InstanceId, t), ct); + + var report = BuildReport(appId, guard.InstanceId); + if (await PostAsync(report, t, ct)) + { + // lastSentUtc advances ONLY on a successful send, so a failed send never silences the instance. + await WriteGuardAsync(t.GuardTable, guardKey, guard.InstanceId, DateTimeOffset.UtcNow, ct); + logger.LogInformation("[Telemetry] Startup report sent for {AppId}", appId); + } + } + + private async Task WaitForStartedAsync(CancellationToken ct) + { + if (lifetime.ApplicationStarted.IsCancellationRequested) return; + + var tcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + using var startedReg = lifetime.ApplicationStarted.Register(() => tcs.TrySetResult()); + using var ctReg = ct.Register(() => tcs.TrySetCanceled(ct)); + await tcs.Task; + } + + private async Task ReadOrMintGuardAsync(string table, string key, CancellationToken ct) + { + await store.EnsureTableAsync(table, ct); + + var row = await store.GetAsync(table, GuardPartition, key, ct); + if (row is not null && row.GetString(ColInstanceId) is { Length: > 0 } existing) + return new GuardState(existing, row.GetDateTimeOffset(ColLastSent)); + + // First ever run for this key: mint a stable instance id and persist it (no lastSent yet). + var minted = Guid.NewGuid().ToString(); + await WriteGuardAsync(table, key, minted, lastSent: null, ct); + return new GuardState(minted, null); + } + + private async Task WriteGuardAsync( + string table, string key, string instanceId, DateTimeOffset? lastSent, CancellationToken ct) + { + var row = new StoreRow(GuardPartition, key); + row[ColInstanceId] = instanceId; + if (lastSent is { } value) row[ColLastSent] = value; + await store.UpsertAsync(table, row, ct); + } + + private StartupReport BuildReport(string appId, string instanceId) + { + var roleNames = new List(3); + if (roles.Frontend) roleNames.Add("frontend"); + if (roles.Http) roleNames.Add("api"); + if (roles.Background) roleNames.Add("background"); + + // Counts only — no route names, no per-route hits. + var routeCount = nativeCatalog.Endpoints.Count + scriptRepo.HttpRoutes.Count; + var taskCount = scheduler.Tasks.Count; + + return new StartupReport( + SchemaVersion: 1, + ReportType: "startup", + ReportId: Guid.NewGuid().ToString(), + InstanceId: instanceId, + SentUtc: DateTimeOffset.UtcNow, + App: new AppInfo(appId, Env("APP_VERSION"), Env("COMMIT_SHA"), Env("IMAGE_TAG")), + Craft: new CraftInfo(CraftVersion()), + Host: new HostInfo(Env("WEBSITE_SKU"), roleNames.ToArray(), Platform(), Region: null), + Surface: new SurfaceInfo(routeCount, taskCount)); + } + + private async Task PostAsync(StartupReport report, TelemetrySettings t, CancellationToken ct) + { + try + { + var client = httpFactory.CreateClient("craft-telemetry"); + using var cts = CancellationTokenSource.CreateLinkedTokenSource(ct); + cts.CancelAfter(TimeSpan.FromSeconds(Math.Max(1, t.TimeoutSeconds))); + + var json = JsonSerializer.Serialize(report, s_json); + using var content = new StringContent(json, Encoding.UTF8, "application/json"); + using var request = new HttpRequestMessage(HttpMethod.Post, t.Endpoint) { Content = content }; + if (!string.IsNullOrEmpty(t.Token)) + request.Headers.TryAddWithoutValidation("X-Telemetry-Token", t.Token); + + using var response = await client.SendAsync(request, cts.Token); + if (response.IsSuccessStatusCode) return true; + + logger.LogDebug("[Telemetry] Ingest returned HTTP {Status}", (int)response.StatusCode); + return false; + } + catch (Exception ex) + { + logger.LogDebug(ex, "[Telemetry] POST failed; the next boot is the retry"); + return false; + } + } + + private static TimeSpan JitterDelay(string instanceId, TelemetrySettings t) + { + var min = Math.Max(0, t.MinStartupDelaySeconds); + var max = Math.Max(min, t.MaxStartupDelaySeconds); + var span = (uint)(max - min) + 1; + var seconds = min + (int)((uint)StableHash(instanceId) % span); + return TimeSpan.FromSeconds(seconds); + } + + // string.GetHashCode is randomized per process, so roll a stable one for a deterministic spread. + private static int StableHash(string value) + { + unchecked + { + var hash = 17; + foreach (var c in value) hash = (hash * 31) + c; + return hash; + } + } + + private static string? CraftVersion() => + typeof(StartupTelemetryService).Assembly + .GetCustomAttribute()?.InformationalVersion; + + private static string Platform() => Env("WEBSITE_SITE_NAME") is not null ? "appservice" : "container"; + + private static string SiteName() => Env("WEBSITE_SITE_NAME") ?? "self"; + + private static bool OptOut() + { + var value = Environment.GetEnvironmentVariable("CRAFT_TELEMETRY_OPTOUT"); + return string.Equals(value, "1", StringComparison.Ordinal) + || string.Equals(value, "true", StringComparison.OrdinalIgnoreCase); + } + + private static string? Env(string name) => + Environment.GetEnvironmentVariable(name) is { Length: > 0 } value ? value : null; + + private sealed record GuardState(string InstanceId, DateTimeOffset? LastSentUtc); +} diff --git a/appsettings.example.jsonc b/appsettings.example.jsonc index d6159b4..6982b96 100644 --- a/appsettings.example.jsonc +++ b/appsettings.example.jsonc @@ -80,11 +80,22 @@ // collapsed into a single bucket. Requests over the limit get HTTP 429 with a Retry-After header. // Set "Enabled": false to turn it off (e.g. for load/perf testing); CRAFT_RATELIMIT_ENABLED=true // can also force it on. + // + // ApiConcurrencyLimit adds a second, orthogonal cap: the most requests a single app-only API + // client (client-credentials caller, idp=aad) may have occupying the worker system AT ONCE — + // counting both those queued waiting for a runspace and those executing, since the limiter's lease + // spans the whole downstream pipeline. Keyed per client (its AppId), so one automation cannot hold + // every runspace and starve the interactive UI, which is never capped by this. A rate cap + // (PermitPerWindow) bounds requests/second; this bounds simultaneous-in-flight. 0 (default) = off. + // Over-limit requests are rejected immediately with 429 + Retry-After (no concurrency queue). + // Env override: CRAFT_API_CONCURRENCY_LIMIT. Works even with "Enabled": false (rate limiter off, + // concurrency cap on) — the limiter middleware runs whenever either is active. // "RateLimit": { // "Enabled": true, - // "PermitPerWindow": 300, // requests allowed per window, per client - // "WindowSeconds": 10, // window length in seconds - // "QueueLimit": 0 // requests queued at the limit before rejecting (0 = reject immediately) + // "PermitPerWindow": 300, // requests allowed per window, per client + // "WindowSeconds": 10, // window length in seconds + // "QueueLimit": 0, // requests queued at the limit before rejecting (0 = reject immediately) + // "ApiConcurrencyLimit": 0 // max simultaneous in-flight requests per API client (0 = unlimited) // }, // Realtime SSE channel served at /.craft/events. Downstream code publishes job events through @@ -142,16 +153,43 @@ // (e.g. "Basic", "PremiumV3"). Ignored when SkuEnv is empty. // Cpu: compared to Environment.ProcessorCount (respects cgroup limits in // Docker). Omit or 0 = match any CPU count. + // GCHeapHardLimitMB: optional GC heap hard limit (MB) for this tier. The + // DOTNET_GCHeapHardLimit env var is consumed before managed code runs, + // so this lands via GC.RefreshMemoryLimit at startup instead. Three-way, + // mirroring the CRAFT_GC_HEAP_LIMIT_MB override below: omit/null (or a + // negative value) = keep the process baseline; 0 = disable the cap entirely, + // deferring to container memory (for a tier with more RAM than the baked + // limit lets it use); > 0 = set that many MB. Raising or removing is always + // safe; a positive value the heap has already outgrown is refused and logged. + // Per-instance override: CRAFT_GC_HEAP_LIMIT_MB wins over this (a positive + // value sets the cap; 0 disables the cap entirely, deferring to container + // memory) — hand-tune one host without touching the fleet-wide profiles. // First match wins. No match (or any parse failure) leaves the baseline above. // Set IgnoreSkuProfiles: true to disable this entirely. // "IgnoreSkuProfiles": false, // "SkuProfiles": [ // { "SkuEnv": "WEBSITE_SKU", "Sku": "Basic", "Cpu": 1, "HttpPoolSize": 2, "BgPoolSize": 2 }, // { "SkuEnv": "WEBSITE_SKU", "Sku": "Basic", "Cpu": 2, "HttpPoolSize": 3, "BgPoolSize": 4 }, - // { "SkuEnv": "WEBSITE_SKU", "Sku": "Basic", "Cpu": 4, "HttpPoolSize": 4, "BgPoolSize": 4 }, + // { "SkuEnv": "WEBSITE_SKU", "Sku": "Basic", "Cpu": 4, "HttpPoolSize": 4, "BgPoolSize": 4, "GCHeapHardLimitMB": 5120 }, // { "SkuEnv": "WEBSITE_SKU", "Sku": "PremiumV3", "Cpu": 2, "HttpPoolSize": 4, "BgPoolSize": 8 }, // { "Cpu": 8, "HttpPoolSize": 6, "BgPoolSize": 12 } // ], + // + // A second SkuProfiles matrix, selected by the *presence* of an env var. When the var named by + // SkuProfilesAltEnv is set to any non-empty value, SkuProfilesAlt is matched instead of SkuProfiles + // — e.g. a smaller per-instance sizing for instances packed onto one shared App Service Plan. Falls + // back to SkuProfiles when the var is unset or SkuProfilesAlt is empty. Same fields as SkuProfiles. + // Set the var on the packed instances and leave it unset on dedicated ones. As with SkuProfiles, an + // entry that matches nothing just keeps the global HttpPoolSize/BgPoolSize — no catch-all needed. + // "SkuProfilesAltEnv": "CIPP_HOSTED", + // "SkuProfilesAlt": [ + // { "SkuEnv": "WEBSITE_SKU", "Sku": "PremiumV3", "Cpu": 8, "HttpPoolSize": 2, "BgPoolSize": 4, "GCHeapHardLimitMB": 2048 } + // ], + // + // Per-instance overrides for the pool sizes themselves, winning over any matched profile (same + // shape as CRAFT_GC_HEAP_LIMIT_MB): CRAFT_HTTP_POOL_SIZE / CRAFT_BG_POOL_SIZE. A non-negative + // integer wins; unset / negative / unparseable defers to the matrix. Hand-tune one host without + // touching the fleet-wide profiles. // Maximum execution time (seconds) for HTTP request handlers // When exceeded, the PowerShell pipeline is stopped and the worker is reclaimed @@ -163,6 +201,14 @@ // 0 = no timeout (default). Recommended: 600-3600 for background jobs // "BgTimeoutSeconds": 0, + // How long an HTTP request waits for a free runspace when the pool is saturated before it is + // shed with 503 "Server busy, please retry". A load-shedding bound, NOT a capacity knob — it + // does not add throughput, it only decides how long callers wait before a spurious 503. Widen + // it to absorb brief bursts; raise HttpPoolSize/MinThreads for steady saturation. Distinct from + // HttpTimeoutSeconds (which bounds execution once a worker is held). + // 0 = built-in default of 30s. Env override: CRAFT_HTTP_QUEUE_TIMEOUT (seconds). + // "HttpQueueTimeoutSeconds": 30, + // Extra env vars injected into every runspace // "EnvVars": { "MY_VAR": "value" }, diff --git a/perf-harness/api-harness/API/Modules/PerfApi/PerfApi.psd1 b/perf-harness/api-harness/API/Modules/PerfApi/PerfApi.psd1 index f41f167..3e0b5f9 100644 --- a/perf-harness/api-harness/API/Modules/PerfApi/PerfApi.psd1 +++ b/perf-harness/api-harness/API/Modules/PerfApi/PerfApi.psd1 @@ -5,7 +5,7 @@ Author = 'CRAFT perf-harness' Description = 'Synthetic HTTP endpoints for load-testing CRAFT in http-only mode. Not for production.' PowerShellVersion = '7.2' - FunctionsToExport = @('Invoke-PerfPing', 'Invoke-PerfEcho', 'Invoke-PerfCpu', 'Invoke-PerfSleep', 'Invoke-PerfJson', 'Invoke-PerfBgEnqueue', 'Push-PerfBg', 'Push-PerfBgLeaf', 'Invoke-ListPerf', 'Invoke-PerfWhoami', 'Invoke-PerfTimerTick', 'Invoke-PerfTimerCount', 'Invoke-PerfPublish') + FunctionsToExport = @('Invoke-PerfPing', 'Invoke-PerfEcho', 'Invoke-PerfCpu', 'Invoke-PerfSleep', 'Invoke-PerfJson', 'Invoke-PerfBgEnqueue', 'Push-PerfBg', 'Push-PerfBgLeaf', 'Invoke-ListPerf', 'Invoke-PerfWhoami', 'Invoke-PerfTimerTick', 'Invoke-PerfTimerCount', 'Invoke-PerfPublish', 'Invoke-PerfAllocation', 'Invoke-PerfRuns') CmdletsToExport = @() VariablesToExport = @() AliasesToExport = @() diff --git a/perf-harness/api-harness/API/Modules/PerfApi/PerfApi.psm1 b/perf-harness/api-harness/API/Modules/PerfApi/PerfApi.psm1 index 1c9c5e1..c896a50 100644 --- a/perf-harness/api-harness/API/Modules/PerfApi/PerfApi.psm1 +++ b/perf-harness/api-harness/API/Modules/PerfApi/PerfApi.psm1 @@ -60,7 +60,9 @@ function Invoke-PerfBgEnqueue { $n = 500; if ($Request.Query.n) { $n = [int]$Request.Query.n } $taskms = 0; if ($Request.Query.taskms) { $taskms = [int]$Request.Query.taskms } $childn = 0; if ($Request.Query.childn) { $childn = [int]$Request.Query.childn } - $batch = @(for ($i = 0; $i -lt $n; $i++) { @{ FunctionName = 'PerfBg'; idx = $i; taskms = $taskms; childn = $childn } }) + $allocmb = 0; if ($Request.Query.allocmb) { $allocmb = [int]$Request.Query.allocmb } + $holdms = 0; if ($Request.Query.holdms) { $holdms = [int]$Request.Query.holdms } + $batch = @(for ($i = 0; $i -lt $n; $i++) { @{ FunctionName = 'PerfBg'; idx = $i; taskms = $taskms; childn = $childn; allocmb = $allocmb; holdms = $holdms } }) $run = Start-CraftOrchestrator -InputObject @{ OrchestratorName = "PerfBg-$([guid]::NewGuid().ToString('N').Substring(0, 8))" Batch = $batch @@ -69,10 +71,23 @@ function Invoke-PerfBgEnqueue { } # The background task each orchestrator batch item runs (Invoke-CraftTask calls Push-{FunctionName}). -# Sleeps taskms to simulate real work, and optionally spawns a child orchestration (fan-out dependency). +# Sleeps taskms to simulate work; allocmb/holdms allocate a large object (LOH) and hold it to create real +# heap pressure across concurrent workers; optionally spawns a child orchestration (fan-out dependency). function Push-PerfBg { param($Item) if ($Item.taskms -and [int]$Item.taskms -gt 0) { Start-Sleep -Milliseconds ([int]$Item.taskms) } + + # Real memory pressure: a single large byte[] lands on the Large Object Heap (>85 KB), touched so the + # pages are actually committed, then held so concurrent tasks pile up live memory at once. Under a GC + # heap hard limit smaller than (workers x allocmb), the allocation throws OutOfMemoryException — which + # the orchestrator must catch as a task failure WITHOUT taking the dispatch loop down with it. + if ($Item.allocmb -and [int]$Item.allocmb -gt 0) { + $buf = [byte[]]::new([int]$Item.allocmb * 1MB) + for ($i = 0; $i -lt $buf.Length; $i += 4096) { $buf[$i] = 1 } + if ($Item.holdms -and [int]$Item.holdms -gt 0) { Start-Sleep -Milliseconds ([int]$Item.holdms) } + $buf = $null + } + if ($Item.childn -and [int]$Item.childn -gt 0) { $cn = [int]$Item.childn $childBatch = @(for ($j = 0; $j -lt $cn; $j++) { @{ FunctionName = 'PerfBgLeaf'; idx = $j } }) @@ -90,6 +105,63 @@ function Push-PerfBgLeaf { return @{ ok = $true; idx = $Item.idx } } +# Worker/queue allocation snapshot — the harness's downstream wrapper around the CRAFT bridge, standing +# in for what a real app (e.g. CIPP) does: CRAFT exposes the data as [Craft.Services.WorkerMetricsBridge], +# the app wraps whichever fields it wants into its own endpoint. Returns the shape run-orch.ps1 and the +# time-to-first-work probes read (jm/queue/limiter/pool) plus memory, for the OOM-resilience harness. +function Invoke-PerfAllocation { + param($Request, $TriggerMetadata) + $s = [Craft.Services.WorkerMetricsBridge]::GetSnapshot() + return @{ StatusCode = 200; Body = @{ + jm = @{ + active = $s.Jobs.Running + queued = $s.Jobs.QueuedLocal + completed = $s.Jobs.Completed + failed = $s.Jobs.Failed + totalProcessed = $s.Jobs.TotalProcessed + maxConcurrency = $s.Jobs.MaxConcurrency + } + queue = @{ + unclaimed = $s.Jobs.QueuedDurable + total = $s.Jobs.Queued + } + limiter = @{ + currentMax = $s.Limiter.CurrentMax + baseMax = $s.Limiter.BaseConcurrency + ceiling = $s.Limiter.CeilingConcurrency + active = $s.Limiter.Active + waiting = $s.Limiter.Waiting + httpThrottled = $s.Limiter.IsHttpThrottled + } + pool = @{ + bgBusy = $s.BgPool.BusyCount + bgTotal = $s.BgPool.PoolSize + bgAvail = $s.BgPool.Available + httpAvail = $s.HttpPool.Available + } + memory = @{ + heapMB = $s.Memory.HeapMB + rssMB = $s.Memory.RssMB + committedMB = $s.Memory.CommittedMB + containerLimitMB = $s.Memory.ContainerLimitMB + containerUsedMB = $s.Memory.ContainerUsedMB + gcHeapLimitMB = $s.Memory.GCHeapLimitMB + usagePct = $s.Memory.UsagePct + gc0 = $s.Memory.GC0; gc1 = $s.Memory.GC1; gc2 = $s.Memory.GC2 + } + } } +} + +# Durable run summaries (table-backed via the bridge), so the OOM harness can confirm ALL tasks reached a +# terminal state even across a crash/restart — the in-memory JobManager counters reset, the tables do not. +function Invoke-PerfRuns { + param($Request, $TriggerMetadata) + $runs = [Craft.Services.WorkerMetricsBridge]::GetRunSummaries() + return @{ StatusCode = 200; Body = @{ runs = @($runs | ForEach-Object { + @{ name = $_.Name; total = $_.Total; completed = $_.Completed; failed = $_.Failed; running = $_.Running; queued = $_.Queued } + }) } } +} + # Identity reflector: returns the principal CRAFT resolved for this request — the EasyAuth # x-ms-client-principal (base64 claims), plus X-Forwarded-For. Used to confirm header decoding, # role lookup, and client-IP pass-through. diff --git a/perf-harness/docker-compose.bg.yml b/perf-harness/docker-compose.bg.yml index 6fa81c0..0b92b7a 100644 --- a/perf-harness/docker-compose.bg.yml +++ b/perf-harness/docker-compose.bg.yml @@ -39,6 +39,14 @@ services: - App__ReadinessMode=Immediate - App__Setup__Enabled=false - App__Orchestrator__TablePrefix=PerfBgOrch + # OOM-resilience harness (run-oom.ps1): cap the .NET GC heap just above baseline to prove the + # durable-queue backlog keeps memory bounded regardless of fan-out size. Empty = no cap. + - CRAFT_GC_HEAP_LIMIT_MB=${GC_HEAP_LIMIT_MB:-} + # Pump claim batch / poll interval. Empty = defaults (batch = Bg pool, poll 1000ms). The OOM harness + # raises the batch so a huge already-enqueued backlog drains at batch/interval instead of pool/interval + # — the JobManager buffer stays O(batch) (still tiny), which is the whole point being measured. + - JobQueueBatchSize=${JOB_BATCH:-} + - JobQueuePollIntervalMs=${JOB_POLL_MS:-} # BackgroundTaskLimiter tuning (top-level config keys). run-orch.ps1 A/Bs the ramp behavior. # Defaults reproduce the app defaults on a small box (base 2, scale-up after 15s, ceiling = BG pool). - BackgroundBaseConcurrency=${BG_BASE:-2} diff --git a/perf-harness/oom-analysis.md b/perf-harness/oom-analysis.md new file mode 100644 index 0000000..69a52af --- /dev/null +++ b/perf-harness/oom-analysis.md @@ -0,0 +1,91 @@ +# Orchestrator memory-boundedness & OOM resilience + +**What:** does the durable-queue orchestrator keep memory bounded under a massive fan-out, and does the +job-dispatch machinery keep going when the workload creates real heap pressure — up to and including an +out-of-memory condition? Measured with `run-oom.ps1` (backend mode + Azurite), which brings CRAFT up under +an optional GC heap hard limit (`CRAFT_GC_HEAP_LIMIT_MB`), enqueues N tasks that allocate a large-object +(LOH) buffer and hold it, and polls `/API/PerfAllocation` (a PerfApi wrapper over +`WorkerMetricsBridge.GetSnapshot()`) tracking peak heap, task completions/failures, and whether the +dispatch loop keeps making progress. 2 vCPU, BG pool 8, burst-to-ceiling, pump batch 100. + +## 1. Memory is bounded by the buffer, not the backlog + +A 20,000-task fan-out (2,500× the 8-worker pool), no-op tasks, unconstrained: + +| metric | value | +|---|--:| +| baseline heap (idle) | 15 MB | +| **peak heap while 20k drained** | **64 MB** | +| peak container RSS | 180 MB | +| all tasks completed | 20,000 / 20,000 | + +The managed heap oscillated 41–64 MB for the entire drain while the durable backlog fell from 19,900 to +0. **Heap does not scale with fan-out size** — the backlog lives in the `Queue` table and the JobManager +holds only a pool-sized (+batch) buffer. This is the core promise of the durable-queue design, and it +holds: a run of any size costs O(buffer) memory, not O(N). + +## 2. A GC heap hard limit is back-pressure, not a crash — while the *live* set fits + +Tasks that allocate a 48–90 MB LOH buffer and hold it, 8 concurrent, under a hard limit at or below the +natural working set: + +| alloc/task | hold | GC limit | peak heap | task OOMs | outcome | +|--:|--:|--:|--:|--:|---| +| 48 MB | 300 ms | 256 MB | 221 MB | 0 | all 1000 done — GC collected released buffers, stayed under | +| 48 MB | 1500 ms | 256 MB | 217 MB | 0 | all 400 done | +| 48 MB | 300 ms | **160 MB** | **118 MB** | 0 | all 500 done — a *tighter* limit made the GC hold the live set *lower* | +| 90 MB | 500 ms | 160 MB | 112 MB | 0 | all 200 done | + +The .NET GC hard limit does **not** OOM as long as the *live* (simultaneously-referenced) set fits: it +collects aggressively and throttles allocation (gc2 counts explode — hundreds of full GCs) to stay under +the cap. Because the harness tasks release their buffer promptly and the dispatch/storage pipeline staggers +the 8 workers, only ~1–3 buffers are ever live at once, so the workload runs to completion at a bounded +heap even when the limit is well below `pool × alloc`. **The limit trades throughput (GC overhead) for a +memory ceiling — it does not, on its own, take the process down.** + +## 3. A *fatal* OOM does crash the process — and only restart+recovery finishes the run + +Push the per-task allocation close to the whole limit so even one live buffer plus the orchestrator's own +concurrent allocations cannot fit — **230 MB/task against a 256 MB limit, 8 concurrent**: + +- **Catchable task OOMs are handled and dispatch keeps going.** Dozens of + `PS error in Invoke-CraftTask: …OutOfMemoryException` — the 230 MB allocation threw, the task's + try/catch marked it Failed, and the loop dispatched the next task (completions continue in the log). + The dispatch guards work for a catchable OOM. +- **But a fatal runtime OOM is uncatchable.** When the GC hard limit is exhausted to where the runtime + can't allocate for its *own* operation, .NET FailFasts: the process aborted with **exit 139 (SIGSEGV)**, + `OOMKilled=false`, last line a bare `Out of memory.` — at task 80/150. No user `try/catch` (nor the + pump's cycle guard, nor the status writer's `LogSafely`) can prevent a runtime FailFast; it takes the + dispatch loop down with the process. +- **Durable crash-recovery is what finishes the work.** Restarting against the same Azurite state: + `Found interrupted run … Released 54 stale claim(s) held by the previous process … Resuming interrupted + run: 50 pending`. With recovery pacing the re-dispatch, the 230 MB allocations ran at low enough + concurrency to fit (250 < 256 MB) and completed; heap returned to ~21 MB and the process stayed up. + +## Conclusions + +1. **Memory is bounded** — a 20k fan-out peaks at ~64 MB managed heap; the backlog is in the table, the + JobManager buffer is O(batch). The design's central claim holds. +2. **The dispatch loop survives everything it *can* survive.** A GC heap hard limit is back-pressure while + the live set fits (no OOM); a catchable task OOM is caught, the task fails, and dispatch continues. +3. **A fatal .NET OOM is the one thing no guard can catch** — the runtime FailFasts the whole process. + The resilience boundary is therefore *process restart + durable crash-recovery*, which is implemented + and proven: interrupted runs resume, stale claims are released, and the run reaches a terminal state. +4. **Practical guidance:** keep per-task peak allocation a small fraction of `GCHeapLimit ÷ BgPoolSize` so + the GC's back-pressure (not a fatal OOM) is what bounds memory. When a task genuinely can OOM, the + safety net is the container restart policy plus recovery — so a heap limit should be paired with a + restart-on-exit host (Azure App Service restarts on crash) and the per-task `MaxRetries` cap, which + turns a poison (repeatedly-OOMing) task Failed after a few attempts instead of crash-looping forever. + +## Reproduce + +```powershell +# 1. Bounded memory under a massive fan-out (no OOM): +pwsh scripts\run-oom.ps1 -Tasks 20000 -Label bounded + +# 2. GC hard limit as back-pressure (real LOH work, still completes): +pwsh scripts\run-oom.ps1 -Tasks 500 -AllocMB 48 -HoldMs 300 -HeapLimitMB 160 -Label backpressure + +# 3. Force a fatal OOM and observe crash + recovery (KeepUp to inspect, then `docker start` the container): +pwsh scripts\run-oom.ps1 -Tasks 150 -AllocMB 230 -HoldMs 200 -HeapLimitMB 256 -Label fatal -KeepUp +``` diff --git a/perf-harness/scripts/run-e2e.ps1 b/perf-harness/scripts/run-e2e.ps1 index 24ce413..ce8b581 100644 --- a/perf-harness/scripts/run-e2e.ps1 +++ b/perf-harness/scripts/run-e2e.ps1 @@ -95,7 +95,7 @@ try { $enq = Api "/API/PerfBgEnqueue?n=$N&taskms=25" $t0 = Get-Date; $sawWork = $false; $idle = 0; $wdl = (Get-Date).AddSeconds(120) while ((Get-Date) -lt $wdl) { - $a = Api '/API/jobs/allocation' + $a = Api '/API/PerfAllocation' if (-not $a) { Start-Sleep -Milliseconds 250; continue } $work = [int]$a.jm.active + [int]$a.jm.queued if ($work -gt 0) { $sawWork = $true; $idle = 0 } elseif ($sawWork) { $idle++ } diff --git a/perf-harness/scripts/run-oom.ps1 b/perf-harness/scripts/run-oom.ps1 new file mode 100644 index 0000000..ed5e2ab --- /dev/null +++ b/perf-harness/scripts/run-oom.ps1 @@ -0,0 +1,174 @@ +<# +.SYNOPSIS + OOM-resilience harness: prove a heap-constrained container still drains a massive fan-out. + +.DESCRIPTION + The durable-queue design keeps the backlog in Azure Table storage; the JobManager holds only a + worker-pool-sized buffer. So memory should stay BOUNDED regardless of fan-out size — a 20,000-task run + uses roughly the same heap as a 500-task one. This harness measures that, and then proves it under a + GC heap hard limit set just above the baseline: if the design were memory-bound (whole backlog in RAM) + a tight limit would OOM long before the run finished. + + Flow: bring CRAFT up (Http+Background + Azurite), record baseline memory, enqueue N tasks, poll + /API/PerfAllocation tracking peak memory + completion, and confirm every task reached a terminal state + via the durable run summary (/API/PerfRuns) — which survives a restart, unlike the in-memory counters. + +.EXAMPLE + # Baseline: unconstrained, find the natural peak for a 20k fan-out. + pwsh scripts\run-oom.ps1 -Tasks 20000 -Label baseline + + # Constrained: cap the GC heap just above the baseline peak and prove it still finishes. + pwsh scripts\run-oom.ps1 -Tasks 20000 -HeapLimitMB 320 -Label capped +#> +[CmdletBinding()] +param( + [string]$SutImage = 'craft:local', + [string]$Label = 'oom', + [int]$Tasks = 20000, + [int]$TaskMs = 0, + [int]$BgPool = 8, + [double]$Cpus = 2, + [int]$HeapLimitMB = 0, # 0 = unconstrained + [int]$AllocMB = 0, # per-task large-object (LOH) allocation — real heap pressure + [int]$HoldMs = 0, # hold the allocation so concurrent workers pile up live memory + [int]$Batch = 100, # pump claim batch — raises drain throughput for an enqueued backlog + [int]$PollMs = 250, + [int]$Port = 5298, + [int]$ReadyTimeoutSec = 240, + [int]$MaxWaitSec = 900, + [int]$StallSec = 90, # no dispatch progress this long (with work left) = dispatch loop wedged + [switch]$KeepUp +) +$ErrorActionPreference = 'Stop' +$here = Split-Path -Parent $MyInvocation.MyCommand.Path +$root = Split-Path -Parent $here +$compose = Join-Path $root 'docker-compose.bg.yml' +$resultsDir = Join-Path $root 'results' +New-Item -ItemType Directory -Force $resultsDir | Out-Null +$stamp = Get-Date -Format 'yyyyMMdd-HHmmss' +$base = "http://127.0.0.1:$Port" + +function Info($m){ Write-Host "[oom-harness] $m" -ForegroundColor Cyan } +function Warn($m){ Write-Host "[oom-harness] $m" -ForegroundColor Yellow } +function Get-Alloc { try { Invoke-RestMethod "$base/API/PerfAllocation" -TimeoutSec 5 } catch { $null } } + +$env:SUT_IMAGE=$SutImage; $env:SUT_PORT="$Port"; $env:SUT_CPUS="$Cpus"; $env:BG_POOL="$BgPool" +# Burst to ceiling so the pool fills immediately — we are testing memory under drain, not the ramp. +$env:BG_BURST='true'; $env:BG_BASE="$BgPool"; $env:BG_SCALEUP='1'; $env:BG_CEILING="$BgPool" +$env:JOB_BATCH="$Batch"; $env:JOB_POLL_MS="$PollMs" +$env:GC_HEAP_LIMIT_MB = if($HeapLimitMB -gt 0){ "$HeapLimitMB" } else { '' } + +Info "image=$SutImage tasks=$Tasks taskMs=$TaskMs bgPool=$BgPool cpus=$Cpus heapLimitMB=$(if($HeapLimitMB -gt 0){$HeapLimitMB}else{'none'})" +Info "compose up ..." +docker compose -f $compose up -d 2>&1 | Out-Host +if ($LASTEXITCODE -ne 0){ throw "compose up failed" } + +$result = [ordered]@{ label=$Label; timestamp=$stamp; tasks=$Tasks; taskMs=$TaskMs; bgPool=$BgPool; cpus=$Cpus + heapLimitMB=$HeapLimitMB } +try { + Info "waiting for ready (timeout ${ReadyTimeoutSec}s) ..." + $ready=$false; $dl=(Get-Date).AddSeconds($ReadyTimeoutSec) + while((Get-Date) -lt $dl){ + try { if((Invoke-RestMethod "$base/healthz" -TimeoutSec 5).status -eq 'ready'){ $ready=$true; break } } catch {} + Start-Sleep -Seconds 2 + } + if(-not $ready){ throw 'SUT never became ready' } + + # Baseline — retry until the bridge reports a real heap reading (the first calls right after ready can + # land before the PS pool answers, and [double]$null would silently record a 0MB baseline). + Start-Sleep -Seconds 2 + $b = $null + for($i=0; $i -lt 30; $i++){ $a=Get-Alloc; if($a -and ([double]$a.memory.heapMB) -gt 0){ $b=$a.memory; break }; Start-Sleep -Milliseconds 500 } + if(-not $b){ throw 'could not read a baseline memory sample from /API/PerfAllocation' } + $baseHeap = [double]$b.heapMB; $baseUsed = [double]$b.containerUsedMB; $gcLimit = [double]$b.gcHeapLimitMB + Info ("baseline: heap={0}MB containerUsed={1}MB gcHeapLimit={2}MB" -f $baseHeap,$baseUsed,$gcLimit) + $result.baselineHeapMB=$baseHeap; $result.baselineContainerUsedMB=$baseUsed; $result.gcHeapLimitMB=$gcLimit + + # ── Massive fan-out ───────────────────────────────────────────────────────── + Info "enqueuing $Tasks tasks ..." + $t0 = Get-Date + $enq = & curl.exe -s --max-time 180 "$base/API/PerfBgEnqueue?n=$Tasks&taskms=$TaskMs&allocmb=$AllocMB&holdms=$HoldMs" 2>$null + Info "enqueue -> $enq" + $runName = $null + try { $runName = ($enq | ConvertFrom-Json).run } catch {} + + # ── Poll to completion; watch dispatch PROGRESS (does the loop keep going under OOM?) ────────── + $peakHeap=$baseHeap; $peakUsed=$baseUsed; $unreachable=0; $maxUnreachableStreak=0; $samples=New-Object System.Collections.ArrayList + $done=$false; $stalled=$false; $crashed=$false; $peakFailed=0 + $lastLog=Get-Date; $prevDone=-1; $lastProgress=Get-Date; $wdl=(Get-Date).AddSeconds($MaxWaitSec) + while((Get-Date) -lt $wdl){ + $a = Get-Alloc + if(-not $a){ + $unreachable++ + if($unreachable -gt $maxUnreachableStreak){$maxUnreachableStreak=$unreachable} + # A sustained no-response means the PROCESS went down — the dispatch loop did not survive the OOM. + if($unreachable -ge 40){ $crashed=$true; Warn "SUT unreachable for ~20s — process appears to have crashed"; break } + Start-Sleep -Milliseconds 500; continue + } + $unreachable=0 + $t=[math]::Round(((Get-Date)-$t0).TotalSeconds,1) + $heap=[double]$a.memory.heapMB; $used=[double]$a.memory.containerUsedMB + if($heap -gt $peakHeap){$peakHeap=$heap}; if($used -gt $peakUsed){$peakUsed=$used} + $fail=[int]$a.jm.failed; if($fail -gt $peakFailed){$peakFailed=$fail} + $terminal=[int]$a.jm.completed + $fail + if($terminal -gt $prevDone){ $prevDone=$terminal; $lastProgress=Get-Date } + [void]$samples.Add([pscustomobject]@{ t=$t; heapMB=$heap; usedMB=$used; qtotal=[int]$a.queue.total; unclaimed=[int]$a.queue.unclaimed + bgBusy=[int]$a.pool.bgBusy; active=[int]$a.jm.active; queued=[int]$a.jm.queued; completed=[int]$a.jm.completed; failed=$fail; gc2=[int]$a.memory.gc2 }) + + if(((Get-Date)-$lastLog).TotalSeconds -ge 5){ + $lastLog=Get-Date + Info ("t={0,6}s done={1,6}/{2} (fail={3}) qtotal={4,6} bgBusy={5}/{6} heap={7}MB used={8}MB gc2={9}" -f ` + $t,$terminal,$Tasks,$fail,$a.queue.total,$a.pool.bgBusy,$BgPool,$heap,$used,$a.memory.gc2) + } + if($terminal -ge $Tasks){ $done=$true; break } + # Stall: work still queued but the dispatch loop has marked nothing terminal for StallSec — wedged. + if(([int]$a.queue.total -gt 0 -or [int]$a.jm.queued -gt 0 -or [int]$a.jm.active -gt 0) -and ((Get-Date)-$lastProgress).TotalSeconds -ge $StallSec){ + $stalled=$true; Warn ("dispatch STALLED: no terminal progress for {0}s with {1} still queued" -f $StallSec,$a.queue.total); break + } + Start-Sleep -Milliseconds 800 + } + $elapsed=[math]::Round(((Get-Date)-$t0).TotalSeconds,1) + + # ── Durable confirmation: every task terminal per the tables (survives a restart) ── + Start-Sleep -Seconds 2 + $durTotal=0; $durDone=0; $durFailed=0; $durRun=$null + try { + $runs = (Invoke-RestMethod "$base/API/PerfRuns" -TimeoutSec 15).runs + $durRun = if($runName){ $runs | Where-Object { $_.name -eq $runName } | Select-Object -First 1 } else { $runs | Select-Object -First 1 } + if($durRun){ $durTotal=[int]$durRun.total; $durDone=[int]$durRun.completed; $durFailed=[int]$durRun.failed } + } catch { Warn "PerfRuns read failed: $_" } + + $peakCompleted = ($samples | Measure-Object completed -Maximum).Maximum + $allTerminal = ($done) -or ($durTotal -gt 0 -and ($durDone + $durFailed) -ge $Tasks) + $dispatchSurvived = (-not $crashed) -and (-not $stalled) + + $result.enqueueTaskCount=$Tasks; $result.allocMB=$AllocMB; $result.holdMs=$HoldMs + $result.completionSec=$elapsed; $result.peakHeapMB=$peakHeap; $result.peakContainerUsedMB=$peakUsed + $result.heapGrowthMB=[math]::Round($peakHeap-$baseHeap,1) + $result.peakCompleted=$peakCompleted; $result.peakFailed=$peakFailed + $result.crashed=$crashed; $result.stalled=$stalled; $result.maxUnreachableStreak=$maxUnreachableStreak + $result.dispatchSurvived=$dispatchSurvived; $result.allTerminal=$allTerminal + $result.durable=@{ run=$runName; total=$durTotal; completed=$durDone; failed=$durFailed } + $result.samples=$samples + + Write-Host "" + Write-Host "===== OOM-resilience: $Label ($Tasks tasks, alloc=${AllocMB}MB hold=${HoldMs}ms, heapLimit=$(if($HeapLimitMB -gt 0){"${HeapLimitMB}MB"}else{'none'})) =====" -ForegroundColor Yellow + Write-Host (" baseline heap : {0} MB gc heap hard limit: {1}" -f $baseHeap,$(if($gcLimit -gt 0){"$gcLimit MB"}else{'(none)'})) -ForegroundColor Gray + Write-Host (" PEAK heap : {0} MB peak container used: {1} MB" -f $peakHeap,$peakUsed) -ForegroundColor Gray + Write-Host (" tasks failed (OOM) : {0} of {1}" -f $peakFailed,$Tasks) -ForegroundColor $(if($peakFailed -gt 0){'Yellow'}else{'Gray'}) + Write-Host (" completed / terminal : {0} completed, all-terminal={1}" -f $peakCompleted,$allTerminal) -ForegroundColor Gray + Write-Host (" completion time : {0}s" -f $elapsed) -ForegroundColor Gray + Write-Host (" process crashed : {0} dispatch stalled: {1}" -f $crashed,$stalled) -ForegroundColor $(if($crashed -or $stalled){'Red'}else{'Green'}) + Write-Host (" >> DISPATCH SURVIVED : {0} (loop kept dispatching through the OOM pressure)" -f $dispatchSurvived) -ForegroundColor $(if($dispatchSurvived){'Green'}else{'Red'}) + Write-Host (" >> ALL TASKS TERMINAL: {0} (every task Completed or Failed, none stranded)" -f $allTerminal) -ForegroundColor $(if($allTerminal){'Green'}else{'Red'}) + + $jsonOut = Join-Path $resultsDir "$Label-h$HeapLimitMB-a$AllocMB-$stamp.json" + ($result | ConvertTo-Json -Depth 6) | Set-Content $jsonOut -Encoding utf8 + Info "wrote $jsonOut" + if($AllocMB -gt 0 -and $peakFailed -eq 0){ Warn "no task OOMs observed — the heap limit may be too high vs (bgPool x allocMB) to actually force pressure" } + if(-not $dispatchSurvived){ Warn "DISPATCH DID NOT SURVIVE — the loop crashed/stalled under OOM (see $jsonOut)" } +} +finally { + if($KeepUp){ Warn "leaving up (-KeepUp). down: docker compose -f `"$compose`" down -v" } + else { Info "tearing down ..."; docker compose -f $compose down -v 2>&1 | Out-Null } +} diff --git a/perf-harness/scripts/run-orch.ps1 b/perf-harness/scripts/run-orch.ps1 index acb336c..f80ce02 100644 --- a/perf-harness/scripts/run-orch.ps1 +++ b/perf-harness/scripts/run-orch.ps1 @@ -5,7 +5,7 @@ .DESCRIPTION Brings up CRAFT in backend mode + Azurite, enqueues a parent orchestration of N tasks (each optionally sleeping -TaskMs to simulate work, and optionally spawning a child orchestration of -ChildN leaf tasks), - then polls /API/jobs/allocation at high frequency to build a timeline of: + then polls /API/PerfAllocation at high frequency to build a timeline of: - BG pool busy vs idle workers - the BackgroundTaskLimiter gate (currentMax) ← the ramp - JobManager queued / active @@ -84,7 +84,7 @@ try { $samples = New-Object System.Collections.ArrayList $idleStreak = 0; $sawWork = $false; $wdl = (Get-Date).AddSeconds($MaxWaitSec) while((Get-Date) -lt $wdl){ - try { $a = Invoke-RestMethod "$baseUrl/API/jobs/allocation" -TimeoutSec 5 } catch { Start-Sleep -Milliseconds 250; continue } + try { $a = Invoke-RestMethod "$baseUrl/API/PerfAllocation" -TimeoutSec 5 } catch { Start-Sleep -Milliseconds 250; continue } $t = ((Get-Date) - $t0).TotalSeconds [void]$samples.Add([pscustomobject]@{ t=[math]::Round($t,2); busy=$a.pool.bgBusy; total=$a.pool.bgTotal max=$a.limiter.currentMax; limActive=$a.limiter.active; limWait=$a.limiter.waiting diff --git a/tests/Craft.Tests/CallerClassifierTests.cs b/tests/Craft.Tests/CallerClassifierTests.cs new file mode 100644 index 0000000..c58ec62 --- /dev/null +++ b/tests/Craft.Tests/CallerClassifierTests.cs @@ -0,0 +1,139 @@ +using Craft.Configuration; +using Craft.Hosting; +using Microsoft.AspNetCore.Http; + +namespace Craft.Tests; + +/// +/// Classifying a caller as API vs UI gates the API concurrency cap, so a misclassification is a +/// correctness bug in both directions: a mislabelled UI request would be capped (throttling a person), +/// and a mislabelled API request would escape the cap it exists to enforce. +/// +public class CallerClassifierTests +{ + private static DefaultHttpContext Request(string? idp = null, string? name = null) + { + var context = new DefaultHttpContext(); + if (idp is not null) context.Request.Headers["x-ms-client-principal-idp"] = idp; + if (name is not null) context.Request.Headers["x-ms-client-principal-name"] = name; + return context; + } + + [Fact] + public void AppOnlyClient_WithAadIdpAndGuidName_IsApi() + { + // Exactly what CraftAuthMiddleware writes for a client-credentials caller. + Assert.True(CallerClassifier.IsApiClient( + Request(idp: "aad", name: "11111111-2222-3333-4444-555555555555"))); + } + + [Fact] + public void InteractiveEntraUser_IsNotApi() + { + // A signed-in user is normalised to azureStaticWebApps with a UPN, never aad + GUID. + Assert.False(CallerClassifier.IsApiClient( + Request(idp: "azureStaticWebApps", name: "user@contoso.com"))); + } + + [Fact] + public void AadIdpButNonGuidName_IsNotApi() + { + // Belt-and-suspenders: a stray aad idp on a non-GUID principal must not be read as an API client. + Assert.False(CallerClassifier.IsApiClient(Request(idp: "aad", name: "user@contoso.com"))); + } + + [Fact] + public void GuidNameButNonAadIdp_IsNotApi() + { + Assert.False(CallerClassifier.IsApiClient( + Request(idp: "azureStaticWebApps", name: "11111111-2222-3333-4444-555555555555"))); + } + + [Fact] + public void AnonymousRequest_IsNotApi() + { + Assert.False(CallerClassifier.IsApiClient(new DefaultHttpContext())); + } + + [Fact] + public void IdpMatchIsCaseInsensitive() + { + Assert.True(CallerClassifier.IsApiClient( + Request(idp: "AAD", name: "11111111-2222-3333-4444-555555555555"))); + } +} + +/// +/// The API concurrency cap must default off (unlimited) and honour its env override, and its presence +/// must be what turns the limiter middleware on independently of the per-client rate limiter — so a +/// deployment can run the concurrency cap with the rate limiter disabled, and vice versa. +/// +public class ApiConcurrencyLimitSettingsTests : IDisposable +{ + private readonly string? _original = Environment.GetEnvironmentVariable("CRAFT_API_CONCURRENCY_LIMIT"); + + public ApiConcurrencyLimitSettingsTests() => + Environment.SetEnvironmentVariable("CRAFT_API_CONCURRENCY_LIMIT", null); + + public void Dispose() + { + Environment.SetEnvironmentVariable("CRAFT_API_CONCURRENCY_LIMIT", _original); + GC.SuppressFinalize(this); + } + + [Fact] + public void DefaultsToOff() + { + var rl = new RateLimitSettings(); + Assert.Equal(0, rl.ResolvedApiConcurrencyLimit); + } + + [Fact] + public void ConfiguredValueIsUsed() + { + var rl = new RateLimitSettings { ApiConcurrencyLimit = 10 }; + Assert.Equal(10, rl.ResolvedApiConcurrencyLimit); + } + + [Fact] + public void EnvOverrideWins() + { + Environment.SetEnvironmentVariable("CRAFT_API_CONCURRENCY_LIMIT", "4"); + var rl = new RateLimitSettings { ApiConcurrencyLimit = 10 }; + Assert.Equal(4, rl.ResolvedApiConcurrencyLimit); + } + + [Fact] + public void EnvOverrideOfZeroDisablesEvenWhenConfigured() + { + // A deployment-level kill switch: CRAFT_API_CONCURRENCY_LIMIT=0 turns the cap off regardless + // of the setting baked into appsettings. + Environment.SetEnvironmentVariable("CRAFT_API_CONCURRENCY_LIMIT", "0"); + var rl = new RateLimitSettings { ApiConcurrencyLimit = 10 }; + Assert.Equal(0, rl.ResolvedApiConcurrencyLimit); + } + + [Theory] + [InlineData("notanumber")] + [InlineData("-3")] + public void InvalidOrNegativeEnvIsIgnored(string value) + { + Environment.SetEnvironmentVariable("CRAFT_API_CONCURRENCY_LIMIT", value); + var rl = new RateLimitSettings { ApiConcurrencyLimit = 7 }; + Assert.Equal(7, rl.ResolvedApiConcurrencyLimit); + } + + [Fact] + public void RateLimiterOff_ButConcurrencyOn_StillNeedsTheMiddleware() + { + var rl = new RateLimitSettings { Enabled = false, ApiConcurrencyLimit = 5 }; + Assert.True(rl.RequiresLimiterMiddleware); + } + + [Fact] + public void BothOff_SkipsTheMiddleware() + { + var rl = new RateLimitSettings { Enabled = false, ApiConcurrencyLimit = 0 }; + Assert.False(rl.RequiresLimiterMiddleware); + } +} diff --git a/tests/Craft.Tests/ExecutionContextReset.cs b/tests/Craft.Tests/ExecutionContextReset.cs new file mode 100644 index 0000000..ed13c98 --- /dev/null +++ b/tests/Craft.Tests/ExecutionContextReset.cs @@ -0,0 +1,67 @@ +using System.Reflection; + +namespace Craft.Tests; + +/// +/// "Solution 1": reset the reused pipeline thread's ExecutionContext to a clean warmup baseline +/// between invocations, dropping any AsyncLocal value set during an invocation. Runspace SessionState +/// (module $script: vars, ModuleInjections caches) and process env do NOT live in the ExecutionContext, +/// so this is safe for persisted per-worker state. +/// +/// Mechanism: + — both +/// PUBLIC and supported on net8/net9/net10. Restore throws on a null argument, so we restore a baseline +/// captured on the pipeline thread at warmup (when it is clean). In the rare case the warmup context is +/// the runtime default (Capture() == null), we fall back to the internal RestoreInternal(null); a fix +/// that had to do that would probe it at startup and degrade to Solution 2 if absent. +/// +/// Must be driven ON the pipeline thread: once at warmup, then +/// at each invocation boundary. +/// +public static class ExecutionContextReset +{ + [ThreadStatic] private static ExecutionContext? s_baseline; + [ThreadStatic] private static bool s_haveBaseline; + + // Only used when the captured warmup baseline is the default (null) context, which public Restore rejects. + private static readonly MethodInfo? s_restoreInternalNull = + typeof(ExecutionContext).GetMethod("RestoreInternal", + BindingFlags.Static | BindingFlags.NonPublic, binder: null, + types: new[] { typeof(ExecutionContext) }, modifiers: null); + + /// Whether the supported public reset primitive exists on this runtime (the reliability answer). + public static bool PublicRestoreAvailable { get; } = + typeof(ExecutionContext).GetMethod("Restore", + BindingFlags.Static | BindingFlags.Public, binder: null, + types: new[] { typeof(ExecutionContext) }, modifiers: null) != null; + + /// Capture the current (clean) context as the per-thread baseline. Call at warmup, on the pipeline thread. + public static void CaptureBaseline() + { + s_baseline = ExecutionContext.Capture(); // may be null if the warmup context is the runtime default + s_haveBaseline = true; + } + + /// What ResetToClean would use on the calling thread — for reporting. + public static string Mechanism => + !s_haveBaseline ? "(baseline not captured on this thread)" + : s_baseline != null ? "ExecutionContext.Restore(baseline) [public, supported]" + : s_restoreInternalNull != null ? "ExecutionContext.RestoreInternal(null) [internal; warmup ctx was default]" + : "unavailable (default baseline, no internal fallback)"; + + /// Restore the warmup baseline on the calling (pipeline) thread, dropping AsyncLocals set since. + public static void ResetToClean() + { + if (!s_haveBaseline) CaptureBaseline(); // best effort; prefer an explicit warmup capture + if (s_baseline != null) + { + ExecutionContext.Restore(s_baseline); // supported public API (net8+) + return; + } + if (s_restoreInternalNull != null) + { + s_restoreInternalNull.Invoke(null, new object?[] { null }); + return; + } + throw new NotSupportedException("Warmup context was the default and no internal null-restore is available."); + } +} diff --git a/tests/Craft.Tests/GcHeapLimitTests.cs b/tests/Craft.Tests/GcHeapLimitTests.cs new file mode 100644 index 0000000..e4f2d53 --- /dev/null +++ b/tests/Craft.Tests/GcHeapLimitTests.cs @@ -0,0 +1,190 @@ +using Craft.Configuration; +using Craft.Hosting; + +namespace Craft.Tests; + +/// +/// The GC heap hard limit rides on the same SkuProfile match as pool sizing, but unlike pool sizes +/// it cannot be set through configuration the runtime reads at startup — it has to land through +/// AppContext + after the CLR is already up. Getting this wrong +/// either leaves a large tier capped at the smallest tier's heap, or (worse) turns a sizing hint +/// into a startup failure. +/// +public class GcHeapLimitTests +{ + [Fact] + public void NoMatchedProfile_IsANoOp() + { + var logs = new List(); + + var applied = GcHeapLimit.Apply(null, logs.Add, _ => throw new InvalidOperationException("must not be called")); + + Assert.False(applied); + Assert.Empty(logs); // like unused SkuProfiles: don't log on every start + } + + [Theory] + [InlineData(null)] + [InlineData(-1)] + public void ProfileWithoutALimit_IsANoOp(int? mb) + { + // Omitted/null (or negative) = no opinion: keep the baseline, silently. A literal 0 is different + // — see ProfileZero_DisablesTheCap. + var profile = new SkuProfile { HttpPoolSize = 2, BgPoolSize = 2, GCHeapHardLimitMB = mb }; + var logs = new List(); + + var applied = GcHeapLimit.Apply(profile, logs.Add, _ => throw new InvalidOperationException("must not be called")); + + Assert.False(applied); + Assert.Empty(logs); + } + + [Fact] + public void ProfileZero_DisablesTheCap() + { + // A profile's literal 0 disables the cap entirely — same meaning as CRAFT_GC_HEAP_LIMIT_MB=0 — + // so a large tier uses container memory instead of the baked smallest-tier limit. + var profile = new SkuProfile { HttpPoolSize = 2, BgPoolSize = 2, GCHeapHardLimitMB = 0 }; + var logs = new List(); + ulong? requested = 123; // sentinel: proves 0 is what reaches refresh + + var applied = GcHeapLimit.Apply(profile, logs.Add, bytes => requested = bytes); + + Assert.True(applied); + Assert.Equal(0UL, requested); + Assert.Contains(logs, l => l.Contains("disabled by SkuProfile", StringComparison.Ordinal)); + } + + [Fact] + public void ConfiguredLimit_IsAppliedInBytes_AndLogged() + { + var profile = new SkuProfile { GCHeapHardLimitMB = 5120 }; + var logs = new List(); + ulong? requested = null; + + var applied = GcHeapLimit.Apply(profile, logs.Add, bytes => requested = bytes); + + Assert.True(applied); + Assert.Equal(5120UL * 1024 * 1024, requested); + Assert.Contains(logs, l => l.Contains("GC heap hard limit set to 5120 MB", StringComparison.Ordinal)); + } + + [Fact] + public void RefreshRefusingTheLimit_LogsAndKeepsTheBaseline() + { + // GC.RefreshMemoryLimit throws when the new limit is below what the heap has already + // committed. That must stay a logged hint, never a startup failure. + var profile = new SkuProfile { GCHeapHardLimitMB = 1 }; + var logs = new List(); + + var applied = GcHeapLimit.Apply(profile, logs.Add, + _ => throw new InvalidOperationException("RefreshMemoryLimit failed")); + + Assert.False(applied); + Assert.Contains(logs, l => l.Contains("GC heap hard limit change (1 MB) by SkuProfile failed", StringComparison.Ordinal)); + } + + [Fact] + public void RealRefresh_ChangesTheProcessHeapLimit() + { + // Proves the actual mechanism (AppContext.SetData + GC.RefreshMemoryLimit) works, not just + // our plumbing around it. Target slightly below the current budget: far above anything the + // test host has committed, so it cannot destabilize parallel tests, while still being an + // observable change. Restored afterwards (raising back is always allowed). + var before = GC.GetGCMemoryInfo().TotalAvailableMemoryBytes; + if (before < 2L * 1024 * 1024 * 1024) return; // tiny CI container — not worth the risk + + var targetMB = (int)(before / (1024 * 1024)) - 128; + try + { + var applied = GcHeapLimit.Apply(new SkuProfile { GCHeapHardLimitMB = targetMB }, _ => { }); + + Assert.True(applied); + Assert.Equal((long)targetMB * 1024 * 1024, GC.GetGCMemoryInfo().TotalAvailableMemoryBytes); + } + finally + { + AppContext.SetData("GCHeapHardLimit", (ulong)before); + GC.RefreshMemoryLimit(); + } + } + + // ── CRAFT_GC_HEAP_LIMIT_MB: the per-instance escape hatch ───────────────────────────────────────── + // Restores the control a fleet-wide profile would otherwise take away: the profile writes the limit + // through AppContext, which overrides a hand-set DOTNET_GCHeapHardLimit, so an operator needs a way + // back in without editing the shared profile list. readEnv is injected here to keep the process + // environment untouched, exactly as refresh is injected to keep the real GC untouched. + + [Fact] + public void EnvOverride_WinsOverProfile() + { + var profile = new SkuProfile { GCHeapHardLimitMB = 5120 }; + var logs = new List(); + ulong? requested = null; + + var applied = GcHeapLimit.Apply(profile, logs.Add, bytes => requested = bytes, () => "8192"); + + Assert.True(applied); + Assert.Equal(8192UL * 1024 * 1024, requested); // env value, not the profile's 5120 + Assert.Contains(logs, l => l.Contains("set to 8192 MB by CRAFT_GC_HEAP_LIMIT_MB", StringComparison.Ordinal)); + } + + [Fact] + public void EnvOverrideZero_DisablesTheCap_OverridingTheProfile() + { + var profile = new SkuProfile { GCHeapHardLimitMB = 5120 }; + var logs = new List(); + ulong? requested = 123; // sentinel: proves the 0 is what actually reaches refresh + + var applied = GcHeapLimit.Apply(profile, logs.Add, bytes => requested = bytes, () => "0"); + + Assert.True(applied); + Assert.Equal(0UL, requested); + Assert.Contains(logs, l => l.Contains("disabled by CRAFT_GC_HEAP_LIMIT_MB", StringComparison.Ordinal)); + } + + [Fact] + public void EnvOverrideZero_DisablesTheCap_WithNoProfile() + { + var logs = new List(); + ulong? requested = 123; + + var applied = GcHeapLimit.Apply(null, logs.Add, bytes => requested = bytes, () => "0"); + + Assert.True(applied); + Assert.Equal(0UL, requested); + Assert.Contains(logs, l => l.Contains("disabled by CRAFT_GC_HEAP_LIMIT_MB", StringComparison.Ordinal)); + } + + [Theory] + [InlineData(null)] + [InlineData("")] + [InlineData(" ")] + [InlineData("not-a-number")] + [InlineData("-5")] // negative = invalid, not a request to disable; that's what 0 is for + public void EnvOverrideAbsentOrInvalid_DefersToProfile(string? env) + { + var profile = new SkuProfile { GCHeapHardLimitMB = 5120 }; + var logs = new List(); + ulong? requested = null; + + var applied = GcHeapLimit.Apply(profile, logs.Add, bytes => requested = bytes, () => env); + + Assert.True(applied); + Assert.Equal(5120UL * 1024 * 1024, requested); + Assert.Contains(logs, l => l.Contains("set to 5120 MB by SkuProfile", StringComparison.Ordinal)); + } + + [Fact] + public void EnvOverrideZero_WhenRefreshRefuses_LogsAndKeepsBaseline() + { + var logs = new List(); + + var applied = GcHeapLimit.Apply(null, logs.Add, + _ => throw new InvalidOperationException("nope"), () => "0"); + + Assert.False(applied); + Assert.Contains(logs, l => l.Contains( + "GC heap hard limit change (disable) by CRAFT_GC_HEAP_LIMIT_MB failed", StringComparison.Ordinal)); + } +} diff --git a/tests/Craft.Tests/HttpQueueTimeoutTests.cs b/tests/Craft.Tests/HttpQueueTimeoutTests.cs new file mode 100644 index 0000000..09aaf39 --- /dev/null +++ b/tests/Craft.Tests/HttpQueueTimeoutTests.cs @@ -0,0 +1,75 @@ +using Craft.Configuration; +using Craft.Hosting; + +namespace Craft.Tests; + +/// +/// The HTTP queue timeout bounds how long a request waits for a free runspace before it is shed with +/// 503. It resolves from the CRAFT_HTTP_QUEUE_TIMEOUT env var, then Worker:HttpQueueTimeoutSeconds, +/// then the built-in default — mirroring how the thread-pool minimum resolves. +/// +public class HttpQueueTimeoutTests : IDisposable +{ + private readonly string? _original = Environment.GetEnvironmentVariable("CRAFT_HTTP_QUEUE_TIMEOUT"); + + public HttpQueueTimeoutTests() => Environment.SetEnvironmentVariable("CRAFT_HTTP_QUEUE_TIMEOUT", null); + + public void Dispose() + { + Environment.SetEnvironmentVariable("CRAFT_HTTP_QUEUE_TIMEOUT", _original); + GC.SuppressFinalize(this); + } + + private static WorkerSettings Worker(int queueTimeout = 0) => + new() { HttpQueueTimeoutSeconds = queueTimeout }; + + [Fact] + public void UnsetFallsBackToTheBuiltInDefault() + { + Assert.Equal( + TimeSpan.FromSeconds(CraftHostBuilderExtensions.DefaultHttpQueueTimeoutSeconds), + CraftHostBuilderExtensions.ResolveHttpQueueTimeout(Worker())); + } + + [Fact] + public void ExplicitSettingWins() + { + Assert.Equal( + TimeSpan.FromSeconds(60), + CraftHostBuilderExtensions.ResolveHttpQueueTimeout(Worker(queueTimeout: 60))); + } + + [Theory] + [InlineData(0)] + [InlineData(-5)] + public void ZeroOrNegativeSettingFallsBackToTheDefault(int configured) + { + Assert.Equal( + TimeSpan.FromSeconds(CraftHostBuilderExtensions.DefaultHttpQueueTimeoutSeconds), + CraftHostBuilderExtensions.ResolveHttpQueueTimeout(Worker(configured))); + } + + [Fact] + public void EnvOverrideWinsOverTheSetting() + { + Environment.SetEnvironmentVariable("CRAFT_HTTP_QUEUE_TIMEOUT", "90"); + + Assert.Equal( + TimeSpan.FromSeconds(90), + CraftHostBuilderExtensions.ResolveHttpQueueTimeout(Worker(queueTimeout: 60))); + } + + [Theory] + [InlineData("")] + [InlineData("notanumber")] + [InlineData("0")] + [InlineData("-1")] + public void InvalidOrNonPositiveEnvIsIgnored(string value) + { + Environment.SetEnvironmentVariable("CRAFT_HTTP_QUEUE_TIMEOUT", value); + + Assert.Equal( + TimeSpan.FromSeconds(60), + CraftHostBuilderExtensions.ResolveHttpQueueTimeout(Worker(queueTimeout: 60))); + } +} diff --git a/tests/Craft.Tests/JobQueueAzuriteTests.cs b/tests/Craft.Tests/JobQueueAzuriteTests.cs index 6d20637..074461d 100644 --- a/tests/Craft.Tests/JobQueueAzuriteTests.cs +++ b/tests/Craft.Tests/JobQueueAzuriteTests.cs @@ -135,16 +135,16 @@ public async Task ServerSideRunFilter_HandlesAQuoteInTheRunName() } [Fact] - public async Task BackendReturnsWorkPriorityFirstThenOldestFirst() + public async Task BackendReturnsWorkHighestPriorityFirst() { var queue = await TryConnectAsync(); if (queue == null) return; - // Inserted in the least helpful order: the bulk low-priority work first, urgent last, and the - // newest P4 before the oldest. If any of this came back in insertion order the scheme is broken. + // Inserted in the least helpful order: bulk P4 work first, urgent P0 last, idle P6 early. If any + // of this came back in insertion order the priority scheme is broken. await queue.EnqueueBatchAsync("StandardsApply", - [("std-newer", 4), ("std-older", 4)], At(30)); - await queue.EnqueueAsync("StandardsApply", "std-oldest", 4, At(1)); + [("std-a", 4), ("std-b", 4)], At(30)); + await queue.EnqueueAsync("StandardsApply", "std-c", 4, At(1)); await queue.EnqueueAsync("DbCache", "cache-0", 6, At(0)); await queue.EnqueueAsync("AuditLogIngest", "audit-0", 0, At(59)); @@ -160,10 +160,12 @@ await queue.EnqueueBatchAsync("StandardsApply", Assert.Equal("audit-0", order[0]); Assert.Equal("cache-0", order[4]); - // Within P4, oldest first — std-oldest was queued at minute 1, the other two at minute 30. - Assert.Equal("std-oldest", order[1]); - Assert.Contains("std-newer", order.GetRange(2, 2)); - Assert.Contains("std-older", order.GetRange(2, 2)); + // The three P4 tasks fill the middle, ahead of P6 and behind P0. Schema v2 keys per (run, task), + // so ORDER within a priority is no longer oldest-first — only that they all rank between the two. + var middle = order.GetRange(1, 3); + Assert.Contains("std-a", middle); + Assert.Contains("std-b", middle); + Assert.Contains("std-c", middle); } [Fact] diff --git a/tests/Craft.Tests/JobQueueIndexBackfillTests.cs b/tests/Craft.Tests/JobQueueIndexBackfillTests.cs index b78276a..3041822 100644 --- a/tests/Craft.Tests/JobQueueIndexBackfillTests.cs +++ b/tests/Craft.Tests/JobQueueIndexBackfillTests.cs @@ -32,12 +32,16 @@ private static (JobQueueStore Queue, RunRemainingCounterTests.ConditionalStore S } /// - /// A queue row exactly as the pre-index code wrote it: no index row anywhere. + /// A queue row exactly as the v1 code wrote it: the legacy time-prefixed key + /// ({ticks:D19}-{run}-{task}), no QueuedUtc property, no index row anywhere. This is what + /// the v2 migration must re-key. /// private static Task SeedLegacyRowAsync(RunRemainingCounterTests.ConditionalStore store, string queueTable, - string runName, string taskId, int priority, DateTime queuedUtc) => - store.UpsertAsync(queueTable, - new StoreRow(JobQueueStore.Bucket(priority), JobQueueStore.BuildRowKey(queuedUtc, runName, taskId)) + string runName, string taskId, int priority, DateTime queuedUtc) + { + var legacyKey = $"{queuedUtc.Ticks.ToString("D19", System.Globalization.CultureInfo.InvariantCulture)}-{runName}-{taskId}"; + return store.UpsertAsync(queueTable, + new StoreRow(JobQueueStore.Bucket(priority), legacyKey) { Properties = { @@ -48,6 +52,7 @@ private static Task SeedLegacyRowAsync(RunRemainingCounterTests.ConditionalStore ["LeaseUntil"] = (DateTimeOffset?)null, } }); + } [Fact] public async Task BuildsTheIndexForAQueueThatPredatesIt() @@ -65,6 +70,31 @@ public async Task BuildsTheIndexForAQueueThatPredatesIt() Assert.Equal(["task-9"], await queue.GetQueuedTaskIdsAsync("run-b")); } + /// + /// v2 re-keys a legacy time-prefixed row to the deterministic {run}|{task} scheme, carrying its + /// enqueue time into the QueuedUtc property, deleting the old row, and leaving the task claimable once. + /// + [Fact] + public async Task MigratesLegacyRowsToTheDeterministicKeyScheme() + { + var (queue, store, queueTable) = NewQueue(); + await SeedLegacyRowAsync(store, queueTable, "run-a", "task-0", 4, At(3)); + + await queue.InitializeAsync(); + + var rows = new List(); + await foreach (var row in store.QueryTableAsync(queueTable)) rows.Add(row); + + // The legacy row is gone; one row remains, keyed deterministically and carrying QueuedUtc. + var only = Assert.Single(rows); + Assert.Equal(JobQueueStore.BuildRowKey("run-a", "task-0"), only.RowKey); + Assert.Equal(new DateTimeOffset(At(3), TimeSpan.Zero), only.GetDateTimeOffset("QueuedUtc")); + + // And it is still claimable, exactly once. + Assert.Equal("task-0", + Assert.Single(await queue.ClaimBatchAsync("w", 8, TimeSpan.FromMinutes(20))).TaskId); + } + [Fact] public async Task RunsOnceAndNeverAgain() { diff --git a/tests/Craft.Tests/JobQueuePumpTests.cs b/tests/Craft.Tests/JobQueuePumpTests.cs index e38eaf9..60f5cf5 100644 --- a/tests/Craft.Tests/JobQueuePumpTests.cs +++ b/tests/Craft.Tests/JobQueuePumpTests.cs @@ -145,6 +145,69 @@ public async Task SurvivesAStoreThatThrows() Assert.Null(ex); } + /// + /// The wake signal: an enqueue must start the pump now, not on its next poll tick. With a + /// deliberately long poll interval, a task queued after the pump has gone quiet is still claimed + /// promptly — which can only happen if the enqueue woke it. Without the signal this waits the full + /// poll interval, which on a cold system had backed off toward its idle ceiling. + /// + [Fact] + public async Task AnEnqueueWakesThePumpBeforeTheNextPollTick() + { + var settings = new CraftSettings(); + settings.Worker.BgPoolSize = 4; + var config = new ConfigurationBuilder().AddInMemoryCollection(new Dictionary + { + ["JobQueueBatchSize"] = "4", + ["JobQueueLowWaterMark"] = "2", + // Long enough that a poll-driven claim would miss the assertion window by an order of magnitude. + ["JobQueuePollIntervalMs"] = "5000", + ["JobQueueIdlePollIntervalMs"] = "5000", + }).Build(); + + var backing = new RunRemainingCounterTests.ConditionalStore(); + var queue = new JobQueueStore(NullLogger.Instance, settings, backing); + await queue.InitializeAsync(); + + var repo = new ScriptRepository(NullLogger.Instance, settings); + var pool = new PowerShellWorkerPool(repo, NullLogger.Instance, config, settings); + var limiter = new BackgroundTaskLimiter(NullLogger.Instance, config, settings, pool); + var jobs = new JobManager(NullLogger.Instance, settings, limiter); + var pump = new JobQueuePump(NullLogger.Instance, queue, jobs, config, settings); + + await pump.StartAsync(CancellationToken.None); + try + { + // Let the first (empty) cycle run and the pump settle into its long wait. + await Task.Delay(200); + Assert.Equal(0, jobs.QueuedCount); + + await queue.EnqueueBatchAsync("run", + new[] { ("task-1", 4) }, + new DateTime(2026, 8, 9, 2, 0, 0, DateTimeKind.Utc)); + + // Well under the 5s poll: only the wake can explain a claim this fast. + var claimed = await WaitUntilAsync(() => jobs.QueuedCount > 0, TimeSpan.FromMilliseconds(1500)); + Assert.True(claimed, + "the pump did not claim the enqueued task within 1.5s despite a 5s poll — the wake signal did not fire"); + } + finally + { + await Task.WhenAny(pump.StopAsync(CancellationToken.None), Task.Delay(3000)); + } + } + + private static async Task WaitUntilAsync(Func condition, TimeSpan timeout) + { + var sw = System.Diagnostics.Stopwatch.StartNew(); + while (sw.Elapsed < timeout) + { + if (condition()) return true; + await Task.Delay(20); + } + return condition(); + } + private sealed class ThrowingStore : ICraftTableStore { public Task PingAsync(CancellationToken ct = default) => Task.CompletedTask; diff --git a/tests/Craft.Tests/JobQueueStatusReaderTests.cs b/tests/Craft.Tests/JobQueueStatusReaderTests.cs index cc8d073..0485c44 100644 --- a/tests/Craft.Tests/JobQueueStatusReaderTests.cs +++ b/tests/Craft.Tests/JobQueueStatusReaderTests.cs @@ -97,21 +97,26 @@ public async Task JobDetails_ListTheBacklog_WithoutDuplicatingLocallyClaimedWork await f.Queue.EnqueueAsync("run", "claimed-elsewhere", 4, At(1)); await f.Queue.EnqueueAsync("run", "waiting", 4, At(2)); - // "claimed-here" is what the pump does: claim the row, enqueue the descriptor locally. + // Claim one locally, the way the pump does: claim the row, enqueue the descriptor locally. Which + // of the two "claimed-*" tasks comes first is no longer time-ordered under schema v2, so drive the + // local record off whatever was actually claimed rather than a hard-coded id. var mine = await f.Queue.ClaimBatchAsync("this-node", 1, Lease); - Assert.Equal("claimed-here", Assert.Single(mine).TaskId); - f.Jobs.Enqueue(new JobDescriptor("run", "claimed-here", 4), "run-claimed-here"); + var mineId = Assert.Single(mine).TaskId; + f.Jobs.Enqueue(new JobDescriptor("run", mineId, 4), $"run-{mineId}"); // Another instance's claim: a row under lease with no local record at all. var theirs = await f.Queue.ClaimBatchAsync("other-node", 1, Lease); - Assert.Equal("claimed-elsewhere", Assert.Single(theirs).TaskId); + var theirsId = Assert.Single(theirs).TaskId; + Assert.NotEqual(mineId, theirsId); var details = await f.Reader.GetJobDetailsAsync(); - // claimed-here once (the local record), waiting once (durable), claimed-elsewhere not at all — - // it is running inside another instance and its records live there. + // The locally-claimed row once (its local record), the still-waiting row once (durable), the row + // claimed by the other instance not at all — its records live there. ("waiting" sorts last, so the + // two claims took the "claimed-*" pair and it is what remains.) Assert.Equal(2, details.Count); - Assert.Single(details, d => d.Id == "run-claimed-here"); + Assert.Single(details, d => d.Id == $"run-{mineId}"); + Assert.DoesNotContain(details, d => d.Id == $"run-{theirsId}"); var waiting = Assert.Single(details, d => d.Id == "run-waiting"); Assert.Equal("Queued", waiting.Status); Assert.Equal(At(2), waiting.QueuedUtc); diff --git a/tests/Craft.Tests/JobQueueStoreTests.cs b/tests/Craft.Tests/JobQueueStoreTests.cs index cde0c78..7ed2264 100644 --- a/tests/Craft.Tests/JobQueueStoreTests.cs +++ b/tests/Craft.Tests/JobQueueStoreTests.cs @@ -50,17 +50,22 @@ await queue.EnqueueBatchAsync("StandardsApply", } [Fact] - public async Task ClaimsOldestFirstWithinAPriority() + public async Task ReEnqueuingATaskUpsertsOneRowRatherThanDuplicating() { var (queue, _) = NewQueue(); await queue.InitializeAsync(); - await queue.EnqueueAsync("run", "newer", 4, At(10)); - await queue.EnqueueAsync("run", "older", 4, At(1)); + // The re-dispatch case (crash recovery, orphan re-drive). Schema v2 keys deterministically per + // (run, task), so the second enqueue UPDATES the first row instead of adding a duplicate — the + // duplicate that used to get claimed and executed a second time. + await queue.EnqueueAsync("run", "task-0", 4, At(1)); + await queue.EnqueueAsync("run", "task-0", 4, At(10)); - var claimed = await queue.ClaimBatchAsync("worker-a", 1, Lease); + Assert.Single(await queue.GetQueuedTaskIdsAsync("run")); - Assert.Equal("older", Assert.Single(claimed).TaskId); + Assert.Equal("task-0", Assert.Single(await queue.ClaimBatchAsync("worker-a", 8, Lease)).TaskId); + // Only one row ever existed, so nothing is left to claim a second time. + Assert.Empty(await queue.ClaimBatchAsync("worker-b", 8, Lease)); } /// @@ -187,13 +192,13 @@ public void PriorityBucketsSortNumericallyNotLexically() } [Fact] - public void RowKeysSortByQueueTimeAcrossTickDigitBoundaries() + public void RowKeyIsDeterministicPerRunAndTask() { - var early = JobQueueStore.BuildRowKey(new DateTime(2026, 1, 1, 0, 0, 0, DateTimeKind.Utc), "r", "t"); - var later = JobQueueStore.BuildRowKey(new DateTime(2026, 1, 1, 0, 0, 1, DateTimeKind.Utc), "r", "t"); - - Assert.True(string.CompareOrdinal(early, later) < 0); - Assert.Equal(19, early.IndexOf('-', StringComparison.Ordinal)); + // Schema v2: the key is a function of (run, task) only, so re-dispatching a task upserts its one + // row instead of writing a second, time-prefixed one — the duplicate-execution class. + Assert.Equal(JobQueueStore.BuildRowKey("r", "t"), JobQueueStore.BuildRowKey("r", "t")); + Assert.NotEqual(JobQueueStore.BuildRowKey("r", "t1"), JobQueueStore.BuildRowKey("r", "t2")); + Assert.NotEqual(JobQueueStore.BuildRowKey("r1", "t"), JobQueueStore.BuildRowKey("r2", "t")); } [Fact] @@ -208,13 +213,35 @@ public async Task EmptyQueueClaimsNothingRatherThanBlocking() // ─── Status/maintenance surface (the table-backed worker-health view) ─── [Fact] - public void ParseQueuedUtcInvertsBuildRowKey() + public void RowKeyEscapingKeepsDistinctPairsDistinctAndKeysLegal() + { + // The '|' separator and '%' escape are themselves escaped, so "a|b"+"c" and "a"+"b|c" cannot + // collide onto one row. + Assert.NotEqual(JobQueueStore.BuildRowKey("a|b", "c"), JobQueueStore.BuildRowKey("a", "b|c")); + + // An illegal character in a component is escaped away, keeping the key legal for Azure Table. + var key = JobQueueStore.BuildRowKey("run", "Owner/Repo - No tenant"); + Assert.DoesNotContain(key, c => c is '/' or '\\' or '#' or '?' || char.IsControl(c)); + } + + [Fact] + public async Task ClearAllEmptiesTheQueueButLeavesItUsable() { - var queuedUtc = new DateTime(2026, 8, 12, 3, 4, 5, DateTimeKind.Utc); - var rowKey = JobQueueStore.BuildRowKey(queuedUtc, "run", "task"); + var (queue, _) = NewQueue(); + await queue.InitializeAsync(); + await queue.EnqueueBatchAsync("run-a", + Enumerable.Range(0, 3).Select(i => ($"task-{i}", 4)).ToList(), At(0)); + await queue.EnqueueAsync("run-b", "solo", 4, At(0)); + + var removed = await queue.ClearAllAsync(); + + Assert.Equal(4, removed); + Assert.Empty(await queue.ListQueuedAsync()); + Assert.Empty(await queue.GetQueuedTaskIdsAsync("run-a")); - Assert.Equal(queuedUtc, JobQueueStore.ParseQueuedUtc(rowKey)); - Assert.Null(JobQueueStore.ParseQueuedUtc("not-a-tick-prefixed-key")); + // The schema marker survives, so the queue keeps working — a fresh enqueue lands and is claimable. + await queue.EnqueueAsync("run-c", "again", 4, At(1)); + Assert.Equal("again", Assert.Single(await queue.ClaimBatchAsync("w", 8, Lease)).TaskId); } [Fact] diff --git a/tests/Craft.Tests/PowerShellWorkerContextResetTests.cs b/tests/Craft.Tests/PowerShellWorkerContextResetTests.cs new file mode 100644 index 0000000..17a705c --- /dev/null +++ b/tests/Craft.Tests/PowerShellWorkerContextResetTests.cs @@ -0,0 +1,45 @@ +using System.Management.Automation; +using System.Management.Automation.Runspaces; +using Craft.PowerShellHost; +using Microsoft.Extensions.Logging.Abstractions; + +namespace Craft.Tests; + +/// A process-static AsyncLocal, so the leak survives the worker's global-variable sweep and we +/// are testing the ExecutionContext reset specifically (not variable cleanup). Its .Value lives in the +/// pipeline thread's ExecutionContext. +public static class LeakProbe +{ + public static readonly System.Threading.AsyncLocal Slot = new(); +} + +/// +/// End-to-end: the worker's per-invocation Cleanup resets the reused pipeline thread's +/// ExecutionContext, so an AsyncLocal set by one invocation does not leak into the next on the same +/// worker. Exercises the real path. +/// +public class PowerShellWorkerContextResetTests +{ + [Fact] + public async Task Cleanup_ResetsAsyncLocal_AcrossWorkerInvocations() + { + var worker = new PowerShellWorker(99, InitialSessionState.CreateDefault2(), NullLogger.Instance); + worker.Runspace.ThreadOptions = PSThreadOptions.ReuseThread; // as Initialize sets it; must precede open + + // Production captures this in Initialize; do the same clean-thread capture here (Slot is unset now). + await worker.InvokeScriptAsync(ScriptBlock.Create( + "[Craft.PowerShellHost.PipelineExecutionContext]::CaptureBaselineIfNeeded()")); + Assert.True(PipelineExecutionContext.Captured); + + // Invocation A: leak an AsyncLocal into the pipeline thread's ExecutionContext. + await worker.InvokeScriptAsync(ScriptBlock.Create("[Craft.Tests.LeakProbe]::Slot.Value = 'LEAK'")); + + // Invocation B: read it back. Cleanup after A restored the clean baseline, so it is gone. + var r = await worker.InvokeScriptAsync(ScriptBlock.Create( + "[pscustomobject]@{ V = [Craft.Tests.LeakProbe]::Slot.Value }")); + + Assert.Null(r[0].Properties["V"]?.Value); // reset cleared the AsyncLocal on the real worker path + + worker.Dispose(); + } +} diff --git a/tests/Craft.Tests/RunRemainingCounterTests.cs b/tests/Craft.Tests/RunRemainingCounterTests.cs index c2c7763..38a287e 100644 --- a/tests/Craft.Tests/RunRemainingCounterTests.cs +++ b/tests/Craft.Tests/RunRemainingCounterTests.cs @@ -167,70 +167,6 @@ private static async Task SeededAsync(ConditionalStore b return store; } - [Fact] - public async Task CounterStartsAtTheTaskCountAndFallsToZero() - { - var backing = new ConditionalStore(); - var store = await SeededAsync(backing, 3); - - Assert.Equal(3, await store.GetRemainingAsync(Run)); - - Assert.Equal(2, await store.CompleteTaskAsync(Run, Task_("task-0"))); - Assert.Equal(1, await store.CompleteTaskAsync(Run, Task_("task-1"))); - Assert.Equal(0, await store.CompleteTaskAsync(Run, Task_("task-2"))); - - Assert.Equal(0, await store.GetRemainingAsync(Run)); - } - - /// - /// THE GUARANTEE. Replaying a completion — which the status writer does whenever a run's batch fails - /// and is requeued — must not decrement twice. A run that double-counts finishes on paper before its - /// work is done. - /// - [Fact] - public async Task ReplayingACompletionDoesNotDecrementTwice() - { - var backing = new ConditionalStore(); - var store = await SeededAsync(backing, 2); - - var task = Task_("task-0"); - Assert.Equal(1, await store.CompleteTaskAsync(Run, task)); - - // Same completion again. Completing a completed task reports the count and changes nothing. - var writesBefore = backing.ConditionalWrites; - var replay = await store.CompleteTaskAsync(Run, task); - - Assert.Equal(1, replay); - Assert.Equal(1, await store.GetRemainingAsync(Run)); - Assert.Equal(writesBefore, backing.ConditionalWrites); - } - - /// - /// A competitor updating the counter between our read and our write must not cost us our decrement. - /// Both completions have to count. - /// - [Fact] - public async Task ConcurrentCompletionsBothCount() - { - var backing = new ConditionalStore(); - var store = await SeededAsync(backing, 5); - - var interfered = false; - backing.OnBeforeConditionalWrite = () => - { - if (interfered) return; - interfered = true; - // Land a competing completion first, invalidating the counter ETag we just read. - store.CompleteTaskAsync(Run, Task_("task-9")).GetAwaiter().GetResult(); - }; - - await store.CompleteTaskAsync(Run, Task_("task-0")); - backing.OnBeforeConditionalWrite = null; - - // task-9 does not exist, so only our own decrement should have landed. - Assert.Equal(4, await store.GetRemainingAsync(Run)); - } - /// /// The counter shares the task partition so it can ride the same transaction. Nothing that reads /// tasks may mistake it for one — a phantom task never completes, and the run never finalizes. @@ -284,7 +220,7 @@ public async Task MissingCounterReportsNullRatherThanGuessing() await store.InitializeAsync(); Assert.Null(await store.GetRemainingAsync("never-seeded")); - Assert.Null(await store.CompleteTaskAsync("never-seeded", Task_("task-0"))); + Assert.Null(await store.DecrementRemainingAsync("never-seeded", 1)); } // ─── Reconciliation (the lost-decrement repair) ─── @@ -348,11 +284,11 @@ public async Task ReconcileLosingARaceDoesNotClobberTheCompetitor() backing.OnBeforeConditionalWrite = () => { backing.OnBeforeConditionalWrite = null; - store.CompleteTaskAsync(Run, Task_("task-1")).GetAwaiter().GetResult(); + store.DecrementRemainingAsync(Run, 1).GetAwaiter().GetResult(); }; Assert.Null(await store.ReconcileRemainingAsync(Run)); - // The competitor's decrement survived: 3 seeded − 1 completed-by-competitor. + // The competitor's decrement survived: 3 seeded − 1 decremented-by-competitor. Assert.Equal(2, await store.GetRemainingAsync(Run)); } diff --git a/tests/Craft.Tests/SkuProfileSelectorTests.cs b/tests/Craft.Tests/SkuProfileSelectorTests.cs index 5e4c454..95a566d 100644 --- a/tests/Craft.Tests/SkuProfileSelectorTests.cs +++ b/tests/Craft.Tests/SkuProfileSelectorTests.cs @@ -191,4 +191,97 @@ public void EnvironmentLookupThrowing_DoesNotTakeTheHostDown() Assert.Equal(2, settings.Worker.HttpPoolSize); Assert.Contains(logs, l => l.Contains("SkuProfile detection failed", StringComparison.Ordinal)); } + + // ---- Second SkuProfiles matrix — selected by env-var presence ---- + + [Fact] + public void AltEnvPresent_SelectsSecondMatrixOverDefault() + { + var settings = WithProfiles(new SkuProfile { SkuEnv = "", HttpPoolSize = 20, BgPoolSize = 30 }); // default + settings.Worker.SkuProfilesAltEnv = "CIPP_HOSTED"; + settings.Worker.SkuProfilesAlt.Add(new SkuProfile { SkuEnv = "", HttpPoolSize = 2, BgPoolSize = 3 }); // second + + var applied = SkuProfileSelector.Apply(settings, 8, Env(("CIPP_HOSTED", "true")), _ => { }); + + Assert.NotNull(applied); + Assert.Equal(2, settings.Worker.HttpPoolSize); // second matrix won + Assert.Equal(3, settings.Worker.BgPoolSize); + } + + [Fact] + public void AltEnvName_IsConfigurable_AndAnyNonEmptyValueCounts() + { + var settings = WithProfiles(new SkuProfile { SkuEnv = "", HttpPoolSize = 20, BgPoolSize = 30 }); + settings.Worker.SkuProfilesAltEnv = "MY_FLAG"; + settings.Worker.SkuProfilesAlt.Add(new SkuProfile { SkuEnv = "", HttpPoolSize = 2, BgPoolSize = 2 }); + + var applied = SkuProfileSelector.Apply(settings, 8, Env(("MY_FLAG", "anything")), _ => { }); + + Assert.NotNull(applied); + Assert.Equal(2, settings.Worker.HttpPoolSize); + } + + [Fact] + public void AltEnvAbsent_UsesDefaultMatrix() + { + var settings = WithProfiles(new SkuProfile { SkuEnv = "", HttpPoolSize = 20, BgPoolSize = 30 }); + settings.Worker.SkuProfilesAltEnv = "CIPP_HOSTED"; + settings.Worker.SkuProfilesAlt.Add(new SkuProfile { SkuEnv = "", HttpPoolSize = 2, BgPoolSize = 3 }); + + var applied = SkuProfileSelector.Apply(settings, 8, Env(), _ => { }); // flag not set + + Assert.NotNull(applied); + Assert.Equal(20, settings.Worker.HttpPoolSize); + } + + [Fact] + public void AltEnvPresent_ButSecondMatrixEmpty_FallsBackToDefaultAndLogs() + { + var settings = WithProfiles(new SkuProfile { SkuEnv = "", HttpPoolSize = 20, BgPoolSize = 30 }); + settings.Worker.SkuProfilesAltEnv = "CIPP_HOSTED"; // SkuProfilesAlt left empty + var logs = new List(); + + var applied = SkuProfileSelector.Apply(settings, 8, Env(("CIPP_HOSTED", "true")), logs.Add); + + Assert.NotNull(applied); + Assert.Equal(20, settings.Worker.HttpPoolSize); // default matrix used + Assert.Contains(logs, l => l.Contains("SkuProfilesAlt is empty", StringComparison.Ordinal)); + } + + // ---- Per-instance env overrides (win over the matrix) ---- + + [Fact] + public void EnvOverride_HttpAndBg_WinOverMatchedProfile() + { + var settings = WithProfiles(new SkuProfile { SkuEnv = "", HttpPoolSize = 20, BgPoolSize = 30 }); + + SkuProfileSelector.Apply(settings, 8, Env(("CRAFT_HTTP_POOL_SIZE", "3"), ("CRAFT_BG_POOL_SIZE", "5")), _ => { }); + + Assert.Equal(3, settings.Worker.HttpPoolSize); // env beat the profile's 20 + Assert.Equal(5, settings.Worker.BgPoolSize); // env beat the profile's 30 + } + + [Fact] + public void EnvOverride_AppliesEvenWithNoProfilesConfigured() + { + var settings = WithProfiles(); // baseline 2 / 4, no profiles + + SkuProfileSelector.Apply(settings, 8, Env(("CRAFT_HTTP_POOL_SIZE", "7")), _ => { }); + + Assert.Equal(7, settings.Worker.HttpPoolSize); // override applied over the baseline + Assert.Equal(4, settings.Worker.BgPoolSize); // untouched + } + + [Fact] + public void EnvOverride_ZeroIsHonored_NegativeAndGarbageAreIgnored() + { + var settings = WithProfiles(); + settings.Worker.HttpPoolSize = 6; + settings.Worker.BgPoolSize = 8; + + SkuProfileSelector.Apply(settings, 8, Env(("CRAFT_HTTP_POOL_SIZE", "0"), ("CRAFT_BG_POOL_SIZE", "-1")), _ => { }); + + Assert.Equal(0, settings.Worker.HttpPoolSize); // 0 is a valid HTTP pool size (native-only HTTP) + Assert.Equal(8, settings.Worker.BgPoolSize); // negative ignored -> baseline kept + } } diff --git a/tests/Craft.Tests/StatusWriterDurabilityTests.cs b/tests/Craft.Tests/StatusWriterDurabilityTests.cs index b237408..3b8b246 100644 --- a/tests/Craft.Tests/StatusWriterDurabilityTests.cs +++ b/tests/Craft.Tests/StatusWriterDurabilityTests.cs @@ -165,6 +165,42 @@ private static (OrchestratorStatusWriter Writer, ControllableStore Backing) NewW private static OrchestratorTaskItem Task1(string id = "t1") => new() { Id = id, Status = "Running", Parameters = new Dictionary { ["TenantFilter"] = "x.com" } }; + // ── R2: COALESCED SMALL-RESULT WRITES ───────────────────────────────────────────────────────────── + + /// + /// A small result rides the writer and is durable after a flush; one too large for a single table + /// property is refused, so the caller keeps the chunked StoreResultAsync path. + /// + [Fact] + public async Task SmallResult_Coalesces_AndIsDurable_WhileLargeResultIsRefused() + { + var settings = new CraftSettings(); + var backing = new ControllableStore(); + var store = new OrchestratorTableStore(NullLogger.Instance, settings, backing); + using var writer = new OrchestratorStatusWriter(store, NullLogger.Instance, settings); + + Assert.True(writer.TryQueueResult("run", "t1", "{\"ok\":true}")); + // 30 001 chars is one over the single-property bound — must fall back to the direct chunked path. + Assert.False(writer.TryQueueResult("run", "t2", new string('x', 30_001))); + + await writer.FlushAsync(); + + Assert.Contains("{\"ok\":true}", await store.GetResultsAsync("run")); + } + + /// With result-batching off, TryQueueResult refuses so the caller writes results directly. + [Fact] + public void TryQueueResult_IsRefused_WhenResultBatchingIsOff() + { + var settings = new CraftSettings(); + settings.Orchestrator.BatchResultWrites = false; + var backing = new ControllableStore(); + var store = new OrchestratorTableStore(NullLogger.Instance, settings, backing); + using var writer = new OrchestratorStatusWriter(store, NullLogger.Instance, settings); + + Assert.False(writer.TryQueueResult("run", "t1", "{\"ok\":true}")); + } + // ── LIVENESS ──────────────────────────────────────────────────────────────────────────────────── /// diff --git a/tests/Craft.Tests/TableKeyTests.cs b/tests/Craft.Tests/TableKeyTests.cs index ef9fb2a..c8e469f 100644 --- a/tests/Craft.Tests/TableKeyTests.cs +++ b/tests/Craft.Tests/TableKeyTests.cs @@ -99,8 +99,7 @@ public void QueueRowKeyIsLegalForARepoNamedTask() } """); - var rowKey = JobQueueStore.BuildRowKey( - new DateTime(2026, 8, 11, 4, 31, 0, DateTimeKind.Utc), "UserTaskOrchestrator_No tenant", id); + var rowKey = JobQueueStore.BuildRowKey("UserTaskOrchestrator_No tenant", id); Assert.True(TableKeys.IsSafe(rowKey)); } diff --git a/tests/Craft.Tests/ThreadReuseContextTests.cs b/tests/Craft.Tests/ThreadReuseContextTests.cs new file mode 100644 index 0000000..d5c802c --- /dev/null +++ b/tests/Craft.Tests/ThreadReuseContextTests.cs @@ -0,0 +1,163 @@ +using System.Collections.ObjectModel; +using System.Diagnostics; +using System.Management.Automation; +using System.Management.Automation.Runspaces; +using Xunit.Abstractions; + +namespace Craft.Tests; + +/// +/// The worker runs its pipeline on a reused thread (PSThreadOptions.ReuseThread, a ~50%-of- +/// invoke-cost optimization in PowerShellWorker.Initialize). A reused thread keeps its +/// ExecutionContext across invocations, so an value set +/// by one invocation is visible to the next on the same worker — a real per-invocation leak. Runspace +/// SessionState (module $script: vars, injected caches) persists regardless of thread, so it is +/// NOT the thing that leaks and must NOT be the thing a fix clears. +/// +/// This harness pins that behaviour down and compares the two candidate fixes on a raw runspace +/// configured exactly like a Craft worker, which isolates the one variable under test (thread reuse): +/// * Solution 1 — keep ReuseThread, reset the ExecutionContext each invocation (ExecutionContextReset). +/// * Solution 2 — drop ReuseThread (UseNewThread): a fresh thread ⇒ a fresh ExecutionContext. +/// Both must clear the leak AND preserve SessionState; the benchmark shows what each costs per invoke. +/// +public class ThreadReuseContextTests +{ + private readonly ITestOutputHelper _out; + public ThreadReuseContextTests(ITestOutputHelper output) => _out = output; + + // Solution 1: run the reset on the pipeline thread as the first statement of an invocation. + private const string ResetStatement = "[Craft.Tests.ExecutionContextReset]::ResetToClean();"; + private const string CaptureBaseline = "[Craft.Tests.ExecutionContextReset]::CaptureBaseline();"; + + // Invocation A: the AsyncLocal OBJECT lives in a global (SessionState, persists like an injected + // cache); its .Value lives in the ExecutionContext (the thing that leaks). A plain session marker + // proves a fix leaves SessionState alone. + private const string SetLeak = @" + $global:__al = [System.Threading.AsyncLocal[object]]::new() + $global:__al.Value = 'LEAKED-FROM-A' + $global:__session = 'CACHE-FROM-A' + "; + + // Invocation B: read both back. + private const string ReadBack = + "[pscustomobject]@{ AsyncLocal = $global:__al.Value; Session = $global:__session }"; + + private static Runspace NewRunspace(PSThreadOptions opts) + { + var rs = RunspaceFactory.CreateRunspace(InitialSessionState.CreateDefault2()); + rs.ThreadOptions = opts; // must be set before Open + rs.Open(); + return rs; + } + + private static Collection Invoke(Runspace rs, string script) + { + using var ps = PowerShell.Create(); + ps.Runspace = rs; + ps.AddScript(script); + return ps.Invoke(); + } + + private static (string? asyncLocal, string? session) ReadBackValues(Runspace rs, string prefix = "") + { + var o = Invoke(rs, prefix + ReadBack)[0]; + return ((string?)o.Properties["AsyncLocal"]?.Value, (string?)o.Properties["Session"]?.Value); + } + + [Fact] // A1 — establish the premise + public void ReuseThread_LeaksAsyncLocalAcrossInvocations() + { + using var rs = NewRunspace(PSThreadOptions.ReuseThread); + Invoke(rs, SetLeak); + var (al, session) = ReadBackValues(rs); + + Assert.Equal("LEAKED-FROM-A", al); // the leak: B sees A's AsyncLocal value + Assert.Equal("CACHE-FROM-A", session); // SessionState persists (expected and wanted) + } + + [Fact] // Solution 2 + public void UseNewThread_DoesNotLeak_ButKeepsSessionState() + { + using var rs = NewRunspace(PSThreadOptions.UseNewThread); + Invoke(rs, SetLeak); + var (al, session) = ReadBackValues(rs); + + Assert.Null(al); // no leak: fresh thread ⇒ fresh ExecutionContext + Assert.Equal("CACHE-FROM-A", session); // injected/session caches survive — they are SessionState, not thread state + } + + [Fact] // Solution 1 + public void ReuseThread_WithEcReset_DoesNotLeak_ButKeepsSessionState() + { + Assert.True(ExecutionContextReset.PublicRestoreAvailable, + "ExecutionContext.Restore(ExecutionContext) not public on this runtime — S1 would need a fallback."); + + using var rs = NewRunspace(PSThreadOptions.ReuseThread); + Invoke(rs, CaptureBaseline); // capture the clean warmup baseline on the pipeline thread + Invoke(rs, SetLeak); + var (al, session) = ReadBackValues(rs, prefix: ResetStatement); // reset restores the baseline, on the pipeline thread + + Assert.Null(al); // reset cleared the leaked ExecutionContext + Assert.Equal("CACHE-FROM-A", session); // SessionState untouched by the EC reset + } + + [Fact] // Solution 1 vs Solution 2 — the decision-relevant numbers + public void Benchmark_ReuseVsReuseResetVsNewThread() + { + int warmup = EnvInt("CRAFT_BENCH_WARMUP", 200); + int iters = EnvInt("CRAFT_BENCH_ITERS", 1500); + + var scripts = new (string name, string body)[] + { + ("trivial", "$null = 1"), // isolates dispatch/thread/reset overhead + ("work", "$s=0; foreach($i in 1..200){ $s += $i }; [void]('x'*64)"), // a light real-world invocation + }; + var modes = new (string name, PSThreadOptions opt, string prefix)[] + { + ("ReuseThread (leaky baseline)", PSThreadOptions.ReuseThread, ""), + ("ReuseThread + EC reset (S1)", PSThreadOptions.ReuseThread, ResetStatement), + ("UseNewThread (S2)", PSThreadOptions.UseNewThread, ""), + }; + + string mech; + using (var probe = NewRunspace(PSThreadOptions.ReuseThread)) + mech = Invoke(probe, CaptureBaseline + "[Craft.Tests.ExecutionContextReset]::Mechanism")[0]?.ToString() ?? "?"; + _out.WriteLine($"net{Environment.Version} publicRestore={ExecutionContextReset.PublicRestoreAvailable} S1 reset: {mech} warmup={warmup} iters={iters}"); + _out.WriteLine("per-invoke dispatch, reused pipeline (isolates the thread-reuse delta) (override with CRAFT_BENCH_WARMUP / CRAFT_BENCH_ITERS)\n"); + _out.WriteLine($"{"script",-8} {"mode",-30} {"median µs",11} {"p95 µs",10} {"mean µs",10} {"vs base",8}"); + + foreach (var (sname, body) in scripts) + { + double baseMedian = 0; + foreach (var (mname, opt, prefix) in modes) + { + using var rs = NewRunspace(opt); + using var ps = PowerShell.Create(); + ps.Runspace = rs; + ps.AddScript(prefix + body); // parse once; each Invoke re-runs the pipeline (new thread under UseNewThread) + + if (prefix.Length > 0) Invoke(rs, CaptureBaseline); // S1: capture the clean baseline on the pipeline thread + + for (int i = 0; i < warmup; i++) ps.Invoke(); + + var us = new double[iters]; + for (int i = 0; i < iters; i++) + { + long t = Stopwatch.GetTimestamp(); + ps.Invoke(); + us[i] = (Stopwatch.GetTimestamp() - t) * 1_000_000.0 / Stopwatch.Frequency; + } + Array.Sort(us); + double median = us[iters / 2], p95 = us[(int)(iters * 0.95)], mean = us.Average(); + if (prefix.Length == 0 && opt == PSThreadOptions.ReuseThread) baseMedian = median; + string vs = baseMedian > 0 ? $"{median / baseMedian:0.00}x" : "-"; + + _out.WriteLine($"{sname,-8} {mname,-30} {median,11:0.0} {p95,10:0.0} {mean,10:0.0} {vs,8}"); + } + _out.WriteLine(""); + } + } + + private static int EnvInt(string name, int dflt) => + int.TryParse(Environment.GetEnvironmentVariable(name), out var v) && v > 0 ? v : dflt; +}