Node-stream write to owning hub times out, failing GUI text-area saves (write verdict unconfirmed) #2896

Activity

1. rbuergi commented on Sep 1, 2026

   

   rbuergi

   on Sep 1, 2026

   Contributor

   More actions

   A live instance, with the write proven to have landed after the verdict said it had not

   Hit this on memex just now doing a one-field patch of Provider/_Policy. It is the cleanest example of this issue's shape I have seen, because the index settles the question the point read could not.

   1. The write reported failure:

   Error: the patch to Provider/_Policy did not land within the confirmation window —
   a concurrent change may have conflicted with it, or the owner did not confirm the write
   in time. Get the node to see its current content and retry.
   

   2. The follow-up point read has been unavailable ever since, repeatedly:

   Unavailable: Provider/_Policy — this read reached no verdict, so it is UNKNOWN whether
   this node exists. Cause: read of 'Provider/_Policy' reached no verdict within 10s
   

   3. But the write DID land. search path:Provider/_Policy answers instantly and shows:

   path: Provider/_Policy   nodeType: PartitionAccessPolicy
   version: 2               lastModified: 2026-09-01T12:27:54Z
   

   It was version 1 when I read it minutes earlier. So the owning hub accepted and persisted the patch, and then failed to confirm it within the window — and has been unable to answer a point read since.

   Why this matters more than "a slow hub"

   The error message is actively misleading in the dangerous direction. It says the patch "did not land" and tells the caller to retry. A caller that believes it and retries is re-applying a write that already succeeded. That is harmless for an idempotent field set and destructive for anything that accumulates — an append, a counter, a ledger row, a with { X = X + 1 }. The instruction to retry is exactly the wrong advice for the state the system is actually in.

   The verdict is not just missing, it is wrong. This issue's title says "write verdict unconfirmed", but the observed behaviour is stronger: the surface reports a negative verdict for a write that succeeded. Unconfirmed and failed must not share a message.

   What the two reads disagreeing tells you

   search (the index) answered in milliseconds while get (the owning per-node hub) reached no verdict in 10 s, twice, over several minutes. So this is not the node, the partition, or storage — the row is written and indexed. It is the per-node hub for that path being unable to answer, which is the same locus as this issue's original occurrence. The index being ahead of a point read is normally the CQRS staleness direction; here it is inverted, and the index is the only honest reader.

   Suggested change, independent of root-causing the hub

   Whatever wedges the hub, the surface should not tell callers a landed write failed:

   1. On confirmation-window expiry, report UNCONFIRMED — "the write may or may not have landed" — and say do not blindly retry a non-idempotent write. Never "did not land".
   2. Where a cheap read-back exists (as here: the index knows the version), check it before choosing the message. A version bump past the pre-write value settles it.
   3. This is the write-side twin of MeshWeaver#2915's finding that mint-time writes are not read-back-verified before the caller is told the outcome. Same lesson, opposite direction.

   Happy to supply more detail; the node is Provider/_Policy on memex and the window is 12:27:54Z.
