From 48fbc6a3f753d727106e6eac52e1e0440b425dff Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Roland=20B=C3=BCrgi?= <6334612+rbuergi@users.noreply.github.com> Date: Mon, 21 Sep 2026 21:57:45 +0200 Subject: [PATCH 1/3] =?UTF-8?q?fix(release):=20the=20re-cut's=20failure=20?= =?UTF-8?q?carries=20its=20reason=20=E2=80=94=20a=20bound=20that=20faults,?= =?UTF-8?q?=20not=20one=20that=20substitutes?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Issue #5057. ReleasePostCondition re-cuts the release a consumed request owes, and logs an ERROR when the re-cut does not land. In production that error read, in full: "...AND the release could not be re-cut. The node advertises a build no release names; instances will keep binding 'X' until a release is created for it." — 8 occurrences over 3 minutes across two memex pods and seven node types, naming the consequence, the stale path, the build and the cost, and not once the cause. The cause was discarded one frame below. TryCreateReleaseNode collapsed four unrelated failures into a bare IObservable emitting null: · no IMeshService on the hub → logged nothing · the create was refused → Warning + stack · the create threw while composing → Warning + stack · the 10 s bound expired → logged NOTHING AT ALL The last is the channel the incident names, and it was unobservable by construction: Timeout(bound, Observable.Return(null)) SUBSTITUTES the fallback rather than faulting, so the expiry never reached the Catch that logs. Its only trace in production is a gap between two adjacent lines — Hosting/InstanceRequest logged "Re-cutting..." at 22:16:14Z and "...could not be re-cut" at 22:16:24Z, exactly the bound. And the three channels that did log logged at Warning, which the log watcher does not ingest, so the loudest line in the log is the one that cannot say why. A remedy that reports its own failure without being able to report the failure is the defect it exists to catch, one level up: the output looks like a diagnosis and carries none. · ReleaseCreateOutcome carries the path OR the reason, with Attempted separating a failure from a create nobody asked for. Three states, because a string? holds two. · Timeout(CreateBound) FAULTS, routing the expiry into the same Catch as every other failure, where it becomes a reason naming the bound AND saying the create's fate is UNKNOWN rather than known not to have happened. · Every sentence the post-condition emits — the Error line and the compile _Activity diagnosis — now names the cause of BOTH attempts: the settle's own create (until now a Warning reaching no operator-facing surface) and the re-cut. · Because never returns the empty string: an attempted failure arriving with no reason SAYS so, so this defect cannot reappear wearing terseness. · The batch bake runs no post-condition at all and its stamp keeps the previous release path, so it logs the reason itself. It is unwatched by design, which is exactly why. The bound was NOT widened and must not be: a create that cannot land in ten seconds is not a slow create, and raising it is the band-aid that would have kept this unobservable for longer. Control on each side, measured: with the pre-fix wording restored on top of the fix, TheFailedDiagnosis_NamesBothCauses and ATimeout_NamesTheBoundItWaitedOut both go red — the assertions can fail. Green after restore: 29 tests, 0 failed, .trx written. The other side is TheRestoredDiagnosis_ReadsAsARepair — a re-cut that WORKED must read as a repair with no failure wording, because a fix that made every outcome sound like a failure would satisfy every other assertion here and be worse than the defect. What this does NOT establish: why the create does not land. That was the point — it was unobservable, and inventing a cause from a ten-second gap would be a guess dressed as a finding. The candidates the evidence admits (a boot-time storm — the Store/* requests were consumed a day and a half after they were made; a cross-hub write refused mid-flight; an owner that never answered) are distinguishable only by the next occurrence, which is now diagnosable. Doc: Architecture/ReleaseFailureClasses — same lesson as that page's own, one layer down. Co-Authored-By: Claude Opus 5 (1M context) --- .../NodeTypeBuildState.cs | 114 +++++++++-- .../NodeTypeCompilationHelpers.cs | 22 ++- .../ReleasePostCondition.cs | 116 ++++++++++-- .../Architecture/ReleaseFailureClasses.md | 89 ++++++++- src/MeshWeaver.Hosting/NodeTypeBatchBake.cs | 22 ++- .../ReleaseRecutReportsWhyItFailedTest.cs | 179 ++++++++++++++++++ 6 files changed, 497 insertions(+), 45 deletions(-) create mode 100644 test/MeshWeaver.Compiler.Pipeline.Test/ReleaseRecutReportsWhyItFailedTest.cs diff --git a/src/MeshWeaver.Compiler.Pipeline/NodeTypeBuildState.cs b/src/MeshWeaver.Compiler.Pipeline/NodeTypeBuildState.cs index df4695cf82..a3d5055dae 100644 --- a/src/MeshWeaver.Compiler.Pipeline/NodeTypeBuildState.cs +++ b/src/MeshWeaver.Compiler.Pipeline/NodeTypeBuildState.cs @@ -44,9 +44,17 @@ public static class NodeTypeBuildState /// 2-core flake). Same rule as RunCompile's activity-create guard: the stamp /// follows the create; it is never a path that does not exist. /// - /// Failures are swallowed (emit null): the release MeshNode is - /// observability + history. Compile correctness must not depend on the create - /// succeeding. See Doc/Architecture/Postmortems/NodeTypeReleaseRedesign.md. + /// Compile correctness must not depend on the create succeeding — the release MeshNode is + /// observability + history — so a failure does not fault the compile. See + /// Doc/Architecture/Postmortems/NodeTypeReleaseRedesign.md. + /// + /// 🚨 But a failure is never SILENT, and that is issue #5057. This used to emit a + /// bare null for every one of its four failure channels, so the reason was thrown away at + /// the only place that knew it. carries the reason out + /// instead, because the caller that reports the consequence — ReleasePostCondition, which + /// logs an ERROR and writes the compile _Activity — is not the frame that can see the + /// cause. An Exception's stack still goes to the log here, where it exists; the one-line + /// reason is what travels. /// /// /// The re-cut's own release path when a create failed only because that path is already taken, @@ -54,10 +62,66 @@ public static class NodeTypeBuildState /// only its ingredient — pinning alone /// would leave the catch free to keep returning null and stay green. /// + /// The exception the create failed with. + /// The path this attempt was minting. internal static string? AdoptOnOwnCollision(Exception ex, string releasePath) => ex.IsNodeAlreadyExists() ? releasePath : null; - internal static IObservable TryCreateReleaseNode( + /// + /// How long the observed create may take before the attempt is abandoned. + /// + /// 🚨 Named, so the refusal can SAY what it waited for — and so no test writes the number + /// again. It is a bound on a cross-hub round trip inside a compile settle; raising it is not the + /// remedy for it expiring (a create that cannot land in ten seconds is not a slow create), which + /// is exactly why the expiry now has to be reportable. + /// + internal static readonly TimeSpan CreateBound = TimeSpan.FromSeconds(10); + + /// + /// What ONE Release-create attempt amounts to: the path when the create LANDED, else the reason + /// it did not — and when none was made. + /// + /// 🚨 Three states, never two. "Landed", "tried and failed BECAUSE x" and "never + /// tried" are three different facts about a build, and a string? can hold only two of + /// them — which is how #5057 came to report "the release could not be re-cut" with + /// nothing after it, eight times over three minutes across seven node types, while the channel + /// that produced it (a that expired) wrote no log line at all. + /// + /// The release that now exists, or null. + /// + /// Why no release exists, in one operator-readable line — null both when the create + /// landed and when no create was attempted, which separates. + /// + /// False only for . + internal sealed record ReleaseCreateOutcome(string? ReleasePath, string? Failure, bool Attempted = true) + { + /// No create was made — this compile was not asked to release anything. + internal static readonly ReleaseCreateOutcome NotAttempted = new(null, null, Attempted: false); + + /// The create landed at . + /// The release that now exists. + internal static ReleaseCreateOutcome Landed(string releasePath) => new(releasePath, null); + + /// The create was attempted and did not land, for . + /// Why, in one line an operator can act on. + internal static ReleaseCreateOutcome Failed(string reason) => new(null, reason); + + /// True when a release exists for these bytes. + internal bool Succeeded => ReleasePath is not null; + + /// + /// The reason as a clause to append to a sentence — ": …" when there is one, and a + /// sentence that SAYS the reason is missing when there is not. Never the empty string: a + /// report that trails off is the defect, not the terse form of it. + /// + internal string Because => Failure is { Length: > 0 } reason + ? $": {reason}" + : Attempted + ? " — and the attempt reported no reason, which is itself a defect in this pipeline" + : " — no create was attempted"; + } + + internal static IObservable TryCreateReleaseNode( IMessageHub hub, string nodeTypePath, NodeCompilationResult result, @@ -68,7 +132,9 @@ public static class NodeTypeBuildState try { var meshService = hub.ServiceProvider.GetService(); - if (meshService is null) return Observable.Return(null); + if (meshService is null) + return Observable.Return(ReleaseCreateOutcome.Failed( + "no IMeshService is registered on this hub, so no Release node could be created")); // Markdown release notes the author wrote on the NodeType's // ReleaseNotes field BEFORE clicking Create Release — sourced @@ -201,9 +267,18 @@ public static class NodeTypeBuildState }) : System.Reactive.Disposables.Disposable.Empty, _ => meshService.CreateNode(node).Take(1)) - .Select(_ => (string?)releasePath) - .Timeout(TimeSpan.FromSeconds(10), Observable.Return(null)) - .Catch(ex => + .Select(_ => ReleaseCreateOutcome.Landed(releasePath)) + // 🚨 A BOUND THAT FAULTS, never one that SUBSTITUTES (#5057). This was + // `Timeout(bound, Observable.Return(null))` — the expiry replaced the + // sequence with the same `null` a refusal produced, wrote NO log line of any kind, + // and was therefore the one failure channel with no trace whatsoever. It is also the + // channel the incident names: on `Hosting/InstanceRequest` the "Re-cutting…" line + // was logged at 22:16:14Z and "…AND the release could not be re-cut" at 22:16:24Z — + // exactly this bound, expiring, reported by nothing but the gap between two lines + // that happened to be adjacent. Faulting routes it into the catch below, where it + // becomes a reason like every other failure. + .Timeout(CreateBound) + .Catch(ex => { // 🚨 A COLLISION AT OUR OWN ID IS SUCCESS (#3407). ReleasePostCondition re-cuts // when latestReleasePath still names an earlier build; when the retry lands in @@ -229,23 +304,40 @@ public static class NodeTypeBuildState + "it. The re-cut collided with its own first attempt in the same second; " + "the id encodes the content hash, so this names the same bytes.", adopted); - return Observable.Return(adopted); + return Observable.Return(ReleaseCreateOutcome.Landed(adopted)); } + // The STACK stays here, where it exists; the one-line REASON travels out, to the + // ERROR line and the compile _Activity that report the consequence (#5057). logger?.LogWarning(ex, "CompileWatcher: failed to create Release node at {ReleasePath}", releasePath); - return Observable.Return(null); + return Observable.Return(ReleaseCreateOutcome.Failed(Describe(ex, releasePath))); }); } catch (Exception ex) { logger?.LogWarning(ex, "CompileWatcher: TryCreateReleaseNode threw for {NodeTypePath}", nodeTypePath); - return Observable.Return(null); + return Observable.Return(ReleaseCreateOutcome.Failed( + $"the Release node could not be composed at all: {ex.GetType().Name}: {ex.Message}")); } } + /// + /// One create failure as one operator-readable line. A is named + /// for what it IS — the bound expired and the owning hub never answered — because "TimeoutException: + /// The operation has timed out" tells a reader nothing about which operation or what it waited for. + /// Pure. + /// + /// The exception the create failed with. + /// The path the attempt was minting. + internal static string Describe(Exception ex, string releasePath) => + ex is TimeoutException + ? $"the create at '{releasePath}' did not land within {CreateBound} — the owning hub did " + + "not answer, so whether the node exists is UNKNOWN from here, not no" + : $"the create at '{releasePath}' failed: {ex.GetType().Name}: {ex.Message}"; + /// /// Holds a NodeType MeshNode stream until /// reaches a settled terminal state — anything other than diff --git a/src/MeshWeaver.Compiler.Pipeline/NodeTypeCompilationHelpers.cs b/src/MeshWeaver.Compiler.Pipeline/NodeTypeCompilationHelpers.cs index 72b95a056a..ff75c9d73f 100644 --- a/src/MeshWeaver.Compiler.Pipeline/NodeTypeCompilationHelpers.cs +++ b/src/MeshWeaver.Compiler.Pipeline/NodeTypeCompilationHelpers.cs @@ -4438,17 +4438,23 @@ curr.Content is NodeTypeDefinition def var releasePathObservable = ok ? NodeTypeBuildState.TryCreateReleaseNode( hub, hubPath, outcome.Result!, outcome.PendingNode, resolvedActivityPath, logger) - : Observable.Return(null); + // 🚨 NOT-ATTEMPTED, not failed (#5057). A compile that produced no assembly + // was never asked to release anything, and the post-condition below must not + // be told a create failed when none was made. + : Observable.Return(NodeTypeBuildState.ReleaseCreateOutcome.NotAttempted); releasePathObservable .Take(1) // 🚨 Same totality guard as the compile pipeline above: the terminal // Status write below runs in THIS OnNext — a release-create observable // that completed empty would silently skip it and wedge the NodeType at - // Compiling. TryCreateReleaseNode is bounded (null on timeout/fault) by - // contract; DefaultIfEmpty makes the write unconditional even if that - // contract is ever violated. - .DefaultIfEmpty() + // Compiling. TryCreateReleaseNode is bounded (a reasoned failure on + // timeout/fault) by contract; DefaultIfEmpty makes the write unconditional + // even if that contract is ever violated — and says so rather than producing + // a null indistinguishable from a refusal (#5057). + .DefaultIfEmpty(NodeTypeBuildState.ReleaseCreateOutcome.Failed( + "the release create completed without emitting — the pipeline's " + + "exactly-once contract was violated")) // 🚨 THE POST-CONDITION (#781), checked where the compile SETTLES — the one // moment at which "does a release name the build this node is about to // advertise?" is answerable from facts all in hand. A consumed request whose @@ -4458,12 +4464,12 @@ curr.Content is NodeTypeDefinition def // remedy re-cuts from the bytes this compile just produced (no recompile, // under System) and is loud either way. Also totality-safe: exactly one // emission, never a fault. - .SelectMany(newReleasePath => ok + .SelectMany(firstAttempt => ok ? ReleasePostCondition.Restore( hub, hubPath, outcome.Result!, outcome.PendingNode, - resolvedActivityPath, newReleasePath, logger) + resolvedActivityPath, firstAttempt, logger) : Observable.Return<(string? ReleasePath, string? Diagnosis)>( - (newReleasePath, null))) + (firstAttempt.ReleasePath, null))) // 🚨 #4469 — THE JOIN POINT. A failure on an unresolved NAME asks the // partition's import bookkeeping whether it lost the file that would have // defined it, so the operator who lands on the compile error is told about diff --git a/src/MeshWeaver.Compiler.Pipeline/ReleasePostCondition.cs b/src/MeshWeaver.Compiler.Pipeline/ReleasePostCondition.cs index 67fe4fd065..166b41d7ae 100644 --- a/src/MeshWeaver.Compiler.Pipeline/ReleasePostCondition.cs +++ b/src/MeshWeaver.Compiler.Pipeline/ReleasePostCondition.cs @@ -21,8 +21,9 @@ namespace MeshWeaver.Graph; /// against a build the compile is about to supersede — or the release create can simply not land: /// TryCreateReleaseNode is best-effort by design (compile correctness must not depend on a /// MeshNode create), so a bound that expires, a fault, or a refusal — it runs under the REQUESTER's -/// identity for attribution, and a partition the requester may not create in refuses it — all emit -/// null, logged at Warning and swallowed. ApplyCompileSuccess then stamps +/// identity for attribution, and a partition the requester may not create in refuses it — all yield +/// a carrying no path (and, since #5057, the +/// REASON; they used to yield a bare null). ApplyCompileSuccess then stamps /// releasePath ?? def.LatestReleasePath, i.e. the PREVIOUS build's release, and the trigger /// is already spent (LastReleaseRequestHandledAt == RequestedReleaseAt, stamped on the /// dispatch commit). Nothing revisits it. @@ -47,6 +48,18 @@ namespace MeshWeaver.Graph; /// 🚨 And it stays LOUD either way: the violation is logged as an ERROR naming the type, the /// stale path and the build, and the remedy's outcome is recorded on the compile _Activity /// (the official diagnosis surface). Silence is what made the incident invisible for a day. +/// +/// 🚨 LOUD IS NOT THE SAME AS DIAGNOSABLE — issue #5057. The remedy can fail, and when +/// it did, this reported it in the one shape nobody can act on: an ERROR reading "AND the release +/// could not be re-cut" with no reason, because the reason was discarded one frame below where +/// TryCreateReleaseNode collapsed four distinct failures into a bare null — and the +/// channel the incident actually names, a that expired, +/// wrote no log line at all. Eight occurrences over three minutes across seven node types, and the +/// filed issue's first task was "log why the re-cut fails". A remedy that reports its own +/// failure without being able to report the failure is the same defect class as the state it exists +/// to catch, one level up: the output looks like a diagnosis and carries none. Every sentence this +/// class emits now names the cause of BOTH attempts — the settle's own create (previously a +/// Warning that reached no operator-facing surface) and the re-cut. /// internal static class ReleasePostCondition { @@ -132,23 +145,39 @@ private static bool SameSnapshot( /// observable's OnNext, so a sequence that completed empty or errored would wedge the NodeType /// at Compiling. /// + /// The hub the compile settled on. + /// The NodeType being settled. + /// The successful compile's result. + /// The definition as observed at dispatch. + /// The compile _Activity, or null when its create did not land. + /// + /// What the settle's OWN release create amounted to — including, when it failed, the reason, + /// which until #5057 existed only as a Warning in the log and reached no operator-facing + /// surface at all. It is the first half of the story this method tells. + /// + /// Where the violation and the remedy's outcome are published. internal static IObservable<(string? ReleasePath, string? Diagnosis)> Restore( IMessageHub hub, string nodeTypePath, NodeCompilationResult result, MeshNode pendingNode, string? activityPath, - string? newReleasePath, + NodeTypeBuildState.ReleaseCreateOutcome firstAttempt, ILogger? logger) { var before = pendingNode.ContentAs(hub.JsonSerializerOptions); - if (Violation(before, result, newReleasePath) is not { } violation) - return Observable.Return<(string?, string?)>((newReleasePath, null)); + if (Violation(before, result, firstAttempt.ReleasePath) is not { } violation) + return Observable.Return<(string?, string?)>((firstAttempt.ReleasePath, null)); + // 🚨 WHY THE FIRST CREATE FAILED, on the line an operator reads (#5057). This was the missing + // half of #781's own diagnosis: the settle's create is best-effort and logged its refusal at + // Warning, so the ERROR line that announced the consequence never named the cause, and the + // incident's Loki selector — cut at Error — could not have shown it. + var firstFailure = FirstAttemptClause(firstAttempt); logger?.LogError( - "[ReleasePostCondition] {HubPath}: {Violation}. Re-cutting the release from the bytes " - + "this compile produced (no recompile) — see issue #781.", - nodeTypePath, violation); + "[ReleasePostCondition] {HubPath}: {Violation}.{FirstFailure} Re-cutting the release from " + + "the bytes this compile produced (no recompile) — see issue #781.", + nodeTypePath, violation, firstFailure); // Under SYSTEM, and with the requester cleared so TryCreateReleaseNode does not re-attempt // the very attribution that was refused. RunAsSystem (not Observable.Using over @@ -163,32 +192,77 @@ private static bool SameSnapshot( .Take(1) .Catch((Exception ex) => { + // The stack goes here; the reason travels, so the Error line below can say it. logger?.LogError(ex, "[ReleasePostCondition] {HubPath}: the re-cut faulted", nodeTypePath); - return Observable.Return(null); + return Observable.Return(NodeTypeBuildState.ReleaseCreateOutcome.Failed( + $"the re-cut faulted: {ex.GetType().Name}: {ex.Message}")); }) - .DefaultIfEmpty() - .Select(restored => + // 🚨 An EMPTY completion is its OWN reason, not a shared null (#5057). It cannot happen + // today — TryCreateReleaseNode emits exactly once on every path — and naming it is what + // keeps that fact from becoming an assumption the next operator pays for. + .DefaultIfEmpty(NodeTypeBuildState.ReleaseCreateOutcome.Failed( + "the re-cut produced no answer at all — an inner observable completed without emitting")) + .Select(recut => { - if (restored is not null) + if (recut.ReleasePath is { } restored) { logger?.LogInformation( "[ReleasePostCondition] {HubPath}: release restored at {ReleasePath} — the " + "node no longer advertises a build no release names", nodeTypePath, restored); - return ((string?)restored, - (string?)$"Release post-condition (#781): {violation}. Restored at {restored} " - + "from the bytes this compile produced — no recompile."); + return ((string?)restored, (string?)RestoredDiagnosis(violation, firstFailure, restored)); } + // 🚨 THE LINE THE INCIDENT WAS FILED FROM, and it now SAYS WHY (#5057). It used to + // end at "could not be re-cut" — an Error naming the consequence, the stale path and + // the build, with the one fact needed to fix it discarded one frame below. logger?.LogError( "[ReleasePostCondition] {HubPath}: {Violation} — AND the release could not be " - + "re-cut. The node advertises a build no release names; instances will keep " - + "binding '{Stale}' until a release is created for it.", - nodeTypePath, violation, before!.LatestReleasePath); - return ((string?)null, - (string?)$"Release post-condition (#781) VIOLATED: {violation}. The re-cut did " - + "not land either — this build has no release."); + + "re-cut{Because}. The node advertises a build no release names; instances will " + + "keep binding '{Stale}' until a release is created for it.", + nodeTypePath, violation, recut.Because, before!.LatestReleasePath); + return ((string?)null, (string?)FailedDiagnosis(violation, firstFailure, recut)); }); } + + /// + /// What the settle's OWN release create amounted to, as a clause for the sentences below — so + /// "the create was refused because x", "the create timed out" and "no create was made" are three + /// readable statements rather than one absent release path. Pure. + /// + /// The settle's own create. + internal static string FirstAttemptClause(NodeTypeBuildState.ReleaseCreateOutcome firstAttempt) => + !firstAttempt.Attempted + ? " No create was attempted on this settle." + : firstAttempt.Succeeded + ? $" The settle's own create landed at {firstAttempt.ReleasePath}." + : $" The settle's own create{firstAttempt.Because}."; + + /// + /// The compile _Activity line for a violation the re-cut REPAIRED. Pure. + /// + /// The violation, as worded it. + /// . + /// Where the re-cut landed. + internal static string RestoredDiagnosis(string violation, string firstAttemptClause, string restored) => + $"Release post-condition (#781): {violation}.{firstAttemptClause} Restored at {restored} " + + "from the bytes this compile produced — no recompile."; + + /// + /// The compile _Activity line for a violation the re-cut could NOT repair — the sentence + /// issue #5057 is about. + /// + /// 🚨 It must NAME THE CAUSE of both attempts. The old wording ended at "The re-cut did + /// not land either", which reads as a complete report and is not one: it tells the operator + /// the state (this build has no release) and withholds the only fact that decides what to do + /// about it. Pure, so that property is asserted rather than hoped for. + /// + /// The violation, as worded it. + /// . + /// What the re-cut amounted to. + internal static string FailedDiagnosis( + string violation, string firstAttemptClause, NodeTypeBuildState.ReleaseCreateOutcome recut) => + $"Release post-condition (#781) VIOLATED: {violation}.{firstAttemptClause} The re-cut did not " + + $"land either{recut.Because}. This build has no release."; } diff --git a/src/MeshWeaver.Documentation/Data/Architecture/ReleaseFailureClasses.md b/src/MeshWeaver.Documentation/Data/Architecture/ReleaseFailureClasses.md index dd4c712bb9..255a6c0b82 100644 --- a/src/MeshWeaver.Documentation/Data/Architecture/ReleaseFailureClasses.md +++ b/src/MeshWeaver.Documentation/Data/Architecture/ReleaseFailureClasses.md @@ -5,7 +5,9 @@ Description: >- One log line carried four unrelated defects, so its issue could never be closed: every close against one cause was followed by a recurrence on another. What an incident's identity is actually computed from — including the two-line trap that hid the last cause entirely — and the rule that - puts a failure CLASS in the template instead of a parameter. + puts a failure CLASS in the template instead of a parameter — and the same defect one layer down, + where the REMEDY's four failure channels collapsed into a bare null and the one the incident names + wrote no log line at all. Icon: --- @@ -168,8 +170,91 @@ repository ever sees ([NodeTypeCompilation](../NodeTypeCompilation)). A caller t refusal to a user keeps using `onError`; a caller that LOGS one should take `onRefused`, so the class reaches the template. +## The REMEDY's failure needs a class too (#5057) + +Everything above is about a **refusal** carrying its cause. The same defect sits one layer down, on +the **repair**: `ReleasePostCondition` exists because a consumed release request can leave +`latestReleasePath` naming an earlier build, and its answer is to re-cut the release from the bytes +the compile just produced. That remedy can itself fail — and when it did, it reported the failure in +the one shape nobody can act on. + +### What was measured + +`Admin/_LogIncident/a98877ee6204cad1`, category `MeshWeaver.Graph.CompileWatcher`, **8 occurrences +over 3 minutes across two `memex` pods**, seven node types (`Store/Catalog`, `Store/Purchase`, +`Store/Provision`, `Store/Tier`, `Store/Publishing`, `Store/Subscription`, `Hosting/InstanceRequest`). +The line, in full: + +> `[ReleasePostCondition] Hosting/InstanceRequest: a release request (requestedReleaseAt=…) was +> consumed and this compile succeeded, yet latestReleasePath still names '…' — cut for an EARLIER +> build (lastCompiledVersion 4650 → 4658) — AND the release could not be re-cut. The node advertises +> a build no release names; instances will keep binding '…' until a release is created for it.` + +It names the consequence, the stale path, the build and the cost. It cannot name the cause, and the +cause is the only thing that decides what to do. **The reason was discarded one frame below**: +`NodeTypeBuildState.TryCreateReleaseNode` collapsed four unrelated failures into a bare +`IObservable` emitting `null` — + +| channel | what it logged | +|---|---| +| no `IMeshService` on the hub | nothing | +| the create was **refused** (attribution, validation, a partition the requester may not write) | `Warning` + stack | +| the create **threw** while being composed | `Warning` + stack | +| the 10 s bound **expired** | **nothing at all** | + +The last row is the one the incident names, and it was invisible by construction: +`Timeout(bound, Observable.Return(null))` **substitutes** the fallback sequence instead of +faulting, so the expiry never reached the `Catch` that logs. The only trace it left in production is +a gap between two adjacent lines — `Hosting/InstanceRequest` logged "Re-cutting…" at 22:16:14Z and +"…could not be re-cut" at **22:16:24Z**, exactly the bound. And the three rows that *did* log logged +at `Warning`, which the log watcher does not ingest, so the loudest line in the log is the one that +cannot say why. + +This is the same rule as the top of this page, applied to a value rather than a template: **the words +that discriminate must travel with the failure, not behind it.** A `string?` can hold "landed" and +"did not land"; it cannot hold "did not land BECAUSE x", and it cannot distinguish either from "no +create was attempted". + +### The fix: three states, and a bound that faults + +`NodeTypeBuildState.ReleaseCreateOutcome` carries the path **or** the reason, with `Attempted` +separating a failure from a create nobody asked for. `Timeout(CreateBound)` now faults, routing the +expiry into the same `Catch` as every other failure, where it becomes a reason naming the bound it +waited out **and** that the create's fate is *unknown* rather than known not to have happened — the +difference between re-issuing it and going to look. Every sentence the post-condition emits — the +`Error` line and the compile `_Activity` diagnosis — names the cause of **both** attempts: the +settle's own create (previously a `Warning` reaching no operator-facing surface at all) and the +re-cut. `ReleaseCreateOutcome.Because` never returns the empty string: an attempted failure that +arrives with no reason SAYS the reason is missing, so the defect cannot reappear wearing terseness. + +🚨 **The bound was not widened, and must not be.** A create that cannot land in ten seconds is not a +slow create, and raising the number is precisely the band-aid that would have made this unobservable +for longer. `CreateBound` is named so the refusal can quote it and so no test writes the number +again. + +🚨 **The batch bake runs no post-condition at all**, and its stamp keeps the previous release path +when a create fails — the same silently-wrong state with no reporter above it. It now logs the reason +itself, because the bake is unwatched *by design*, which is exactly why the reason has to be in its +log rather than inferred from a release that never appeared. + +### The control + +`ReleaseRecutReportsWhyItFailedTest` drives the pure sentence composition +(`FirstAttemptClause`, `RestoredDiagnosis`, `FailedDiagnosis`, `Describe`) with no hub and no stream. +Measured: against the pre-fix wording restored on top of the fix, `TheFailedDiagnosis_NamesBothCauses` +and `ATimeout_NamesTheBoundItWaitedOut` both go **red** — the assertions can fail. The other side of +the control is `TheRestoredDiagnosis_ReadsAsARepair`: a re-cut that WORKED must read as a repair with +no failure wording in it, because a fix that made every outcome sound like a failure would satisfy +every other assertion here and be worse than the defect. + ## What this does not claim +- **It does not establish WHY the re-cut's create does not land.** That is the point: the reason was + unobservable, the filed issue's own first task was to make it reach the log, and inventing a cause + from a ten-second gap would be a guess dressed as a finding. The candidates the evidence admits — + a boot-time storm (the `Store/*` requests were consumed a day and a half after they were made), a + cross-hub write refused mid-flight, an owner that never answered — are distinguishable only by the + next occurrence, which is now diagnosable. Nothing here should be read as excluding any of them. - **It does not fix any of the four causes.** It makes them arrive separately, each naming itself, so each can be owned, fixed and closed on its own evidence. The base-state one was fixed (#1990); the teardown one belongs to #1540's family; the routing no-verdict and the non-terminating leg keep @@ -196,3 +281,5 @@ reaches the template. - [Reading a Recurrence Reopen](../ReadingARecurrenceReopen) — what a bot reopen asserts, and the two ways it fails - [NodeType Compilation](../NodeTypeCompilation) — the release path these refusals come from +- [A Failure Report Answers Its Own Instruction](../AFailureReportAnswersItsOwnInstruction) — the + general form of the #5057 half: a report that reads complete and withholds the deciding fact diff --git a/src/MeshWeaver.Hosting/NodeTypeBatchBake.cs b/src/MeshWeaver.Hosting/NodeTypeBatchBake.cs index 75df512542..470ae5ca23 100644 --- a/src/MeshWeaver.Hosting/NodeTypeBatchBake.cs +++ b/src/MeshWeaver.Hosting/NodeTypeBatchBake.cs @@ -1140,13 +1140,27 @@ private static IObservable StampAndReport( var releaseObservable = ok ? NodeTypeBuildState.TryCreateReleaseNode( mesh, typePath, result!, typeNode, activityPath: null, logger) - : Observable.Return(null); + : Observable.Return(NodeTypeBuildState.ReleaseCreateOutcome.NotAttempted); return releaseObservable .Take(1) - .DefaultIfEmpty() - .SelectMany(releasePath => WriteStamp( - mesh, typeNode, ok, result, error, releasePath, startedAt, logger)) + .DefaultIfEmpty(NodeTypeBuildState.ReleaseCreateOutcome.Failed( + "the release create completed without emitting")) + .Do(outcome => + { + // 🚨 This path runs NO post-condition check (#5057), so the stamp below silently + // keeps the PREVIOUS release path and nothing else ever mentions it. The bake is + // unwatched by design — which is exactly why the reason has to be in its log rather + // than inferred from a release that did not appear. + if (outcome is { Attempted: true, Succeeded: false }) + logger?.LogWarning( + "[BatchBake] {NodeTypePath}: no release was cut for this build{Because}. The " + + "stamp below keeps the previous release path, so the type will advertise a " + + "build no release names.", + typePath, outcome.Because); + }) + .SelectMany(outcome => WriteStamp( + mesh, typeNode, ok, result, error, outcome.ReleasePath, startedAt, logger)) .Select(_ => { if (ok) diff --git a/test/MeshWeaver.Compiler.Pipeline.Test/ReleaseRecutReportsWhyItFailedTest.cs b/test/MeshWeaver.Compiler.Pipeline.Test/ReleaseRecutReportsWhyItFailedTest.cs new file mode 100644 index 0000000000..5bed9fc76f --- /dev/null +++ b/test/MeshWeaver.Compiler.Pipeline.Test/ReleaseRecutReportsWhyItFailedTest.cs @@ -0,0 +1,179 @@ +using System; +using MeshWeaver.Mesh; +using Xunit; + +namespace MeshWeaver.Graph.Test; + +/// +/// 🚨 Issue #5057 — a remedy that reports its own failure must be able to report the FAILURE. +/// +/// ReleasePostCondition re-cuts the release a consumed request owes, and logs an ERROR +/// when the re-cut does not land. In production that error read, in full: "…AND the release could +/// not be re-cut. The node advertises a build no release names; instances will keep binding 'X' until +/// a release is created for it." — eight occurrences over three minutes across seven node types, +/// naming the consequence, the stale path and the build, and not once the cause. The cause was +/// discarded one frame below, where TryCreateReleaseNode collapsed four distinct failures into +/// a bare null; and the channel the incident actually names wrote nothing at all, because +/// Timeout(bound, Observable.Return<string?>(null)) SUBSTITUTES rather than faults. The +/// evidence is a ten-second gap: on Hosting/InstanceRequest the "Re-cutting…" line was logged +/// at 22:16:14Z and "…could not be re-cut" at 22:16:24Z — exactly +/// , expiring, reported by nothing but the fact that the +/// two lines happened to be adjacent. +/// +/// The control on each side. Every failure channel must carry a reason that reaches the +/// operator-facing sentence (the cases below would have been unwritable against the old shape — there +/// was no reason to assert on); and a create that LANDED must still read as a clean success, with no +/// failure wording anywhere near it. The pure verdict Violation and the collision adoption are +/// pinned by ReleasePostConditionTest and ReleaseRecutAdoptsItsOwnCollisionTest; the +/// end-to-end settle is pinned on a real mesh by ReleasePostConditionAtSettleTest in +/// MeshWeaver.Plugins. +/// +public class ReleaseRecutReportsWhyItFailedTest +{ + private const string ReleasePath = "Hosting/InstanceRequest/Release/20260920221436-CNCf6e7F"; + private const string Violation = + "a release request was consumed and this compile succeeded, yet latestReleasePath still " + + "names an EARLIER build"; + + // ───────────────── the channel the incident names: a bound that expired ───────────────── + + /// + /// 🚨 THE CASE. A timeout is named for what it is — the bound, and that the create's fate is + /// UNKNOWN rather than known-not-to-have-happened, which is the difference between "re-issue it" + /// and "go and look". + /// + [Fact] + public void ATimeout_NamesTheBoundItWaitedOut() + { + var reason = NodeTypeBuildState.Describe(new TimeoutException("timed out"), ReleasePath); + Assert.Contains(NodeTypeBuildState.CreateBound.ToString(), reason); + Assert.Contains(ReleasePath, reason); + Assert.Contains("UNKNOWN", reason); + } + + /// Any other fault names its exception type and message — never a bare class name. + [Fact] + public void ARefusal_NamesTheExceptionAndItsMessage() + { + var reason = NodeTypeBuildState.Describe( + new InvalidOperationException("cross-hub write PARTIALLY refused"), ReleasePath); + Assert.Contains(nameof(InvalidOperationException), reason); + Assert.Contains("cross-hub write PARTIALLY refused", reason); + Assert.Contains(ReleasePath, reason); + } + + // ───────────────── the three states a string? could hold only two of ───────────────── + + /// A landed create: a path, no reason, and it reads as success. + [Fact] + public void ALandedCreate_Succeeds_AndCarriesNoReason() + { + var landed = NodeTypeBuildState.ReleaseCreateOutcome.Landed(ReleasePath); + Assert.True(landed.Succeeded); + Assert.Null(landed.Failure); + Assert.Equal(ReleasePath, landed.ReleasePath); + } + + /// A failed create: no path, and the reason survives into the appendable clause. + [Fact] + public void AFailedCreate_CarriesItsReason() + { + var failed = NodeTypeBuildState.ReleaseCreateOutcome.Failed("the owning hub did not answer"); + Assert.False(failed.Succeeded); + Assert.Contains("the owning hub did not answer", failed.Because); + } + + /// + /// 🚨 NOT-ATTEMPTED is not FAILED. A compile that produced no assembly was never asked to release + /// anything, and a report that calls that a failure sends the reader after a create nobody made. + /// + [Fact] + public void ANotAttemptedCreate_IsDistinguishableFromAFailedOne() + { + var none = NodeTypeBuildState.ReleaseCreateOutcome.NotAttempted; + Assert.False(none.Attempted); + Assert.False(none.Succeeded); + Assert.Null(none.Failure); + Assert.Contains("no create was attempted", none.Because); + Assert.DoesNotContain("no create was attempted", + NodeTypeBuildState.ReleaseCreateOutcome.Failed("refused").Because); + } + + /// + /// 🚨 A REPORT THAT CANNOT FAIL IS NOT A REPORT. An attempted failure that arrived with no reason + /// must SAY the reason is missing, not trail off — otherwise the exact defect #5057 is would + /// reappear as an empty clause and read as terseness. + /// + [Theory] + [InlineData(null)] + [InlineData("")] + public void AnAttemptedFailureWithNoReason_SaysSoRatherThanTrailingOff(string? reason) + { + var mute = new NodeTypeBuildState.ReleaseCreateOutcome(null, reason, Attempted: true); + Assert.NotEqual("", mute.Because); + Assert.Contains("defect", mute.Because); + } + + // ───────────────── the operator-facing sentences ───────────────── + + /// + /// 🚨 THE LINE THE INCIDENT WAS FILED FROM. Both causes reach it: the settle's own create (which + /// used to be a Warning no operator-facing surface carried) and the re-cut. + /// + [Fact] + public void TheFailedDiagnosis_NamesBothCauses() + { + var sentence = ReleasePostCondition.FailedDiagnosis( + Violation, + ReleasePostCondition.FirstAttemptClause( + NodeTypeBuildState.ReleaseCreateOutcome.Failed("the attributed create was refused")), + NodeTypeBuildState.ReleaseCreateOutcome.Failed( + NodeTypeBuildState.Describe(new TimeoutException("nope"), ReleasePath))); + + Assert.Contains(Violation, sentence); + Assert.Contains("the attributed create was refused", sentence); + Assert.Contains(NodeTypeBuildState.CreateBound.ToString(), sentence); + Assert.Contains("This build has no release.", sentence); + } + + /// + /// The OTHER side of the control: a re-cut that WORKED must read as a repair, naming where the + /// release landed, with no "could not" anywhere in it. A fix that made every outcome sound like a + /// failure would pass every assertion above and be worse than the defect. + /// + [Fact] + public void TheRestoredDiagnosis_ReadsAsARepair() + { + var sentence = ReleasePostCondition.RestoredDiagnosis( + Violation, + ReleasePostCondition.FirstAttemptClause( + NodeTypeBuildState.ReleaseCreateOutcome.Failed("the attributed create was refused")), + ReleasePath); + + Assert.Contains($"Restored at {ReleasePath}", sentence); + Assert.Contains("no recompile", sentence); + Assert.DoesNotContain("VIOLATED", sentence); + Assert.DoesNotContain("has no release", sentence); + } + + /// A settle that attempted nothing says exactly that, in both sentences. + [Fact] + public void ANotAttemptedFirstCreate_IsWordedAsSuch() + => Assert.Contains( + "No create was attempted", + ReleasePostCondition.FirstAttemptClause( + NodeTypeBuildState.ReleaseCreateOutcome.NotAttempted)); + + /// + /// And a first create that LANDED is worded as a landing — the clause is total, so a future + /// caller that reaches it with a success cannot produce a sentence claiming a failure. + /// + [Fact] + public void ALandedFirstCreate_IsWordedAsALanding() + { + var clause = ReleasePostCondition.FirstAttemptClause( + NodeTypeBuildState.ReleaseCreateOutcome.Landed(ReleasePath)); + Assert.Contains($"landed at {ReleasePath}", clause); + Assert.DoesNotContain("defect", clause); + } +} From 39a91ec6cf250751fd7991584f83bd7d36b76f4b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Roland=20B=C3=BCrgi?= <6334612+rbuergi@users.noreply.github.com> Date: Mon, 21 Sep 2026 22:10:21 +0200 Subject: [PATCH 2/3] fix(release): pin the bound through the real chain, and key the transcript entry MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Both findings from the automatic review on #5152, answered on their threads first. 1. The controls did not cover the load-bearing change. Reverting `Timeout(CreateBound)` to a SUBSTITUTING `Timeout(CreateBound, other)` left every new test green, because `Describe` was only ever reached through a TimeoutException built by hand. The bounded wait is now a seam — `Bounded(IObservable, string, IScheduler?, ILogger?)`, pure over its source and its clock, the same shape the fleet-watch dead-man's switch uses — driven by a HistoricalScheduler with no mesh, no clock and no sleep. Four cases through the production `.Timeout(...).Catch(...)`: an elapsed create reports the bound; one that lands inside it succeeds; a NodeAlreadyExists refusal is adopted (#3407 through the chain, not only through AdoptOnOwnCollision in isolation); any other refusal fails carrying its reason. Measured: with the substituting bound restored, AnElapsedCreate_ReportsTheBound_ThroughTheRealChain fails on the absent reason. The revert is caught. 2. The _Activity transcript entry was unkeyed, so it rendered its English interpolation to every viewer forever. LogMessage says this in its own words — a transcript is a RENDERED surface, `Message` alone cannot be localized (#3236), a localizable entry carries MessageKey + MessageArgs and resolves at render time off AccessContext.Locale — and the sibling entry two lines above already does it (`activity.compile.releaseCreated`). Pre-existing (it came in with #781), but this diff makes that string longer and richer, which is exactly when the rule applies. `Restore` now returns the entry itself, keyed, carrying its own level: activity.compile.releasePostCondition.{restored,violated} in both catalogs, with the English text kept as the FALLBACK so an old persisted row and a key that later leaves the catalog still render as they do today. The ARGUMENTS stay English on purpose — a node path, a release path, a store version and an exception's own message are not translatable. BothActivityEntries_AreKeyed_WithTheEnglishTextAsFallback pins the keys, the fallbacks, the levels and the exact placeholder names the catalog values spell. Also recorded in the doc page: what the reportable expiry immediately revealed. The bound stops the WAIT, not the CREATE — the request is already on the bus, so the owning hub writes the node whether or not anyone is still listening. Measured on the control instance over Hosting/InstanceRequest/Release/* (200 nodes, a floor — the listing truncated), from each id's own second stamp to the node's creation: median 0.7 s, 8 of 200 (4%) BEYOND the bound, out to 17.8 s (20260920222136-3V8XoerZ, landed 22:21:53Z, minutes after the incident burst). So a refusal reading "could not be re-cut" was, 4% of the time, emitted over a release node that exists. And the retry compounds it: 20260917173651-dU1GWMZG and 20260917173701-dU1GWMZG share a content hash with ids exactly 10 s apart — the bound — and BOTH landed, because a retry one bound later mints a different second and so collides with nothing for AdoptOnOwnCollision to adopt. That root is named, not fixed here: the remedy is for the re-cut to reuse the abandoned attempt's path so the late landing becomes a NodeAlreadyExists the adoption already resolves. It is a behavioural change to release-id minting with a real in-flight race to design against, and widening the bound is not the alternative — a tail reaching 17.8 s would only make the same failure rarer and harder to catch. Verified: 34 release tests, 0 failed. 60 LocalizationTest cases, 0 failed. Doc gates 6, 0 failed. Release -warnaserror, 0 Error(s): MeshWeaver.Compiler.Pipeline, MeshWeaver.Hosting, MeshWeaver.Compiler.Pipeline.Test, MeshWeaver.Messaging.Hub.Test, MeshWeaver.Documentation.Test. Co-Authored-By: Claude Opus 5 (1M context) --- .../NodeTypeBuildState.cs | 87 ++++++++--- .../NodeTypeCompilationHelpers.cs | 9 +- .../ReleasePostCondition.cs | 52 ++++++- .../Architecture/ReleaseFailureClasses.md | 45 ++++++ .../Localization/strings.de.json | 2 + .../Localization/strings.en.json | 2 + .../ReleaseRecutReportsWhyItFailedTest.cs | 146 +++++++++++++++++- 7 files changed, 310 insertions(+), 33 deletions(-) diff --git a/src/MeshWeaver.Compiler.Pipeline/NodeTypeBuildState.cs b/src/MeshWeaver.Compiler.Pipeline/NodeTypeBuildState.cs index a3d5055dae..756f605e1f 100644 --- a/src/MeshWeaver.Compiler.Pipeline/NodeTypeBuildState.cs +++ b/src/MeshWeaver.Compiler.Pipeline/NodeTypeBuildState.cs @@ -1,4 +1,5 @@ using System.Collections.Immutable; +using System.Reactive.Concurrency; using System.Reactive.Linq; using System.Text.Json; using MeshWeaver.Compiler; @@ -258,16 +259,54 @@ internal static IObservable TryCreateReleaseNode( // Bounded — a hung owner must never block the compile's terminal write; // on timeout/fault emit null so the parent never advertises a phantom // Release path (mirrors RunCompile's activity-create guard). - return Observable.Using( - () => !string.IsNullOrEmpty(requestedBy) && accessService is not null - ? accessService.SwitchAccessContext(new AccessContext - { - ObjectId = requestedBy, - Name = requestedBy - }) - : System.Reactive.Disposables.Disposable.Empty, - _ => meshService.CreateNode(node).Take(1)) - .Select(_ => ReleaseCreateOutcome.Landed(releasePath)) + return Bounded( + Observable.Using( + () => !string.IsNullOrEmpty(requestedBy) && accessService is not null + ? accessService.SwitchAccessContext(new AccessContext + { + ObjectId = requestedBy, + Name = requestedBy + }) + : System.Reactive.Disposables.Disposable.Empty, + _ => meshService.CreateNode(node).Take(1)) + .Select(_ => System.Reactive.Unit.Default), + releasePath, scheduler: null, logger); + } + catch (Exception ex) + { + logger?.LogWarning(ex, + "CompileWatcher: TryCreateReleaseNode threw for {NodeTypePath}", nodeTypePath); + return Observable.Return(ReleaseCreateOutcome.Failed( + $"the Release node could not be composed at all: {ex.GetType().Name}: {ex.Message}")); + } + } + + /// + /// The BOUNDED WAIT around one create, and the classification of however it ends — extracted so a + /// test drives the production chain rather than only its ingredients. + /// + /// 🚨 Why this is a seam and not an inline expression (review on #5057). The + /// load-bearing change is that the bound FAULTS instead of substituting, and asserting that + /// through a hand-built handed to proves + /// nothing about the chain: reverting + /// Timeout(CreateBound) to Timeout(CreateBound, Observable.Return(<no reason>)) + /// would leave every such test green. Pure over its source and its + /// — the same shape the fleet-watch dead-man's switch uses — so a + /// HistoricalScheduler drives the expiry with no mesh, no clock and no sleep, and the + /// substituting revert is caught by the outcome carrying no reason. + /// + /// The create, as a single signal that it LANDED. + /// The path being minted — named in every outcome. + /// The clock the bound is measured on; null uses the default. + /// Where an exception's stack is published. + internal static IObservable Bounded( + IObservable create, + string releasePath, + IScheduler? scheduler, + ILogger? logger) => + create + .Take(1) + .Select(_ => ReleaseCreateOutcome.Landed(releasePath)) // 🚨 A BOUND THAT FAULTS, never one that SUBSTITUTES (#5057). This was // `Timeout(bound, Observable.Return(null))` — the expiry replaced the // sequence with the same `null` a refusal produced, wrote NO log line of any kind, @@ -277,8 +316,8 @@ internal static IObservable TryCreateReleaseNode( // exactly this bound, expiring, reported by nothing but the gap between two lines // that happened to be adjacent. Faulting routes it into the catch below, where it // becomes a reason like every other failure. - .Timeout(CreateBound) - .Catch(ex => + .Timeout(CreateBound, scheduler ?? DefaultScheduler.Instance) + .Catch(ex => { // 🚨 A COLLISION AT OUR OWN ID IS SUCCESS (#3407). ReleasePostCondition re-cuts // when latestReleasePath still names an earlier build; when the retry lands in @@ -314,28 +353,30 @@ internal static IObservable TryCreateReleaseNode( releasePath); return Observable.Return(ReleaseCreateOutcome.Failed(Describe(ex, releasePath))); }); - } - catch (Exception ex) - { - logger?.LogWarning(ex, - "CompileWatcher: TryCreateReleaseNode threw for {NodeTypePath}", nodeTypePath); - return Observable.Return(ReleaseCreateOutcome.Failed( - $"the Release node could not be composed at all: {ex.GetType().Name}: {ex.Message}")); - } - } /// /// One create failure as one operator-readable line. A is named /// for what it IS — the bound expired and the owning hub never answered — because "TimeoutException: /// The operation has timed out" tells a reader nothing about which operation or what it waited for. /// Pure. + /// + /// 🚨 And the expiry says the node MAY EXIST, naming where. The bound stops this + /// process WAITING; it does not stop the create, whose message is already on the bus, so the + /// owning hub writes the node whether or not anyone is still listening. Measured on the control + /// instance over Hosting/InstanceRequest/Release/* (200 nodes, a floor — the listing + /// truncated): the interval from the id's own minute-second stamp to the node's creation is a + /// median 0.7 s with 8 of 200 (4%) beyond this bound, out to 17.8 s. So + /// "did not land within the bound" and "was not created" are DIFFERENT facts, and a reader told + /// the first who acts on the second goes looking for bytes that are already published. The path + /// is in the sentence for exactly that reason: it is the one place to look. /// /// The exception the create failed with. /// The path the attempt was minting. internal static string Describe(Exception ex, string releasePath) => ex is TimeoutException - ? $"the create at '{releasePath}' did not land within {CreateBound} — the owning hub did " - + "not answer, so whether the node exists is UNKNOWN from here, not no" + ? $"the create did not land within {CreateBound} — the bound stops this process WAITING, " + + "not the create, so the node may well exist and nothing here advanced the pointer to " + + $"it: LOOK AT '{releasePath}' before concluding the release is missing" : $"the create at '{releasePath}' failed: {ex.GetType().Name}: {ex.Message}"; /// diff --git a/src/MeshWeaver.Compiler.Pipeline/NodeTypeCompilationHelpers.cs b/src/MeshWeaver.Compiler.Pipeline/NodeTypeCompilationHelpers.cs index ff75c9d73f..70d4372c13 100644 --- a/src/MeshWeaver.Compiler.Pipeline/NodeTypeCompilationHelpers.cs +++ b/src/MeshWeaver.Compiler.Pipeline/NodeTypeCompilationHelpers.cs @@ -4468,7 +4468,7 @@ curr.Content is NodeTypeDefinition def ? ReleasePostCondition.Restore( hub, hubPath, outcome.Result!, outcome.PendingNode, resolvedActivityPath, firstAttempt, logger) - : Observable.Return<(string? ReleasePath, string? Diagnosis)>( + : Observable.Return<(string? ReleasePath, LogMessage? Diagnosis)>( (firstAttempt.ReleasePath, null))) // 🚨 #4469 — THE JOIN POINT. A failure on an unresolved NAME asks the // partition's import bookkeeping whether it lost the file that would have @@ -4598,9 +4598,12 @@ curr.Content is NodeTypeDefinition def .WithKey("activity.compile.releaseCreated", ("path", newReleasePath))); // The post-condition's verdict belongs on the OFFICIAL diagnosis surface, not // only in a log sink — a stale release is invisible everywhere else (#781). + // 🚨 KEYED, so a German viewer reads it in German (#3236 / review on #5057). The + // entry arrives carrying its own catalog key, args and level — it used to be + // wrapped in a bare `new LogMessage(string, …)` here, which renders its English + // interpolation to every viewer forever. if (settle.Diagnosis is { } diagnosis) - activityMessages.Add(new LogMessage(diagnosis, - newReleasePath is null ? LogLevel.Error : LogLevel.Warning)); + activityMessages.Add(diagnosis); NodeTypeCompilationActivity.Complete(hub, resolvedActivityPath, ok ? ActivityStatus.Succeeded : ActivityStatus.Failed, activityMessages.ToImmutable(), logger!); diff --git a/src/MeshWeaver.Compiler.Pipeline/ReleasePostCondition.cs b/src/MeshWeaver.Compiler.Pipeline/ReleasePostCondition.cs index 166b41d7ae..075947225d 100644 --- a/src/MeshWeaver.Compiler.Pipeline/ReleasePostCondition.cs +++ b/src/MeshWeaver.Compiler.Pipeline/ReleasePostCondition.cs @@ -156,7 +156,7 @@ private static bool SameSnapshot( /// surface at all. It is the first half of the story this method tells. /// /// Where the violation and the remedy's outcome are published. - internal static IObservable<(string? ReleasePath, string? Diagnosis)> Restore( + internal static IObservable<(string? ReleasePath, LogMessage? Diagnosis)> Restore( IMessageHub hub, string nodeTypePath, NodeCompilationResult result, @@ -167,7 +167,7 @@ private static bool SameSnapshot( { var before = pendingNode.ContentAs(hub.JsonSerializerOptions); if (Violation(before, result, firstAttempt.ReleasePath) is not { } violation) - return Observable.Return<(string?, string?)>((firstAttempt.ReleasePath, null)); + return Observable.Return<(string?, LogMessage?)>((firstAttempt.ReleasePath, null)); // 🚨 WHY THE FIRST CREATE FAILED, on the line an operator reads (#5057). This was the missing // half of #781's own diagnosis: the settle's create is best-effort and logged its refusal at @@ -203,7 +203,7 @@ private static bool SameSnapshot( // keeps that fact from becoming an assumption the next operator pays for. .DefaultIfEmpty(NodeTypeBuildState.ReleaseCreateOutcome.Failed( "the re-cut produced no answer at all — an inner observable completed without emitting")) - .Select(recut => + .Select(recut => { if (recut.ReleasePath is { } restored) { @@ -211,7 +211,7 @@ private static bool SameSnapshot( "[ReleasePostCondition] {HubPath}: release restored at {ReleasePath} — the " + "node no longer advertises a build no release names", nodeTypePath, restored); - return ((string?)restored, (string?)RestoredDiagnosis(violation, firstFailure, restored)); + return ((string?)restored, (LogMessage?)RestoredEntry(violation, firstFailure, restored)); } // 🚨 THE LINE THE INCIDENT WAS FILED FROM, and it now SAYS WHY (#5057). It used to @@ -222,7 +222,7 @@ private static bool SameSnapshot( + "re-cut{Because}. The node advertises a build no release names; instances will " + "keep binding '{Stale}' until a release is created for it.", nodeTypePath, violation, recut.Because, before!.LatestReleasePath); - return ((string?)null, (string?)FailedDiagnosis(violation, firstFailure, recut)); + return ((string?)null, (LogMessage?)ViolatedEntry(violation, firstFailure, recut)); }); } @@ -249,6 +249,48 @@ internal static string RestoredDiagnosis(string violation, string firstAttemptCl $"Release post-condition (#781): {violation}.{firstAttemptClause} Restored at {restored} " + "from the bytes this compile produced — no recompile."; + /// Catalog key for . + internal const string RestoredKey = "activity.compile.releasePostCondition.restored"; + + /// Catalog key for . + internal const string ViolatedKey = "activity.compile.releasePostCondition.violated"; + + /// + /// The repaired verdict as an activity entry a GERMAN viewer can read. + /// + /// 🚨 A transcript entry is keyed or it is English forever (LogMessage, #3236; + /// review on #5057). The entry is written server-side with NO viewer in scope and read later by + /// viewers whose languages differ, so the sentence must be resolved at RENDER time off + /// AccessContext.Locale — the English text stays as the fallback, which is what keeps an + /// old persisted row and a key that later leaves the catalog rendering exactly as they do now. + /// The ARGUMENTS stay English on purpose: a node path, a release path, a store version and an + /// exception's own message are not translatable, and inventing German for an exception message + /// would be worse than leaving it. + /// + /// The violation, as worded it. + /// . + /// Where the re-cut landed. + internal static LogMessage RestoredEntry( + string violation, string firstAttemptClause, string restored) => + new LogMessage(RestoredDiagnosis(violation, firstAttemptClause, restored), LogLevel.Warning) + .WithKey(RestoredKey, + ("violation", violation), ("firstAttempt", firstAttemptClause), ("path", restored)); + + /// + /// The unrepaired verdict as an activity entry a German viewer can read — same rule as + /// , and Error because this build has no release. + /// + /// The violation, as worded it. + /// . + /// What the re-cut amounted to. + internal static LogMessage ViolatedEntry( + string violation, string firstAttemptClause, + NodeTypeBuildState.ReleaseCreateOutcome recut) => + new LogMessage(FailedDiagnosis(violation, firstAttemptClause, recut), LogLevel.Error) + .WithKey(ViolatedKey, + ("violation", violation), ("firstAttempt", firstAttemptClause), + ("reason", recut.Because)); + /// /// The compile _Activity line for a violation the re-cut could NOT repair — the sentence /// issue #5057 is about. diff --git a/src/MeshWeaver.Documentation/Data/Architecture/ReleaseFailureClasses.md b/src/MeshWeaver.Documentation/Data/Architecture/ReleaseFailureClasses.md index 255a6c0b82..f7f9b56fbf 100644 --- a/src/MeshWeaver.Documentation/Data/Architecture/ReleaseFailureClasses.md +++ b/src/MeshWeaver.Documentation/Data/Architecture/ReleaseFailureClasses.md @@ -237,6 +237,51 @@ when a create fails — the same silently-wrong state with no reporter above it. itself, because the bake is unwatched *by design*, which is exactly why the reason has to be in its log rather than inferred from a release that never appeared. +### 🚨 What the reportable expiry immediately revealed: the bound stops the WAIT, not the CREATE + +Once the expiry had a name, one read settled what it means — and it is not what "timed out" reads as. +`Timeout` disposes this process's subscription to the `CreateNode` response. **The request is already +on the bus**, so the owning hub writes the node whether or not anyone is still listening. A release +id is `{yyyyMMddHHmmss}-{8 chars of SHA256(Collection/ContentPath)}`, so the id records when the +attempt STARTED and the node's `createdDate` records when it LANDED — the gap between them is +measurable from the store, with no instrumentation at all. + +Measured on the control instance over `Hosting/InstanceRequest/Release/*`, 200 nodes (**a floor** — +the listing truncated at the limit): + +| | | +|---|---| +| median id-mint → landed | **0.7 s** | +| beyond the 10 s bound | **8 of 200 (4%)** | +| slowest | **17.8 s** (`20260920222136-3V8XoerZ`, landed 2026-09-20T22:21:53Z — minutes after the incident burst) | + +So a refusal reading *"the release could not be re-cut"* was, 4% of the time, emitted over a release +node **that exists**. The pointer was never advanced to it, and the type went on advertising a build +whose release was sitting right there. + +🚨 **And the retry compounds it, because the id encodes the SECOND.** Two nodes in the same sample: + +``` +20260917173651-dU1GWMZG landed 2026-09-17T17:37:06.550Z +20260917173701-dU1GWMZG landed 2026-09-17T17:37:15.169Z +``` + +Identical content hash — so, by the id's own construction, identical bytes — with ids **exactly 10 +seconds apart**: the bound. The first attempt's wait expired, the re-cut minted a *new* id for the +same build, and **both landed**. `AdoptOnOwnCollision` cannot rescue this: it adopts only a create +REFUSED for `NodeAlreadyExists`, which requires the same id, and #3407's reasoning explicitly rests +on the collision happening *in the same second*. A retry one bound later collides with nothing, so a +second node is created and nothing adopts either. + +**The remedy this points at — deliberately not taken here.** The re-cut should reuse the abandoned +attempt's release path rather than mint a fresh one: the same id turns the late landing into a +`NodeAlreadyExists` refusal, which the adoption mechanism already resolves correctly, and the +duplicate stops being minted. That is a behavioural change to release-id minting with a genuine +in-flight race to design against, and it needs a control that drives expiry → retry → adopt. It is +not something to bolt onto a diagnosability fix, and **widening the bound is not the alternative**: +a tail that reaches 17.8 s would only move the same failure further out while making it rarer and +therefore harder to catch. + ### The control `ReleaseRecutReportsWhyItFailedTest` drives the pure sentence composition diff --git a/src/MeshWeaver.Messaging.Hub/Localization/strings.de.json b/src/MeshWeaver.Messaging.Hub/Localization/strings.de.json index ce14045251..0ad1f6b7a4 100644 --- a/src/MeshWeaver.Messaging.Hub/Localization/strings.de.json +++ b/src/MeshWeaver.Messaging.Hub/Localization/strings.de.json @@ -1361,6 +1361,8 @@ "activity.compile.notPublished": "Assembly NICHT VERÖFFENTLICHT — Roslyn hat sie erzeugt, aber der Assembly-Store hat die Bytes nicht behalten, daher wurde kein Release erstellt: {detail}", "activity.compile.aborted": "Kompilierung abgebrochen durch {exceptionType}:\n{detail}", "activity.compile.releaseCreated": "Release erstellt: {path}", + "activity.compile.releasePostCondition.restored": "Release-Nachbedingung (#781): {violation}.{firstAttempt} Bei {path} aus den Bytes dieses Compile-Vorgangs wiederhergestellt \u2014 ohne Neukompilierung.", + "activity.compile.releasePostCondition.violated": "Release-Nachbedingung (#781) VERLETZT: {violation}.{firstAttempt} Auch das erneute Erstellen des Release ist nicht gelandet{reason}. F\u00fcr diesen Build existiert kein Release.", "activity.compile.importRefusedSources": "⚠ {count} Quell-Node(s), die diese Kompilierung benötigt, wurden von einem Import dieser Partition ABGELEHNT; das Mesh enthält sie also NICHT — die unten nicht auflösbaren Namen sind fehlende DATEIEN, keine fehlenden Module: {paths}. Korrigieren Sie die Quelldatei im Repository und importieren Sie erneut.", "activity.dataUpdate.noRoute": "DataChangeRequest konnte nicht gesendet werden (keine Route).", "activity.dataUpdate.streamClosed": "Die Verbindung zu dieser Seite wurde geschlossen; es wurde nichts übermittelt.", diff --git a/src/MeshWeaver.Messaging.Hub/Localization/strings.en.json b/src/MeshWeaver.Messaging.Hub/Localization/strings.en.json index e989b7a8b1..b4ced4a590 100644 --- a/src/MeshWeaver.Messaging.Hub/Localization/strings.en.json +++ b/src/MeshWeaver.Messaging.Hub/Localization/strings.en.json @@ -1361,6 +1361,8 @@ "activity.compile.notPublished": "Assembly NOT PUBLISHED — Roslyn produced it, but the assembly store did not keep the bytes, so no Release was minted: {detail}", "activity.compile.aborted": "Compile aborted by {exceptionType}:\n{detail}", "activity.compile.releaseCreated": "Release created: {path}", + "activity.compile.releasePostCondition.restored": "Release post-condition (#781): {violation}.{firstAttempt} Restored at {path} from the bytes this compile produced \u2014 no recompile.", + "activity.compile.releasePostCondition.violated": "Release post-condition (#781) VIOLATED: {violation}.{firstAttempt} The re-cut did not land either{reason}. This build has no release.", "activity.compile.importRefusedSources": "⚠ {count} source node(s) this compile needs were REFUSED by an import of this partition, so the mesh does NOT hold them — the unresolved name(s) below are missing FILES, not missing modules: {paths}. Fix the source file in the repository and re-import.", "activity.dataUpdate.noRoute": "Failed to post DataChangeRequest (no route).", "activity.dataUpdate.streamClosed": "The connection to this page was closed; nothing was submitted.", diff --git a/test/MeshWeaver.Compiler.Pipeline.Test/ReleaseRecutReportsWhyItFailedTest.cs b/test/MeshWeaver.Compiler.Pipeline.Test/ReleaseRecutReportsWhyItFailedTest.cs index 5bed9fc76f..5d1deaa135 100644 --- a/test/MeshWeaver.Compiler.Pipeline.Test/ReleaseRecutReportsWhyItFailedTest.cs +++ b/test/MeshWeaver.Compiler.Pipeline.Test/ReleaseRecutReportsWhyItFailedTest.cs @@ -1,4 +1,8 @@ using System; +using System.Linq; +using System.Reactive; +using System.Reactive.Concurrency; +using System.Reactive.Subjects; using MeshWeaver.Mesh; using Xunit; @@ -35,20 +39,121 @@ public class ReleaseRecutReportsWhyItFailedTest "a release request was consumed and this compile succeeded, yet latestReleasePath still " + "names an EARLIER build"; + // ───────────── the PRODUCTION CHAIN, driven by a clock (review on #5057) ───────────── + // + // 🚨 The cases below exist because the ones further down do NOT cover the load-bearing change. + // `Timeout(CreateBound)` faulting instead of SUBSTITUTING is the whole fix, and a test that hands + // a hand-built TimeoutException to `Describe` would stay green through a revert to + // `Timeout(CreateBound, Observable.Return())`. These drive + // `Bounded` — the real `.Timeout(…).Catch(…)` chain — on a HistoricalScheduler, so the expiry is + // the scheduler's, not a sleep's, and the substituting revert is caught by the outcome arriving + // with nothing to say. + + /// Runs against the production chain and returns its one outcome. + private static NodeTypeBuildState.ReleaseCreateOutcome? Run( + Action, HistoricalScheduler> drive) + { + var create = new Subject(); + var clock = new HistoricalScheduler(); + NodeTypeBuildState.ReleaseCreateOutcome? seen = null; + using var subscription = NodeTypeBuildState + .Bounded(create, ReleasePath, clock, logger: null) + .Subscribe(outcome => seen = outcome, _ => { }); + drive(create, clock); + return seen; + } + + /// + /// 🚨 THE REVERT DETECTOR. The clock passes the bound with no answer from the create, and the + /// outcome must carry a REASON naming the bound. A substituting fallback emits an outcome with no + /// reason at all — `Because` then reports that the attempt said nothing — so this assertion is + /// what a revert to Timeout(bound, other) cannot satisfy. + /// + [Fact] + public void AnElapsedCreate_ReportsTheBound_ThroughTheRealChain() + { + var outcome = Run((_, clock) => clock.AdvanceBy(NodeTypeBuildState.CreateBound.Add(TimeSpan.FromTicks(1)))); + + Assert.NotNull(outcome); + Assert.False(outcome!.Succeeded); + Assert.True(outcome.Attempted); + Assert.NotNull(outcome.Failure); + Assert.Contains(NodeTypeBuildState.CreateBound.ToString(), outcome.Failure!); + Assert.DoesNotContain("reported no reason", outcome.Because); + } + + /// + /// The other side: a create that answers INSIDE the bound is a plain success, with no failure + /// wording and the path intact. A fix that reported every outcome as a failure would satisfy the + /// case above and be worse than the defect. + /// + [Fact] + public void ACreateThatLandsInsideTheBound_Succeeds_ThroughTheRealChain() + { + var outcome = Run((create, clock) => + { + clock.AdvanceBy(NodeTypeBuildState.CreateBound - TimeSpan.FromSeconds(1)); + create.OnNext(Unit.Default); + }); + + Assert.NotNull(outcome); + Assert.True(outcome!.Succeeded); + Assert.Equal(ReleasePath, outcome.ReleasePath); + Assert.Null(outcome.Failure); + } + + /// + /// 🚨 #3407 through the chain rather than only through AdoptOnOwnCollision in isolation: a + /// create refused because the path is already taken has SUCCEEDED, so the pointer advances. + /// + [Fact] + public void AnAlreadyExistsRefusal_IsAdopted_ThroughTheRealChain() + { + var outcome = Run((create, _) => create.OnError( + CreateNodeResponse.Fail("taken", NodeCreationRejectionReason.NodeAlreadyExists) + .ToException(ReleasePath))); + + Assert.NotNull(outcome); + Assert.True(outcome!.Succeeded); + Assert.Equal(ReleasePath, outcome.ReleasePath); + } + + /// + /// Any other refusal leaves the pointer un-advanced AND says why — advertising a release path + /// whose node does not exist would be worse than the bug being fixed. + /// + [Fact] + public void AnyOtherRefusal_FailsWithItsReason_ThroughTheRealChain() + { + var outcome = Run((create, _) => create.OnError( + new InvalidOperationException("cross-hub write PARTIALLY refused"))); + + Assert.NotNull(outcome); + Assert.False(outcome!.Succeeded); + Assert.Contains("cross-hub write PARTIALLY refused", outcome.Failure!); + } + // ───────────────── the channel the incident names: a bound that expired ───────────────── /// /// 🚨 THE CASE. A timeout is named for what it is — the bound, and that the create's fate is /// UNKNOWN rather than known-not-to-have-happened, which is the difference between "re-issue it" /// and "go and look". + /// + /// Measured on the control instance over Hosting/InstanceRequest/Release/* (200 + /// nodes, a floor — the listing truncated): 8 of 200 creates landed AFTER this bound, out to + /// 17.8 s, against a median of 0.7 s. The bound stops the WAIT, not the create, so the sentence + /// must send the reader to the path rather than let them conclude the release is missing. /// [Fact] - public void ATimeout_NamesTheBoundItWaitedOut() + public void ATimeout_NamesTheBoundAndSendsTheReaderToThePath() { var reason = NodeTypeBuildState.Describe(new TimeoutException("timed out"), ReleasePath); Assert.Contains(NodeTypeBuildState.CreateBound.ToString(), reason); Assert.Contains(ReleasePath, reason); - Assert.Contains("UNKNOWN", reason); + // Not "was not created": the create outlives the wait, so the node may well exist. + Assert.Contains("may well exist", reason); + Assert.DoesNotContain("was not created", reason); } /// Any other fault names its exception type and message — never a bare class name. @@ -156,6 +261,43 @@ public void TheRestoredDiagnosis_ReadsAsARepair() Assert.DoesNotContain("has no release", sentence); } + // ───────────────── the transcript entry is KEYED, or it is English forever ───────────────── + + /// + /// 🚨 Both activity entries carry a catalog key and their arguments, so a German viewer reads a + /// German sentence (LogMessage, #3236). The English text stays as the FALLBACK — that is + /// what keeps an old persisted row, and a key that later leaves the catalog, rendering as they do + /// today. Without this case the keying could be dropped and every sentence assertion above would + /// stay green while the transcript silently went English-only again. + /// + [Fact] + public void BothActivityEntries_AreKeyed_WithTheEnglishTextAsFallback() + { + var clause = ReleasePostCondition.FirstAttemptClause( + NodeTypeBuildState.ReleaseCreateOutcome.Failed("refused")); + + var restored = ReleasePostCondition.RestoredEntry(Violation, clause, ReleasePath); + Assert.Equal(ReleasePostCondition.RestoredKey, restored.MessageKey); + Assert.Equal( + ReleasePostCondition.RestoredDiagnosis(Violation, clause, ReleasePath), restored.Message); + Assert.Equal(Microsoft.Extensions.Logging.LogLevel.Warning, restored.LogLevel); + + var recut = NodeTypeBuildState.ReleaseCreateOutcome.Failed("the owning hub did not answer"); + var violated = ReleasePostCondition.ViolatedEntry(Violation, clause, recut); + Assert.Equal(ReleasePostCondition.ViolatedKey, violated.MessageKey); + Assert.Equal( + ReleasePostCondition.FailedDiagnosis(Violation, clause, recut), violated.Message); + // Error, not Warning: this build has no release. + Assert.Equal(Microsoft.Extensions.Logging.LogLevel.Error, violated.LogLevel); + + // 🚨 Every placeholder the catalog entries spell is supplied, or a German render shows the + // literal token. These are the ONLY names the two catalog values use. + Assert.NotNull(restored.MessageArgs); + Assert.Equal(["firstAttempt", "path", "violation"], restored.MessageArgs!.Keys.Order()); + Assert.NotNull(violated.MessageArgs); + Assert.Equal(["firstAttempt", "reason", "violation"], violated.MessageArgs!.Keys.Order()); + } + /// A settle that attempted nothing says exactly that, in both sentences. [Fact] public void ANotAttemptedFirstCreate_IsWordedAsSuch() From c8b0ee5793a34e593fb0ea8bb9060a826e813ed3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Roland=20B=C3=BCrgi?= <6334612+rbuergi@users.noreply.github.com> Date: Mon, 21 Sep 2026 22:14:39 +0200 Subject: [PATCH 3/3] style(release): re-indent the extracted catch, and name the measured create latency beside the bound MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The Bounded extraction left the comment block and the catch lambda one level out. The added comment records what the expiry MEANS, beside the bound it belongs to: it bounds the WAIT, not the CREATE — the request is already on the bus. Measured over Hosting/InstanceRequest/Release/* (200 nodes, a floor), id second-stamp to creation: median 0.7 s, 8 of 200 beyond the bound, out to 17.8 s. No behaviour change. 34 release tests, 0 failed; Release -warnaserror, 0 Error(s). Co-Authored-By: Claude Opus 5 (1M context) --- .../NodeTypeBuildState.cs | 100 ++++++++++-------- 1 file changed, 54 insertions(+), 46 deletions(-) diff --git a/src/MeshWeaver.Compiler.Pipeline/NodeTypeBuildState.cs b/src/MeshWeaver.Compiler.Pipeline/NodeTypeBuildState.cs index 756f605e1f..e8f735a435 100644 --- a/src/MeshWeaver.Compiler.Pipeline/NodeTypeBuildState.cs +++ b/src/MeshWeaver.Compiler.Pipeline/NodeTypeBuildState.cs @@ -255,10 +255,11 @@ internal static IObservable TryCreateReleaseNode( var requestedBy = pendingNode.ContentAs(hub.JsonSerializerOptions)?.RequestedReleaseBy; var accessService = hub.ServiceProvider.GetService(); - // OBSERVED create: emit the path only once the create response lands. - // Bounded — a hung owner must never block the compile's terminal write; - // on timeout/fault emit null so the parent never advertises a phantom - // Release path (mirrors RunCompile's activity-create guard). + // OBSERVED create: report the path only once the create response lands. + // Bounded — a hung owner must never block the compile's terminal write; on + // timeout/fault the outcome carries no path (and, since #5057, the REASON), so + // the parent never advertises a phantom Release path (mirrors RunCompile's + // activity-create guard). return Bounded( Observable.Using( () => !string.IsNullOrEmpty(requestedBy) && accessService is not null @@ -307,52 +308,59 @@ internal static IObservable Bounded( create .Take(1) .Select(_ => ReleaseCreateOutcome.Landed(releasePath)) - // 🚨 A BOUND THAT FAULTS, never one that SUBSTITUTES (#5057). This was - // `Timeout(bound, Observable.Return(null))` — the expiry replaced the - // sequence with the same `null` a refusal produced, wrote NO log line of any kind, - // and was therefore the one failure channel with no trace whatsoever. It is also the - // channel the incident names: on `Hosting/InstanceRequest` the "Re-cutting…" line - // was logged at 22:16:14Z and "…AND the release could not be re-cut" at 22:16:24Z — - // exactly this bound, expiring, reported by nothing but the gap between two lines - // that happened to be adjacent. Faulting routes it into the catch below, where it - // becomes a reason like every other failure. + // 🚨 A BOUND THAT FAULTS, never one that SUBSTITUTES (#5057). This was + // `Timeout(bound, Observable.Return(null))` — the expiry replaced the sequence + // with the same `null` a refusal produced, wrote NO log line of any kind, and was + // therefore the one failure channel with no trace whatsoever. It is also the channel the + // incident names: on `Hosting/InstanceRequest` the "Re-cutting…" line was logged at + // 22:16:14Z and "…AND the release could not be re-cut" at 22:16:24Z — exactly this + // bound, expiring, reported by nothing but the gap between two lines that happened to be + // adjacent. Faulting routes it into the catch below, where it becomes a reason like + // every other failure. + // + // 🚨 And it bounds the WAIT, not the CREATE: the request is already on the bus, so the + // owning hub writes the node whether or not anyone is still listening. Measured over + // `Hosting/InstanceRequest/Release/*` on the control instance (200 nodes, a floor), from + // each id's own second stamp to the node's creation: median 0.7 s, 8 of 200 BEYOND this + // bound, out to 17.8 s. Which is why `Describe` sends the reader to the path instead of + // saying the release was not created. .Timeout(CreateBound, scheduler ?? DefaultScheduler.Instance) .Catch(ex => + { + // 🚨 A COLLISION AT OUR OWN ID IS SUCCESS (#3407). ReleasePostCondition re-cuts + // when latestReleasePath still names an earlier build; when the retry lands in + // the SAME SECOND as the first attempt, both mint the same id and the second + // create throws. Swallowing that into null left the pointer un-advanced: the + // bytes were published, the Release node existed, and the type went on + // advertising a build no release named — every instance kept executing the + // previous assembly behind a $Banner whose own text says a recycle will not + // clear it. Measured on memex.localhost 2026-09-06 (Edu/CourseInvite build 767); + // only a pod restart cleared it, and nothing in the pipeline did. + // + // Adopting is naming the same bytes, not guessing. The id is + // {yyyyMMddHHmmss}-{8 chars of SHA256(Collection/ContentPath)} — the hash comes + // from the DURABLE content reference, so an equal id means equal second AND + // equal content. A collision can therefore only be this same code's own earlier + // attempt for this same compile. (Healthy re-cuts show in the release list as + // PAIRS a second or two apart sharing the suffix; the failing one was the single + // unpaired id.) + if (AdoptOnOwnCollision(ex, releasePath) is { } adopted) { - // 🚨 A COLLISION AT OUR OWN ID IS SUCCESS (#3407). ReleasePostCondition re-cuts - // when latestReleasePath still names an earlier build; when the retry lands in - // the SAME SECOND as the first attempt, both mint the same id and the second - // create throws. Swallowing that into null left the pointer un-advanced: the - // bytes were published, the Release node existed, and the type went on - // advertising a build no release named — every instance kept executing the - // previous assembly behind a $Banner whose own text says a recycle will not - // clear it. Measured on memex.localhost 2026-09-06 (Edu/CourseInvite build 767); - // only a pod restart cleared it, and nothing in the pipeline did. - // - // Adopting is naming the same bytes, not guessing. The id is - // {yyyyMMddHHmmss}-{8 chars of SHA256(Collection/ContentPath)} — the hash comes - // from the DURABLE content reference, so an equal id means equal second AND - // equal content. A collision can therefore only be this same code's own earlier - // attempt for this same compile. (Healthy re-cuts show in the release list as - // PAIRS a second or two apart sharing the suffix; the failing one was the single - // unpaired id.) - if (AdoptOnOwnCollision(ex, releasePath) is { } adopted) - { - logger?.LogInformation( - "CompileWatcher: Release node at {ReleasePath} already exists — adopting " - + "it. The re-cut collided with its own first attempt in the same second; " - + "the id encodes the content hash, so this names the same bytes.", - adopted); - return Observable.Return(ReleaseCreateOutcome.Landed(adopted)); - } + logger?.LogInformation( + "CompileWatcher: Release node at {ReleasePath} already exists — adopting " + + "it. The re-cut collided with its own first attempt in the same second; " + + "the id encodes the content hash, so this names the same bytes.", + adopted); + return Observable.Return(ReleaseCreateOutcome.Landed(adopted)); + } - // The STACK stays here, where it exists; the one-line REASON travels out, to the - // ERROR line and the compile _Activity that report the consequence (#5057). - logger?.LogWarning(ex, - "CompileWatcher: failed to create Release node at {ReleasePath}", - releasePath); - return Observable.Return(ReleaseCreateOutcome.Failed(Describe(ex, releasePath))); - }); + // The STACK stays here, where it exists; the one-line REASON travels out, to the + // ERROR line and the compile _Activity that report the consequence (#5057). + logger?.LogWarning(ex, + "CompileWatcher: failed to create Release node at {ReleasePath}", + releasePath); + return Observable.Return(ReleaseCreateOutcome.Failed(Describe(ex, releasePath))); + }); /// /// One create failure as one operator-readable line. A is named