From ad5dc324aaf84eda2cf4d72cd30f92e9292ca77c Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Tue, 25 Aug 2026 20:46:32 +0800 Subject: [PATCH 01/17] feat(hosting): make the HTTP worker-queue timeout configurable The wait for a free HTTP runspace before a request is shed with 503 was a hardcoded TimeSpan.FromSeconds(30) at both checkout sites in PowerShellRunnerService. Surface it as Worker:HttpQueueTimeoutSeconds with a CRAFT_HTTP_QUEUE_TIMEOUT env override, resolved once via CraftHostBuilderExtensions.ResolveHttpQueueTimeout (env > setting > built-in 30s default), mirroring how MinThreads resolves. This is a load-shedding bound, not a capacity knob. --- Services/Configuration/WorkerSettings.cs | 23 ++++++ .../Hosting/CraftHostBuilderExtensions.cs | 25 +++++++ .../PowerShellHost/PowerShellRunnerService.cs | 12 ++- appsettings.example.jsonc | 8 ++ tests/Craft.Tests/HttpQueueTimeoutTests.cs | 75 +++++++++++++++++++ 5 files changed, 140 insertions(+), 3 deletions(-) create mode 100644 tests/Craft.Tests/HttpQueueTimeoutTests.cs diff --git a/Services/Configuration/WorkerSettings.cs b/Services/Configuration/WorkerSettings.cs index 7ed4dba..5062e0e 100644 --- a/Services/Configuration/WorkerSettings.cs +++ b/Services/Configuration/WorkerSettings.cs @@ -75,6 +75,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/CraftHostBuilderExtensions.cs b/Services/Hosting/CraftHostBuilderExtensions.cs index a331e3d..544d882 100644 --- a/Services/Hosting/CraftHostBuilderExtensions.cs +++ b/Services/Hosting/CraftHostBuilderExtensions.cs @@ -74,6 +74,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. 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/appsettings.example.jsonc b/appsettings.example.jsonc index d6159b4..b740baf 100644 --- a/appsettings.example.jsonc +++ b/appsettings.example.jsonc @@ -163,6 +163,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/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))); + } +} From 3a90cb11b6fdbaa803fc8a43aea2540a3ac3419e Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Tue, 25 Aug 2026 20:53:00 +0800 Subject: [PATCH 02/17] feat(hosting): log rate-limit rejections when a 429 is sent The rate limiter set Retry-After on a throttled request but logged nothing, so every 429 went out invisible to operators. Emit a warning from OnRejected naming the partition the limit fired for (authenticated principal, else client address) plus the method, path and Retry-After. The logger is resolved per rejection (service registration has no built provider yet) and any logging failure is swallowed so it can never turn a throttle into a 500. --- .../Hosting/CraftHostBuilderExtensions.cs | 24 +++++++++++++++++-- 1 file changed, 22 insertions(+), 2 deletions(-) diff --git a/Services/Hosting/CraftHostBuilderExtensions.cs b/Services/Hosting/CraftHostBuilderExtensions.cs index 544d882..d341762 100644 --- a/Services/Hosting/CraftHostBuilderExtensions.cs +++ b/Services/Hosting/CraftHostBuilderExtensions.cs @@ -316,9 +316,29 @@ 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; }; From af2140813a13b9012d0492caf99d515f4ff4eeac Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Tue, 25 Aug 2026 21:17:19 +0800 Subject: [PATCH 03/17] feat(hosting): cap per-client API concurrency, chained onto the rate limiter MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add an optional per-client concurrency cap on app-only API callers so one automation cannot hold every runspace at once and starve the interactive UI, which is never capped. Config RateLimit:ApiConcurrencyLimit (env override CRAFT_API_CONCURRENCY_LIMIT), 0 = off by default. Because the limiter's lease spans the whole downstream pipeline, a permit covers both the wait for a runspace and execution — so the cap counts in-flight and queued-for-a-worker requests alike. Over-limit is rejected immediately with 429 (QueueLimit 0), reusing the existing Retry-After + log path. Callers are classified by a new, tested CallerClassifier (idp=aad plus a GUID AppId principal). The per-client rate limiter and the concurrency cap are built as chained partitioned limiters, and the middleware now runs whenever either is active. --- Services/Configuration/RateLimitSettings.cs | 36 +++++ Services/Hosting/CallerClassifier.cs | 31 ++++ .../Hosting/CraftHostBuilderExtensions.cs | 73 +++++++-- Services/Program.cs | 2 +- appsettings.example.jsonc | 17 ++- tests/Craft.Tests/CallerClassifierTests.cs | 139 ++++++++++++++++++ 6 files changed, 279 insertions(+), 19 deletions(-) create mode 100644 Services/Hosting/CallerClassifier.cs create mode 100644 tests/Craft.Tests/CallerClassifierTests.cs 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/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 d341762..e649528 100644 --- a/Services/Hosting/CraftHostBuilderExtensions.cs +++ b/Services/Hosting/CraftHostBuilderExtensions.cs @@ -293,9 +293,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) @@ -303,9 +310,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 => { @@ -342,16 +350,51 @@ public static IServiceCollection AddCraftRateLimiter( 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/Program.cs b/Services/Program.cs index 2bfdcb5..6cef08a 100644 --- a/Services/Program.cs +++ b/Services/Program.cs @@ -382,7 +382,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 diff --git a/appsettings.example.jsonc b/appsettings.example.jsonc index b740baf..632997b 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 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); + } +} From d6012a3b9dcb5a0291178410c95d8b17689b9dd0 Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Wed, 26 Aug 2026 08:29:44 +0800 Subject: [PATCH 04/17] feat(hosting): set the GC heap hard limit per host tier via SkuProfiles The image bakes a DOTNET_GCHeapHardLimit sized for the smallest tier, and the CLR consumes it before any managed code runs - so larger tiers were stuck with the small tier's heap cap. Let a SkuProfile carry an optional GCHeapHardLimitMB and apply it on the matched profile at startup through AppContext.SetData + GC.RefreshMemoryLimit (.NET 8), under the same best-effort contract as pool sizing: any refusal logs and keeps the baseline rather than failing startup. --- Services/Configuration/SkuProfile.cs | 9 +++ Services/Hosting/GcHeapLimit.cs | 65 ++++++++++++++++++ Services/Hosting/SkuProfileSelector.cs | 4 ++ Services/Program.cs | 6 +- appsettings.example.jsonc | 7 +- tests/Craft.Tests/GcHeapLimitTests.cs | 94 ++++++++++++++++++++++++++ 6 files changed, 182 insertions(+), 3 deletions(-) create mode 100644 Services/Hosting/GcHeapLimit.cs create mode 100644 tests/Craft.Tests/GcHeapLimitTests.cs diff --git a/Services/Configuration/SkuProfile.cs b/Services/Configuration/SkuProfile.cs index 83ce805..fb5048f 100644 --- a/Services/Configuration/SkuProfile.cs +++ b/Services/Configuration/SkuProfile.cs @@ -32,4 +32,13 @@ 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. Omit or 0 = keep the + /// process baseline (typically the DOTNET_GCHeapHardLimit env var baked into the image for the + /// smallest tier). The env var is consumed by the CLR before any managed code runs, so this is + /// applied after the fact via — raising the limit is + /// always safe; a value the heap has already outgrown is refused and logged. + /// + public int? GCHeapHardLimitMB { get; set; } } diff --git a/Services/Hosting/GcHeapLimit.cs b/Services/Hosting/GcHeapLimit.cs new file mode 100644 index 0000000..b1dbc54 --- /dev/null +++ b/Services/Hosting/GcHeapLimit.cs @@ -0,0 +1,65 @@ +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) and applies it to the running GC. +/// +/// +/// 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 from the matched profile, if it carries one. + /// + /// 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. + /// when a limit was applied. + public static bool Apply(SkuProfile? profile, Action log, Action? refresh = null) + { + ArgumentNullException.ThrowIfNull(log); + + var mb = profile?.GCHeapHardLimitMB ?? 0; + if (mb <= 0) return false; + + refresh ??= SetAndRefresh; + var beforeMB = GC.GetGCMemoryInfo().TotalAvailableMemoryBytes / (1024 * 1024); + try + { + refresh((ulong)mb * 1024 * 1024); + var afterMB = GC.GetGCMemoryInfo().TotalAvailableMemoryBytes / (1024 * 1024); + log($"[System] GC heap hard limit set to {mb} MB by SkuProfile " + + $"(TotalAvailableMemory {beforeMB} MB -> {afterMB} MB)"); + return true; + } + catch (Exception ex) + { + // Same contract as pool sizing: a sizing hint must never prevent startup. + log($"[System] GC heap hard limit refresh to {mb} MB 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..072060e 100644 --- a/Services/Hosting/SkuProfileSelector.cs +++ b/Services/Hosting/SkuProfileSelector.cs @@ -15,6 +15,10 @@ namespace Craft.Hosting; /// 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. /// +/// +/// The returned profile may also carry a ; applying that +/// is a process-wide side effect and lives in , not here. +/// /// public static class SkuProfileSelector { diff --git a/Services/Program.cs b/Services/Program.cs index 6cef08a..9cb7874 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); diff --git a/appsettings.example.jsonc b/appsettings.example.jsonc index 632997b..693c0d4 100644 --- a/appsettings.example.jsonc +++ b/appsettings.example.jsonc @@ -153,13 +153,18 @@ // (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. Omit or + // 0 = keep the process baseline. Raising is always safe; a value the + // heap has already outgrown is refused and logged, keeping the baseline. // 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 } // ], diff --git a/tests/Craft.Tests/GcHeapLimitTests.cs b/tests/Craft.Tests/GcHeapLimitTests.cs new file mode 100644 index 0000000..29c4e85 --- /dev/null +++ b/tests/Craft.Tests/GcHeapLimitTests.cs @@ -0,0 +1,94 @@ +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(0)] + [InlineData(-1)] + public void ProfileWithoutALimit_IsANoOp(int? mb) + { + 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 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 refresh to 1 MB 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(); + } + } +} From adbf6af10dd21c7f5fefc4af2b154fdbab625f60 Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Fri, 28 Aug 2026 22:09:43 +0800 Subject: [PATCH 05/17] fix(orchestration): keep a background OOM from stalling the run and false-failing jobs Under a pegged GC hard limit, an OutOfMemoryException thrown while logging inside the JobQueuePump and JobManager catch-all blocks escaped ExecuteAsync. With the host's default BackgroundServiceExceptionBehavior.StopHost that faults the service and restarts the container mid-run: dispatch stops with work still queued, and the pending backlog waits for the restart to reclaim its leases. Guard those two log calls the way BackgroundTaskLimiter already guards its own ("logging is never worth the loop") so an allocation failure in logging can no longer take the host down. Separately, jobs still in flight when a shutdown began finished their work and persisted their data, then threw ObjectDisposedException enqueueing their terminal status because OrchestratorStatusWriter._signal was already disposed -- so a task that fully succeeded was recorded as Failed. Route every drain-loop wake through a guarded Signal() that drops the wake once disposed. A lost coalesced status wake on the way down is harmless; a succeeded task marked Failed is not. --- Services/Orchestration/JobManager.cs | 8 +++++- Services/Orchestration/JobQueuePump.cs | 9 +++++- .../Orchestration/OrchestratorStatusWriter.cs | 28 +++++++++++++++---- 3 files changed, 38 insertions(+), 7 deletions(-) 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..bbfa919 100644 --- a/Services/Orchestration/JobQueuePump.cs +++ b/Services/Orchestration/JobQueuePump.cs @@ -92,7 +92,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 diff --git a/Services/Orchestration/OrchestratorStatusWriter.cs b/Services/Orchestration/OrchestratorStatusWriter.cs index 10dd3e7..22e687e 100644 --- a/Services/Orchestration/OrchestratorStatusWriter.cs +++ b/Services/Orchestration/OrchestratorStatusWriter.cs @@ -41,6 +41,10 @@ public sealed class OrchestratorStatusWriter : IDisposable 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) @@ -84,7 +88,7 @@ public async Task MarkRunningAsync(string runName, OrchestratorTaskItem task, Ca _pendingTasks[Key(runName, task.Id)] = Snap(runName, task); barrier = _barrier.Task; } - _signal.Release(); + Signal(); // Bounded. This wait sits between dispatch and worker checkout while holding a JobManager slot, // so waiting forever converts a slow flush into a whole-host outage — observed in production as @@ -135,7 +139,7 @@ public void QueueTask(string runName, OrchestratorTaskItem task) { if (!_enabled) { _ = _store.UpsertTaskAsync(runName, task); return; } lock (_lock) { _pendingTasks[Key(runName, task.Id)] = Snap(runName, task); } - _signal.Release(); + Signal(); } /// Queue a run's status — non-blocking, coalesced, flushed by the drain loop. @@ -143,7 +147,7 @@ public void QueueRun(OrchestratorRun run) { if (!_enabled) { _ = _store.UpsertRunAsync(run); return; } lock (_lock) { _pendingRuns[run.Name] = run; } - _signal.Release(); + Signal(); } /// Flush all currently-pending writes and await their persistence. Call before finalizing a run @@ -153,7 +157,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 @@ -296,14 +300,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(); From ed337c04e3b063e7d32a61a941573b174570ab0f Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Fri, 28 Aug 2026 22:11:23 +0800 Subject: [PATCH 06/17] feat(telemetry): add startup usage reporting Introduce opt-in startup telemetry with configurable endpoint, app ID, timeouts, and jittered delays. Register a hosted service that emits one guarded boot report per instance using persisted storage state, and add version stamping plus native catalog injection so reports include meaningful build and surface metadata. --- Directory.Build.props | 8 + Services/Configuration/CraftSettings.cs | 3 + Services/Configuration/TelemetrySettings.cs | 41 +++ .../Hosting/CraftHostBuilderExtensions.cs | 10 + Services/Program.cs | 3 + Services/Telemetry/StartupReport.cs | 22 ++ Services/Telemetry/StartupTelemetryService.cs | 251 ++++++++++++++++++ 7 files changed, 338 insertions(+) create mode 100644 Services/Configuration/TelemetrySettings.cs create mode 100644 Services/Telemetry/StartupReport.cs create mode 100644 Services/Telemetry/StartupTelemetryService.cs 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/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/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/Hosting/CraftHostBuilderExtensions.cs b/Services/Hosting/CraftHostBuilderExtensions.cs index e649528..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; @@ -268,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; } diff --git a/Services/Program.cs b/Services/Program.cs index 9cb7874..132a665 100644 --- a/Services/Program.cs +++ b/Services/Program.cs @@ -75,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); 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); +} From 7d1653c3e03e65bc6a1663c005b07564f02ad8ce Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Sun, 30 Aug 2026 14:55:33 +0800 Subject: [PATCH 07/17] fix(orchestration): guard the run-status timer callback against crashing the host MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A System.Threading.Timer callback that throws takes the whole process down. The per-run 60s maintenance tick (LogRunStatus / RedrivePendingTasks / CheckRunCompletion) had no guard, so a transient error — a dependency disposed during shutdown, a race on run state — would crash the host instead of being logged and retried on the next tick. Wrap the callback in try/catch (null-safe logger). --- Services/Orchestration/OrchestratorService.cs | 16 +++++++++++++--- 1 file changed, 13 insertions(+), 3 deletions(-) diff --git a/Services/Orchestration/OrchestratorService.cs b/Services/Orchestration/OrchestratorService.cs index 53c8f8c..9f77b3f 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)) From 363921ff42e116f5ef03958796cdb267904b81ed Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Sun, 30 Aug 2026 23:16:50 +0800 Subject: [PATCH 08/17] feat(hosting): add CRAFT_GC_HEAP_LIMIT_MB per-instance GC heap override The SkuProfile GC limit lands through AppContext + GC.RefreshMemoryLimit, which the runtime treats as precedence over DOTNET_GCHeapHardLimit (it won't re-read that env var on refresh). So a fleet-wide profile value silently countermands a heap limit an operator hand-set on a single instance. Add CRAFT_GC_HEAP_LIMIT_MB as the per-instance escape hatch, mirroring CRAFT_API_CONCURRENCY_LIMIT and CRAFT_HTTP_QUEUE_TIMEOUT: when set it wins over the matched profile. A positive value sets the cap; 0 disables it entirely, refreshing to the container's own memory allowance. Unset/negative/unparseable defers to the profile (unchanged behaviour). Disabling only ever raises the limit, so it cannot trip RefreshMemoryLimit's below-committed-heap guard; any refusal logs and keeps the baseline, same best-effort contract as pool sizing. --- Services/Configuration/SkuProfile.cs | 5 ++ Services/Hosting/GcHeapLimit.cs | 60 +++++++++++++++++--- appsettings.example.jsonc | 3 + tests/Craft.Tests/GcHeapLimitTests.cs | 81 ++++++++++++++++++++++++++- 4 files changed, 139 insertions(+), 10 deletions(-) diff --git a/Services/Configuration/SkuProfile.cs b/Services/Configuration/SkuProfile.cs index fb5048f..fe243b7 100644 --- a/Services/Configuration/SkuProfile.cs +++ b/Services/Configuration/SkuProfile.cs @@ -39,6 +39,11 @@ public class SkuProfile /// smallest tier). The env var is consumed by the CLR before any managed code runs, so this is /// applied after the fact via — raising the limit is /// always safe; a 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/Hosting/GcHeapLimit.cs b/Services/Hosting/GcHeapLimit.cs index b1dbc54..14ae7a0 100644 --- a/Services/Hosting/GcHeapLimit.cs +++ b/Services/Hosting/GcHeapLimit.cs @@ -1,3 +1,4 @@ +using System.Globalization; using Craft.Configuration; namespace Craft.Hosting; @@ -10,7 +11,16 @@ namespace Craft.Hosting; /// 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) and applies it to the running GC. +/// 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 @@ -21,19 +31,48 @@ namespace Craft.Hosting; public static class GcHeapLimit { /// - /// Applies from the matched profile, if it carries one. + /// 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. - /// when a limit was applied. - public static bool Apply(SkuProfile? profile, Action log, Action? refresh = null) + /// 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); - var mb = profile?.GCHeapHardLimitMB ?? 0; - if (mb <= 0) return false; + // 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. Distinct from a profile's 0/null, which means + // "no opinion, keep the baseline". 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 (original behaviour). + 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 + { + mb = profile?.GCHeapHardLimitMB ?? 0; + source = "SkuProfile"; + // Profile 0/null/negative = keep the process baseline, silently (like unused SkuProfiles). + if (mb <= 0) return false; + } refresh ??= SetAndRefresh; var beforeMB = GC.GetGCMemoryInfo().TotalAvailableMemoryBytes / (1024 * 1024); @@ -41,14 +80,17 @@ public static bool Apply(SkuProfile? profile, Action log, Action? { refresh((ulong)mb * 1024 * 1024); var afterMB = GC.GetGCMemoryInfo().TotalAvailableMemoryBytes / (1024 * 1024); - log($"[System] GC heap hard limit set to {mb} MB by SkuProfile " + - $"(TotalAvailableMemory {beforeMB} MB -> {afterMB} MB)"); + 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. - log($"[System] GC heap hard limit refresh to {mb} MB failed " + + 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; } diff --git a/appsettings.example.jsonc b/appsettings.example.jsonc index 693c0d4..3219f20 100644 --- a/appsettings.example.jsonc +++ b/appsettings.example.jsonc @@ -158,6 +158,9 @@ // so this lands via GC.RefreshMemoryLimit at startup instead. Omit or // 0 = keep the process baseline. Raising is always safe; a value the // heap has already outgrown is refused and logged, keeping the baseline. + // 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, diff --git a/tests/Craft.Tests/GcHeapLimitTests.cs b/tests/Craft.Tests/GcHeapLimitTests.cs index 29c4e85..5566ae9 100644 --- a/tests/Craft.Tests/GcHeapLimitTests.cs +++ b/tests/Craft.Tests/GcHeapLimitTests.cs @@ -64,7 +64,7 @@ public void RefreshRefusingTheLimit_LogsAndKeepsTheBaseline() _ => throw new InvalidOperationException("RefreshMemoryLimit failed")); Assert.False(applied); - Assert.Contains(logs, l => l.Contains("GC heap hard limit refresh to 1 MB failed", StringComparison.Ordinal)); + Assert.Contains(logs, l => l.Contains("GC heap hard limit change (1 MB) by SkuProfile failed", StringComparison.Ordinal)); } [Fact] @@ -91,4 +91,83 @@ public void RealRefresh_ChangesTheProcessHeapLimit() 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)); + } } From 9979e409cb821f4d91cdbd87fdb1c6a0d024ab60 Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Mon, 31 Aug 2026 19:58:34 +0800 Subject: [PATCH 09/17] fix(powershell): reset async local leaks Add a shared PipelineExecutionContext helper that captures a clean execution-context baseline during worker initialization and restores it during per-invocation cleanup. This prevents AsyncLocal values from leaking between invocations on ReuseThread workers while preserving runspace session state, and adds focused tests covering worker behavior, thread-reuse leak reproduction, and reset strategy validation/benchmarking. --- .../PipelineExecutionContext.cs | 54 ++++++ Services/PowerShellHost/PowerShellWorker.cs | 39 +++++ tests/Craft.Tests/ExecutionContextReset.cs | 67 +++++++ .../PowerShellWorkerContextResetTests.cs | 45 +++++ tests/Craft.Tests/ThreadReuseContextTests.cs | 163 ++++++++++++++++++ 5 files changed, 368 insertions(+) create mode 100644 Services/PowerShellHost/PipelineExecutionContext.cs create mode 100644 tests/Craft.Tests/ExecutionContextReset.cs create mode 100644 tests/Craft.Tests/PowerShellWorkerContextResetTests.cs create mode 100644 tests/Craft.Tests/ThreadReuseContextTests.cs 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/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/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/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/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; +} From 96550591891e49e2c577b83599e591063da6136f Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Tue, 1 Sep 2026 01:25:00 +0800 Subject: [PATCH 10/17] feat(hosting): add alt sku matrix selection Introduce a second `SkuProfiles` matrix (`SkuProfilesAlt`) that is selected by configurable env-var presence, with fallback to the default matrix when the alt list is empty. Add per-instance `CRAFT_HTTP_POOL_SIZE` and `CRAFT_BG_POOL_SIZE` overrides that apply last and win over profile/baseline values, and align GC heap semantics so profile `GCHeapHardLimitMB=0` disables the cap (null/negative remains no-op). Update example config comments and expand tests for matrix selection, env overrides, and GC zero behavior. --- Services/Configuration/SkuProfile.cs | 17 +- Services/Configuration/WorkerSettings.cs | 17 ++ Services/Hosting/GcHeapLimit.cs | 18 +- Services/Hosting/SkuProfileSelector.cs | 168 +++++++++++++------ appsettings.example.jsonc | 25 ++- tests/Craft.Tests/GcHeapLimitTests.cs | 19 ++- tests/Craft.Tests/SkuProfileSelectorTests.cs | 93 ++++++++++ 7 files changed, 293 insertions(+), 64 deletions(-) diff --git a/Services/Configuration/SkuProfile.cs b/Services/Configuration/SkuProfile.cs index fe243b7..6d2717d 100644 --- a/Services/Configuration/SkuProfile.cs +++ b/Services/Configuration/SkuProfile.cs @@ -34,11 +34,18 @@ public class SkuProfile public int BgPoolSize { get; set; } /// - /// Optional GC heap hard limit, in MB, to apply when this profile matches. Omit or 0 = keep the - /// process baseline (typically the DOTNET_GCHeapHardLimit env var baked into the image for the - /// smallest tier). The env var is consumed by the CLR before any managed code runs, so this is - /// applied after the fact via — raising the limit is - /// always safe; a value the heap has already outgrown is refused and logged. + /// 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 diff --git a/Services/Configuration/WorkerSettings.cs b/Services/Configuration/WorkerSettings.cs index 5062e0e..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. diff --git a/Services/Hosting/GcHeapLimit.cs b/Services/Hosting/GcHeapLimit.cs index 14ae7a0..89ca774 100644 --- a/Services/Hosting/GcHeapLimit.cs +++ b/Services/Hosting/GcHeapLimit.cs @@ -50,10 +50,9 @@ public static bool Apply(SkuProfile? profile, Action log, Action? // 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. Distinct from a profile's 0/null, which means - // "no opinion, keep the baseline". 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 (original behaviour). + // 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 @@ -68,10 +67,15 @@ public static bool Apply(SkuProfile? profile, Action log, Action? } else { - mb = profile?.GCHeapHardLimitMB ?? 0; source = "SkuProfile"; - // Profile 0/null/negative = keep the process baseline, silently (like unused SkuProfiles). - if (mb <= 0) return false; + // 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; diff --git a/Services/Hosting/SkuProfileSelector.cs b/Services/Hosting/SkuProfileSelector.cs index 072060e..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,29 +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. -/// -/// -/// The returned profile may also carry a ; applying that -/// is a process-wide side effect and lives in , not here. +/// 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) { @@ -38,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)) + { + skuMatch = true; + } + else { - 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; + 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; + } + + 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)) + { + log($"[System] HttpPoolSize overridden to {http} by CRAFT_HTTP_POOL_SIZE (was {worker.HttpPoolSize})"); + worker.HttpPoolSize = http; } - catch (Exception ex) + if (TryReadEnvInt(env, "CRAFT_BG_POOL_SIZE", out var bg)) { - // 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] 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/appsettings.example.jsonc b/appsettings.example.jsonc index 3219f20..6982b96 100644 --- a/appsettings.example.jsonc +++ b/appsettings.example.jsonc @@ -155,9 +155,12 @@ // 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. Omit or - // 0 = keep the process baseline. Raising is always safe; a value the - // heap has already outgrown is refused and logged, keeping the baseline. + // 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. @@ -171,6 +174,22 @@ // { "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 diff --git a/tests/Craft.Tests/GcHeapLimitTests.cs b/tests/Craft.Tests/GcHeapLimitTests.cs index 5566ae9..e4f2d53 100644 --- a/tests/Craft.Tests/GcHeapLimitTests.cs +++ b/tests/Craft.Tests/GcHeapLimitTests.cs @@ -25,10 +25,11 @@ public void NoMatchedProfile_IsANoOp() [Theory] [InlineData(null)] - [InlineData(0)] [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(); @@ -38,6 +39,22 @@ public void ProfileWithoutALimit_IsANoOp(int? mb) 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() { 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 + } } From c701fd1cb25c59e11eec207cfb94eb636f24f1e6 Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Tue, 1 Sep 2026 11:00:58 +0800 Subject: [PATCH 11/17] perf(orchestrator): wake pump on enqueue, trim lease renewals, batch queue deletes Four in-process table-IO improvements to the background orchestrator; no durable schema change. - R1 (latency): JobQueuePump now waits on an enqueue-driven wake signal instead of only its Task.Delay poll tick, so a quiet-system orchestration no longer waits up to the pump's backed-off idle interval (<=10s) before its first task is claimed. The poll stays as the backstop. Measured cold time-to-first-work: ~2.5s median / 7s worst-case -> sub-second. - R5 (efficiency): renew a claim's lease only in its last third rather than re-reading every in-flight row every tick. The lease outlives a normal task, so most claims never renew at all. - R6a (efficiency): batch the pump's finished-row deletes into one transaction per partition (new ICraftTableStore.DeleteBatchAsync; default = per-row loop, AzureTableStore override batches), replacing two point deletes per task. - F5 (reliability): the batch-upsert per-entity fallback no longer silently swallows a poison row -- it logs the dropped row, so a task that vanishes at creation is visible rather than surfacing only later as a run that never finalizes. Verified: full suite 675/675 green against Azurite; adds a pump wake-signal test. --- Services/Orchestration/JobQueuePump.cs | 55 +++++++++++++++++++--- Services/Storage/AzureTableStore.cs | 46 ++++++++++++++++++- Services/Storage/ICraftTableStore.cs | 15 ++++++ Services/Storage/JobQueueStore.cs | 60 +++++++++++++++++++++++- tests/Craft.Tests/JobQueuePumpTests.cs | 63 ++++++++++++++++++++++++++ 5 files changed, 230 insertions(+), 9 deletions(-) diff --git a/Services/Orchestration/JobQueuePump.cs b/Services/Orchestration/JobQueuePump.cs index bbfa919..5ac832e 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))); @@ -113,7 +126,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; } } @@ -132,15 +150,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; + + // 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, claim) in finished) + 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); } /// @@ -173,6 +196,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 @@ -180,6 +204,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)", @@ -197,7 +224,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/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..04bd53f 100644 --- a/Services/Storage/JobQueueStore.cs +++ b/Services/Storage/JobQueueStore.cs @@ -50,7 +50,7 @@ namespace Craft.Storage; /// claim path is untouched. The index is maintained by the enqueue/remove paths, and built 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; @@ -178,6 +205,8 @@ public async Task EnqueueAsync(string runName, string taskId, int priority, Date }, 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. @@ -212,6 +241,8 @@ public async Task EnqueueBatchAsync(string runName, IReadOnlyList<(string 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 +356,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. @@ -421,6 +475,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; } 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; From a4a8568f45ff551f8927f4eddb936bc9555f7fa7 Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Tue, 1 Sep 2026 11:12:24 +0800 Subject: [PATCH 12/17] refactor(orchestrator): remove dead CompleteTaskAsync primitive CompleteTaskAsync (atomic mark-terminal + counter-decrement in one conditional transaction) had no production callers: the live fan-out path decrements via the batched status writer + DecrementRemainingAsync, a deliberate throughput choice, with ReconcileRemainingAsync as the lost-decrement backstop. Keeping the unused primitive implied an atomicity guarantee the hot path does not actually use. - Delete CompleteTaskAsync. - Rewrite the counter-section comment to describe the real design: the partition is shared so the CANCEL path (CancelPendingTaskAsync, still live) can ride one atomic transaction, while the fan-out path decrements separately by design. - Drop the three tests that exercised only CompleteTaskAsync; repoint the two that used it incidentally onto DecrementRemainingAsync (the live method). Build + full counter/cancel suite green. --- Services/Storage/OrchestratorTableStore.cs | 56 +++------------ tests/Craft.Tests/RunRemainingCounterTests.cs | 70 +------------------ 2 files changed, 12 insertions(+), 114 deletions(-) diff --git a/Services/Storage/OrchestratorTableStore.cs b/Services/Storage/OrchestratorTableStore.cs index 75b6523..bc2f24f 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); 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)); } From cc7b85e702b93663c7c7edf45c37fb010cccd999 Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Tue, 1 Sep 2026 11:22:33 +0800 Subject: [PATCH 13/17] perf(orchestrator): coalesce small result writes off the fan-out critical path (R2) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Per-task StoreResultAsync was a single-entity upsert awaited while the JobManager slot was held — the un-batched O(N) write that leaves the BG pool ~93% idle under child fan-out (gated by table write throughput, not workers). Small results (those that fit one Azure Table property, <=30k chars) now ride the coalescing status writer, which writes them BEFORE the run's terminal task markers in the same flush. So a result is durable before its task is counted done -> before the counter decrements -> before finalize/post-execution reads it. On a rare result-write failure the writer WITHHOLDS that run's terminal markers too, so a task can never be counted done with its result lost. Large/chunked results keep the directly-awaited StoreResultAsync path unchanged. - OrchestratorStatusWriter: new _pendingResults + TryQueueResult; FlushOnce writes results first and holds failed-result runs' task/run markers; Requeue restores results. - OrchestratorTableStore.WriteResultBatchAsync: batched single-property result rows. - OrchestratorService.BuildTaskWork: small -> TryQueueResult, else await StoreResultAsync. - App:Orchestrator:BatchResultWrites (default true) gates it; false = original per-task write. Verified: full suite 675/675 green (the end-to-end result/finalize/post-exec tests run through the coalesced path by default); adds durability + threshold tests. --- .../Configuration/OrchestratorSettings.cs | 10 +++ Services/Orchestration/OrchestratorService.cs | 9 ++- .../Orchestration/OrchestratorStatusWriter.cs | 74 +++++++++++++++++-- Services/Storage/OrchestratorTableStore.cs | 49 ++++++++++++ Services/Storage/ResultWrite.cs | 10 +++ .../StatusWriterDurabilityTests.cs | 36 +++++++++ 6 files changed, 179 insertions(+), 9 deletions(-) create mode 100644 Services/Storage/ResultWrite.cs 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/Orchestration/OrchestratorService.cs b/Services/Orchestration/OrchestratorService.cs index 9f77b3f..1f97d54 100644 --- a/Services/Orchestration/OrchestratorService.cs +++ b/Services/Orchestration/OrchestratorService.cs @@ -1096,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 { diff --git a/Services/Orchestration/OrchestratorStatusWriter.cs b/Services/Orchestration/OrchestratorStatusWriter.cs index 22e687e..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,6 +42,7 @@ 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(); @@ -53,6 +60,7 @@ public OrchestratorStatusWriter(OrchestratorTableStore store, ILogger + /// 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 /// so terminal task states + run state are durable before post-execution reads results. public async Task FlushAsync(CancellationToken ct = default) @@ -208,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(); @@ -221,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 @@ -233,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 @@ -242,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 @@ -278,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; diff --git a/Services/Storage/OrchestratorTableStore.cs b/Services/Storage/OrchestratorTableStore.cs index bc2f24f..b096f41 100644 --- a/Services/Storage/OrchestratorTableStore.cs +++ b/Services/Storage/OrchestratorTableStore.cs @@ -490,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/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 ──────────────────────────────────────────────────────────────────────────────────── /// From 677e5ed0bb0477f76c115648e28133ba437991bd Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Tue, 1 Sep 2026 11:40:48 +0800 Subject: [PATCH 14/17] fix(orchestrator): idempotent queue row keys via one-time schema v2 migration (R4) The queue RowKey embedded the enqueue tick ({ticks}-{run}-{task}), so re-dispatching a task (crash recovery, orphan re-drive) wrote a SECOND row instead of updating the first -- the documented cause of a task being claimed and executed 2-6x. Schema v2 keys each row deterministically as {run}|{task} (both components escaped so the key stays legal and the separator unambiguous), and moves the enqueue time to a QueuedUtc property for age/status reporting. Re-enqueuing a task now upserts its one row. Migration: a single forward pass at startup (MigrateSchemaAsync, bumped from the v1 index backfill) re-keys every legacy row -- preserving bucket, priority, claim state and time -- new-key-first then old-key-deleted, so a crash mid-pass re-runs and converges. No dual-read; after the pass only the new scheme is used. The pump now awaits InitializeAsync before it claims (as the enqueue paths already do), so no row is claimed while the migration is only half-applied. Trade: within a priority bucket Azure now returns rows in run|task order, not oldest-first. Priority still orders across buckets, and a fan-out enqueues together, so only sub-priority FIFO fairness is given up -- cheap next to never running a task twice. Tests updated for the new guarantees (idempotent re-enqueue; priority-first; claim-order- agnostic status view) + a migration re-key test. Full suite 676/676 green against Azurite. --- Services/Orchestration/JobQueuePump.cs | 5 + Services/Storage/JobQueueStore.cs | 205 ++++++++++++++---- tests/Craft.Tests/JobQueueAzuriteTests.cs | 20 +- .../Craft.Tests/JobQueueIndexBackfillTests.cs | 38 +++- .../Craft.Tests/JobQueueStatusReaderTests.cs | 19 +- tests/Craft.Tests/JobQueueStoreTests.cs | 39 ++-- tests/Craft.Tests/TableKeyTests.cs | 3 +- 7 files changed, 243 insertions(+), 86 deletions(-) diff --git a/Services/Orchestration/JobQueuePump.cs b/Services/Orchestration/JobQueuePump.cs index 5ac832e..76b3ca5 100644 --- a/Services/Orchestration/JobQueuePump.cs +++ b/Services/Orchestration/JobQueuePump.cs @@ -93,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); diff --git a/Services/Storage/JobQueueStore.cs b/Services/Storage/JobQueueStore.cs index 04bd53f..b96347d 100644 --- a/Services/Storage/JobQueueStore.cs +++ b/Services/Storage/JobQueueStore.cs @@ -47,8 +47,8 @@ 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 sealed class JobQueueStore : IDisposable { @@ -92,12 +92,22 @@ public Task WaitForWorkAsync(TimeSpan pollInterval, CancellationToken ct = 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 @@ -120,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 @@ -190,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) { @@ -201,6 +257,9 @@ 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); @@ -221,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 = { @@ -230,13 +290,14 @@ 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) @@ -487,17 +548,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 @@ -519,7 +576,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, @@ -587,7 +644,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++; } @@ -622,38 +679,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; } @@ -663,17 +749,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); - rows.Add(IndexRow(runName, taskId, row.PartitionKey, row.RowKey)); + // 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)); + + // 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); } } @@ -685,13 +794,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/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/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..53ec0d3 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,15 @@ public async Task EmptyQueueClaimsNothingRatherThanBlocking() // ─── Status/maintenance surface (the table-backed worker-health view) ─── [Fact] - public void ParseQueuedUtcInvertsBuildRowKey() + public void RowKeyEscapingKeepsDistinctPairsDistinctAndKeysLegal() { - var queuedUtc = new DateTime(2026, 8, 12, 3, 4, 5, DateTimeKind.Utc); - var rowKey = JobQueueStore.BuildRowKey(queuedUtc, "run", "task"); + // 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")); - Assert.Equal(queuedUtc, JobQueueStore.ParseQueuedUtc(rowKey)); - Assert.Null(JobQueueStore.ParseQueuedUtc("not-a-tick-prefixed-key")); + // 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] 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)); } From bc43ac8651c12e65b568f55f3671b116c719130a Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Tue, 1 Sep 2026 11:54:54 +0800 Subject: [PATCH 15/17] feat(orchestrator): queue-maintenance bridge + drop redundant HTTP job endpoints Adds a durable-queue clear as a bridge method and removes CRAFT's HTTP job/run endpoints, whose data is already exposed via bridges for downstream apps to wrap. - JobQueueStore.ClearAllAsync: empty the durable queue (queue + index rows, keeping the schema marker), streamed in bounded windows. A maintenance/reset primitive -- drops the backlog, not in-flight work; pair with cancel to actually stop work. - OrchestratorService.ClearQueueAsync delegates to it. - WorkerMetricsBridge.ClearQueue() exposes it to PowerShell, alongside the existing CancelRun/CancelJob/ChangePriority/GetSnapshot/GetSummary/GetJobDetails/GetRunSummaries. - Remove JobEndpoints.cs (GET /API/jobs/{summary,allocation,runs,list}, POST /API/runs/cancel) and its registration: CRAFT is the framework and exposes these as bridge methods; a downstream app wraps whichever it needs into its OWN endpoints. - perf-harness becomes exactly such a downstream wrapper: PerfApi's Invoke-PerfAllocation wraps WorkerMetricsBridge.GetSnapshot() into the allocation shape (+ memory, for the upcoming OOM-resilience harness); run-orch.ps1/run-e2e.ps1 point at /API/PerfAllocation. Full suite green. --- Services/Bridges/WorkerMetricsBridge.cs | 21 ++++ Services/Hosting/Endpoints/JobEndpoints.cs | 117 ------------------ Services/Orchestration/OrchestratorService.cs | 8 ++ Services/Program.cs | 7 +- Services/Storage/JobQueueStore.cs | 50 ++++++++ .../API/Modules/PerfApi/PerfApi.psm1 | 44 +++++++ perf-harness/scripts/run-e2e.ps1 | 2 +- perf-harness/scripts/run-orch.ps1 | 4 +- tests/Craft.Tests/JobQueueStoreTests.cs | 20 +++ 9 files changed, 150 insertions(+), 123 deletions(-) delete mode 100644 Services/Hosting/Endpoints/JobEndpoints.cs 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/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/Orchestration/OrchestratorService.cs b/Services/Orchestration/OrchestratorService.cs index 1f97d54..3741b6b 100644 --- a/Services/Orchestration/OrchestratorService.cs +++ b/Services/Orchestration/OrchestratorService.cs @@ -1906,6 +1906,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/Program.cs b/Services/Program.cs index 132a665..4c627a7 100644 --- a/Services/Program.cs +++ b/Services/Program.cs @@ -415,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/JobQueueStore.cs b/Services/Storage/JobQueueStore.cs index b96347d..d895f17 100644 --- a/Services/Storage/JobQueueStore.cs +++ b/Services/Storage/JobQueueStore.cs @@ -507,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. diff --git a/perf-harness/api-harness/API/Modules/PerfApi/PerfApi.psm1 b/perf-harness/api-harness/API/Modules/PerfApi/PerfApi.psm1 index 1c9c5e1..16e4adf 100644 --- a/perf-harness/api-harness/API/Modules/PerfApi/PerfApi.psm1 +++ b/perf-harness/api-harness/API/Modules/PerfApi/PerfApi.psm1 @@ -90,6 +90,50 @@ 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 + 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 + } + } } +} + # 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/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-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/JobQueueStoreTests.cs b/tests/Craft.Tests/JobQueueStoreTests.cs index 53ec0d3..7ed2264 100644 --- a/tests/Craft.Tests/JobQueueStoreTests.cs +++ b/tests/Craft.Tests/JobQueueStoreTests.cs @@ -224,6 +224,26 @@ public void RowKeyEscapingKeepsDistinctPairsDistinctAndKeysLegal() Assert.DoesNotContain(key, c => c is '/' or '\\' or '#' or '?' || char.IsControl(c)); } + [Fact] + public async Task ClearAllEmptiesTheQueueButLeavesItUsable() + { + 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")); + + // 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] public async Task ListQueuedReportsIdentityAgeAndClaimState() { From 13f9d187a64e9c8cf02af844ad5de290e6f0d4aa Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Tue, 1 Sep 2026 12:29:41 +0800 Subject: [PATCH 16/17] =?UTF-8?q?test(perf):=20OOM-resilience=20harness=20?= =?UTF-8?q?=E2=80=94=20memory-boundedness=20+=20dispatch=20survival=20unde?= =?UTF-8?q?r=20heap=20pressure?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit run-oom.ps1 brings CRAFT up under an optional GC heap hard limit (CRAFT_GC_HEAP_LIMIT_MB), enqueues a massive fan-out of tasks that allocate a large-object (LOH) buffer and hold it, and tracks peak heap, task completions/failures, dispatch progress (stall detection), and process survival. PerfApi gains Invoke-PerfAllocation / Invoke-PerfRuns (downstream wrappers over WorkerMetricsBridge) and a large-object task mode (allocmb/holdms on Push-PerfBg). Findings (perf-harness/oom-analysis.md): - Memory is bounded by the buffer, not the backlog: a 20,000-task fan-out peaks at ~64 MB managed heap (baseline 15 MB) and drains fully — heap does not scale with N. - A GC heap hard limit is back-pressure, not a crash, while the live set fits: the GC collects/throttles to stay under the cap (even 90 MB/task under a 160 MB limit completes). - Catchable task OOMs are caught (task -> Failed) and the dispatch loop keeps dispatching. - A FATAL runtime OOM (GC hard limit exhausted for the runtime's own allocation) is uncatchable: .NET FailFasts, exit 139, and it takes the dispatch loop down with the process. The resilience boundary is restart + durable crash-recovery, which is proven: on restart the interrupted run resumes, 54 stale claims are released, and it reaches a terminal state. Harness/tooling only; no product code change. --- .../API/Modules/PerfApi/PerfApi.psd1 | 2 +- .../API/Modules/PerfApi/PerfApi.psm1 | 32 +++- perf-harness/docker-compose.bg.yml | 8 + perf-harness/oom-analysis.md | 91 +++++++++ perf-harness/scripts/run-oom.ps1 | 174 ++++++++++++++++++ 5 files changed, 304 insertions(+), 3 deletions(-) create mode 100644 perf-harness/oom-analysis.md create mode 100644 perf-harness/scripts/run-oom.ps1 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 16e4adf..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 } }) @@ -101,6 +116,9 @@ function Invoke-PerfAllocation { 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 = @{ @@ -134,6 +152,16 @@ function Invoke-PerfAllocation { } } } +# 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-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 } +} From 011960eb024e21fdf72b8c801803c1f04bc1b1db Mon Sep 17 00:00:00 2001 From: Zacgoose <107489668+Zacgoose@users.noreply.github.com> Date: Thu, 3 Sep 2026 20:19:56 +0800 Subject: [PATCH 17/17] fix(orchestrator): flush status writer before the finalize counter read CheckRunCompletion read the run's remaining-counter to veto finalize before flushing the batched status writer that decrements it. The counter drops only when a terminal write flushes (WriteTaskStatusBatchAsync writes the row, then decrements), so a single fast GET beat the multi-round-trip drain+decrement every time and read the pre-decrement value, deferring a finalize that was actually due. The run then sat until the 60s status timer re-checked, adding ~1 min before PostExecution ran on every completing run - badly amplified on loaded storage where each table op costs seconds. Await _writer.FlushAsync() before the counter read so the terminal rows and their decrement are durable and the read is authoritative. This is the same flush FinalizeRunCoreAsync already relies on, moved ahead of the veto read; it is bounded by the barrier timeout so it cannot hang, and the 3-deferral ReconcileRemainingAsync path stays as the backstop for a genuinely lost decrement. --- Services/Orchestration/OrchestratorService.cs | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/Services/Orchestration/OrchestratorService.cs b/Services/Orchestration/OrchestratorService.cs index 3741b6b..28ce4d9 100644 --- a/Services/Orchestration/OrchestratorService.cs +++ b/Services/Orchestration/OrchestratorService.cs @@ -1361,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