2. rbuergi commented on Sep 1, 2026

   

   rbuergi

   on Sep 1, 2026

   Contributor

   More actions

   Re-measured on origin/main (2026-09-01): the subject of this issue no longer has code in core

   $ git grep -l "TextAreaView" origin/main -- 'src/*.cs' 'src/*.razor' 'memex/*.cs' 'test/*.cs'
   (no matches)
   

   The write path this issue also names — src/MeshWeaver.Hosting/MeshNodeStreamCache.cs, UpdateRemote, LateResponseWatchBound — is still core, so the owner-side-silence half is answerable here. Only the view site (MeshWeaver.Blazor.EntityViews/TextAreaView.razor) has left.

   This is the carve-out (#2276 and the view/host moves #2678/#2293/#2169) having moved the
   implementation to MeshWeaver.Plugins since this issue was filed. Nothing here is stale about the
   defect — the measurement, the mechanism and the "where to look" are all still good — but the file
   the fix belongs in is not in this repository, so a core PR cannot carry it and a core sweep will
   keep re-triaging it.

   Suggested disposition: transfer to Systemorph/MeshWeaver.Plugins (the analysis travels with
   it), or close here with a link to a Plugins issue carrying the same body. Please do not close it as
   "fixed" — as far as this measurement goes it is still live, just somewhere else.

   (Filed while sweeping the core backlog to fix what is fixable here; no code change made.)
3. rbuergi commented on Sep 2, 2026

   

   rbuergi

   on Sep 2, 2026

   Contributor

   More actions

   Re-measured against #3009 and #3020 — neither accounts for it, and this issue's premise is falsified by its own log line

   Re-checked on origin/main @ 6e9ec2f9c. The headline first, because it redirects the whole investigation:

   This was NOT a VERDICT_TIMEOUT. The owner DID produce a terminal verdict — a NACK carrying the owner's OWN internal TimeoutException.

   The proof is in the message string

   MeshNodeStreamException renders its structured error verbatim:

   // src/MeshWeaver.Data.Contract/MeshNodeError.cs
   public MeshNodeStreamException(MeshNodeError error)
       : base($"MeshNode {error.Code} at '{error.Path}': {error.Message}")

   The logged line was MeshNode Unknown at '…/StructureTheMessBook': TimeoutException: The operation has timed out. — so Code = Unknown, Message = "TimeoutException: The operation has timed out.".

   The writer's no-verdict path cannot produce that. It stamps a different code and a different sentence:

   // src/MeshWeaver.Mesh.Contract/MeshNodeStreamExtensions.cs  (the VERDICT_TIMEOUT arm)
   RaiseError(new MeshNodeStreamException(new MeshNodeError(
       MeshNodeErrorCode.OwnerUnreachable, _path!,
       $"The owner of '{_path}' returned no verdict for this update within {verdictBoundSeconds:0}s. "
       + "The patch was posted and may still apply, but it is NOT confirmed — …
       + $"Request trail: {trail}")));

   OwnerUnreachable, not Unknown; a long sentence with a request trail, not a bare exception echo. None of that is in the incident log.

   The one site in src/ that mints a MeshNodeError shaped {TypeName}: {message} is the owner's classifier:

   // src/MeshWeaver.Data/DataExtensions.cs — ClassifyPatchException
   _ => (MeshNodeErrorCode.Unknown, ex.GetType().Name),
   …
   return new MeshNodeError(code, path, $"{prefix}: {ex.Message}", ex.StackTrace);

   For a TimeoutException that yields exactly Unknown + "TimeoutException: The operation has timed out.", character for character. So the owner accepted the patch and answered PatchDataResponse { Success = false, … }.

   🚨 TimeoutException here does not mean "the write timed out". It means the owner hit one of its own bounds and said so. Same word, different failing component — and that is what sent this issue at the writer instead of the owner.

   Which owner bound

   The owner does not ack immediately; it watches for its own commit echo, then flushes durably. Both bounds surface as Unknown + TimeoutException:

   // src/MeshWeaver.Data/DataExtensions.cs
   var postSub = stream
       .Where(c => ChangeContainsStampedWrite(...))
       .Take(1)
       .Timeout(TimeSpan.FromSeconds(20))              // (1) commit echo
       .Subscribe(
           committed => {
               var flush = hub.ServiceProvider.GetService<IPostCommitFlush>();
               if (flush is null) { AckOnce(true); return; }
               var flushSub = flush.Flush(committed.Value!)
                   .Take(1)
                   .Timeout(TimeSpan.FromSeconds(10))  // (2) durable flush -> Postgres write
                   .Subscribe(_ => AckOnce(true),
                              ex => AckOnce(false, ClassifyPatchException(ex, hubPath)));
               hub.RegisterForDisposal(flushSub);
           },
           ex => AckOnce(false, ClassifyPatchException(ex, hubPath)));

   In case (2) the write is already committed in memory when the NACK is sent — which is exactly the "reported failure, but the write DID land (version 2)" shape reported in the follow-up comment above.

   Neither merged fix explains it

   PR	Failure mode it closes	Accounts for this?
   #3020 (3b5c9f975) — a write with no base gets a verdict	base read completes empty ⇒ no terminal at all, and no PatchDataRequest posted	No — mutually exclusive. An owner-minted MeshNodeError requires the patch to have been posted.
   #3009 (0766eca46) — the recycle re-arm latch	mid-recycle owner NACKs ShuttingDown; the subscriber's latch gave up in ~1 ms ⇒ the base read never arrives	No. That path fails as a bare TimeoutException("Update aborted: no initial state arrived for '…' within 30s.") — never a MeshNodeStreamException. It also postdates the incident.
   #3018 — oversized grain-routed deliveries	100 MiB+ frames	No. A text-area save is small.

   (Provenance note while checking #3009: only 0766eca46 is on main. The second commit of that PR, 40aa343bc — "a recycled address must reactivate; a Dead activation was pinned in the registry" — is not an ancestor of HEAD, and ActivationTag.cs does not exist in the tree. The registry-pin half of #2986 is still live, and it is the better candidate for the follow-up's "point reads unavailable for minutes".)

   Verdict: KEEP OPEN — and re-scope from the writer to the owner

   Nothing in this issue is stale about the defect; what is stale is where to look. The write path (UpdateRemote, LateResponseWatchBound) behaved correctly and reported what the owner told it. The open question is why the owner's commit echo or its storage flush did not complete inside 20 s / 10 s.

   That is not derivable from the code, so I am not closing it and not guessing.

   The decisive next sample

   1. Loki, pod memex-portal-deployment-9bf79b774-jwrng, 08:59:00–08:59:30Z, channel MeshWeaver.Mesh.MeshNodeStreamHandle. Exactly one of these can be present — ClaimTerminal() admits one:
      • [UpdateRemote] LATE_NACK_TERMINAL … code=Unknown or [UpdateRemote] OWNER_REJECTED … code=Unknown ⇒ confirms the owner answered (this measurement).
      • [UpdateRemote] VERDICT_TIMEOUT … Request trail: … ⇒ refutes it and the original premise stands.
   2. Elapsed time from the save to the log line. ~20 s ⇒ the commit-echo watcher; ~25–30 s ⇒ the 10 s IPostCommitFlush (Postgres) bound; ~31 s ⇒ the writer's own window.
   3. Did the node's Version advance at 08:59:22Z? If yes, the user's edit is on the node despite the error — and the caller was told to retry a write that had landed.
   4. Postgres latency for partition sglauser in that window — a stalled PG connection explains bound (2) directly.

   A second, code-provable defect found while measuring — filed separately

   postSub above subscribes with onNext and onError only. If the filtered stream completes without emitting — which SynchronizationStream.Dispose does via Store.OnCompleted(), and which mirror eviction can do while the hub still lives — then Take(1) ends empty, the Timeout is cancelled, neither arm runs, and no ack is ever posted. That produces this issue's titled shape (owner produces no terminal) via a route that is provable from the code today. It is the owner-side twin of the writer-side defect #3020 just fixed. Filed on its own rather than patched blind here: the naive completion arm is wrong, because Take(1) also completes right after onNext on the successful path while the inner flush is still in flight, so a bare AckOnce(false) there would NACK writes that are about to succeed.

   Conserved

   Doc/Architecture/ReadingAWriteVerdict (new, in #3032) — which verdict shape means which hub, how elapsed time names the bound that fired, the fact that in the flush case the write is already committed when the NACK is sent, and the known completion-arm gap. Cross-linked from Doc/Architecture/MeshNodeStreamCache.
4. rbuergi commented on Sep 2, 2026

   

   rbuergi

   on Sep 2, 2026

   Contributor

   More actions

   This is #3112's defect, and #3115 fixed it — the error code is the proof

   Picked this up off the open queue. It does not need the investigation it asks for: the evidence already in this issue identifies which of the two write-failure shapes it is, using a discriminator that did not exist when it was filed.

   The banner says MeshNode Unknown at 'sglauser/…'.

   That single word settles it. From #3115's analysis of the same failure:

   a MeshNode Unknown …: TimeoutException is minted only by the owner's ClassifyPatchException; the writer's no-verdict path stamps OwnerUnreachable.

   So the owning hub did answer. This is not a hub that went silent, which is what the issue's "Probable cause" reasonably assumed and what its "Where to look" was written to distinguish. It is the owner returning a NACK for a write that had already committed.

   What actually happened to that save

   Per #3115, the owner carries two internal bounds — 20 s for the commit echo, 10 s for the durable flush — and ArmPatchAckWatcher fed durable.Take(1).Timeout(10s) into its fault arm. When the durable flush was slow (a deep write queue, not a broken hub), the bound expired and:

   • the expiry became NACK Unknown + TimeoutException;
   • the writer read that as "the write did NOT apply";
   • meanwhile the merge had committed, the Version had advanced, and every mirror already carried the stamp;
   • and the .Timeout disposed the flush, cancelling a storage write that was merely queued and handing the row to the persistence sampler, which queued it again — so under congestion every slow flush became two writes and one false failure.

   That maps exactly onto what this issue reported and could not resolve:

   the save was reported failed (the patch may even have applied, but is unconfirmed)

   It had applied. The report was wrong, and the honest uncertainty in this issue's title — "write verdict unconfirmed" — was the correct read of a verdict that should never have been negative.

   Fixed

   #3115 — "The flush bound acks the commit instead of NACKing a landed write", merged 2026-09-02 12:36Z. A commit that has landed is acked on the flush bound rather than NACKed, and the flush is no longer disposed by the timeout.

   The occurrence here is 2026-08-31 08:59Z, i.e. before that fix. #3132 (merged 16:13Z) removed a second contributor — a draining replica clearing shared coordinates.

   Disposition

   Closing as fixed by #3115.

   Two things worth keeping from it, because they are not obvious from #3115's own framing:

   1. This was the user-visible face of it. The flush bound acks the commit instead of NACKing a landed write (#3112) #3115 was diagnosed from a CI bake gate declining one assembly. The same defect was, three days earlier, a real person's worksheet edit reported as failed — the Entity Views text area behaved perfectly and told the truth as it was given it. Anyone weighing the severity of a "bake gate" bug should know it also silently lied to an editor about whether their work was saved.
   2. The view's error handling was right and should not be changed. The issue notes TextAreaView logged the fault instead of swallowing it. That is what made this diagnosable at all; the fault was in the verdict it was handed, not in trusting it.

   _{Diagnosed 2026-09-02 by matching this issue's own banner against #3115's classification of the two shapes.}
5. rbuergi

   closed this as completedon Sep 2, 2026
6. rbuergi commented on Oct 11, 2026

   

   rbuergi

   on Oct 11, 2026

   Contributor

   More actions

   (re-posted 2026-10-11; originally by @rbuergi on 2026-09-02)

   A production instance of this, on the READ side, with a clean control arm — and recycle clears it.

   Reported by the maintainer opening a document on memex.systemorph.com (ACA memex-prod), 2026-09-02 ~08:1x UTC.

   Loading document ClientA/EmailDraft-RevisedProposal-2026-08-30:
   No response received in hub cache/v_Gxh1flrEq61vKWo2f-GA within 00:01:00
   for request SubscribeRequest (id=Pd6wi5HeiEWhekWeCWt-9g)
   → target ClientA/EmailDraft-RevisedProposal-2026-08-30.
   The request may have been undeliverable or the target hub was not found.
   

   What makes this worth adding here rather than filing separately: this issue is the WRITE side ("node-stream write to owning hub times out"). This is the same wedge reached by a plain READ — a SubscribeRequest for one node's stream — so the defect is not specific to the write path. Both are "the owning per-node hub stops answering and the caller waits out the full RequestTimeout".

   Evidence, including the control arm

   probe	result
   point read of the affected node	60 s timeout, twice, different request ids — deterministic, not transient
   point read of a sibling (ClientA/EslProposal/RenewalSupportEmail)	instant, full content
   index listing of namespace:ClientA scope:descendants	healthy, 60 nodes, the affected node present at version 53
   after recycle on the affected path	instant, full content, all 53 versions intact

   So: the partition is fine, the index is fine, the node is fine, the store is fine. Exactly one per-node hub was wedged, and disposing the grain cleared it with no data loss.

   The node

   state: Active, version: 53, lastModified 2026-09-01T18:15:28 by rsalzmann — edited the evening before, then unreadable the next morning. Nothing about it is unusual: nodeType: Markdown, a large-ish content body, no NodeType compilation involved.

   Two observations that may narrow it

   1. The refusal semantics are correct and did their job. The read returned Unavailable with "it is UNKNOWN whether this node exists. This is NOT 'not found': do not create, delete or recreate anything on the strength of it." That is the right verdict and it prevented a destructive recovery. Whatever fixes the wedge should not weaken this.

   2. A sibling node created around the same time may be relevant: ClientA/EmailRevisedProposal-2026-08-30 (nodeType: Essentials/Email, version 1, created 2026-09-01T15:47) — i.e. an Essentials/Email node minted from the same draft ~2.5 h before the draft's last edit. If the wedge involves a second hub taking a dependency on the first, that pairing is where to look.

   🚨 recycle is a stopgap and was used as one

   I recycled the hub because the maintainer was blocked on a live document. It is a mitigation, not a fix: it disposes the grain and forces re-initialisation, which restores service and destroys the wedged state that would have diagnosed it. The next occurrence should be captured before recycling — hub queue depth, RunLevel, and whether the grain is in Starting with an open gate (the shape in the #3056 shard-3 log, where mesh/y80u9YBdy0GRRgBLxgGePg reported DISPOSAL DEADLOCK DETECTED … made no teardown progress for 00:00:08 with one child at RunLevel=Starting … openGates=1).

   Prod is running an image that predates today's #3059 (SubscribeAck no longer overtakes the snapshot it acknowledges), so it is worth re-measuring after the next roll — but note #3059 addressed the RE-subscribe ordering, and this is a first subscribe that never got any answer at all, so I would not expect it to be covered.