DeleteNode logs a spurious "fail" when a cancellation aborts the handler before any rows are touched

What is failing

MeshWeaver.Mesh.MeshNode's [DeleteNode] handler is emitting fail: level log lines of the form [DeleteNode] unexpected path={path} partial-deleted=0 when a TaskCanceledException interrupts the operation. partial-deleted=0 says the node was never touched, so there is no inconsistency to report — but the handler still logs it at the same severity it would use for a genuine half-completed delete.

Probable cause — high confidence

The catch block in the [DeleteNode] handler does not distinguish OperationCanceledException / TaskCanceledException from a real failure, and does not gate the unexpected … message on partial-deleted > 0. In production the trigger is almost certainly cancellation cascading down from the delete pipeline's own bounds (MeshOperationOptions.Timeout → NestedTimeout → PermissionEstablishmentBudget, per Doc/Architecture/AccessControl) or grain/hub teardown — every sample path is an _Access/*_Access satellite (Public_Access, Anonymous_Access), which is the classic cascade-target when a parent partition is being cleaned up. The node was never modified: the log is wrong to describe the state as "unexpected".

Impact — low; wrong log level is the real cost

7 occurrences over ~4 days (2026-08-20 23:59 → 2026-08-24 21:11 UTC), spread across 7 distinct pods on memex — background trickle, not a burst.
Zero data-consistency impact: every sample reports partial-deleted=0.
The cost is signal quality — on-call sees fail: from MeshWeaver.Mesh.MeshNode and cannot tell this apart from a genuine half-completed delete without reading the counter. A real partial-delete would be indistinguishable from this noise.

Where to look

Component: MeshWeaver.Mesh.MeshNode — the [DeleteNode] message handler (search the source for the literal string "[DeleteNode] unexpected path=" and the partial-deleted counter).
Suggested fix: in the catch block, when partial-deleted == 0 and the exception is an OperationCanceledException (includes TaskCanceledException), suppress the log entirely or downgrade to Debug. Keep the fail: path for partial-deleted > 0 — that is the case that actually names a corrupted state. Related context on the delete-path timeout budgets: Doc/Architecture/AccessControl → The budget is DERIVED (A recursive delete's commit stage can stall for its whole budget — pre-flight fan-out and budget nesting are fixed and deployed; the commit stall is unmeasured on memex-cloud #1198).

Evidence


Fingerprint	`d9d92bca2b00a3f9`
Category	`MeshWeaver.Mesh.MeshNode`
Severity	Error
Exception	`System.Threading.Tasks.TaskCanceledException`
Namespace	`memex`
Pods	`memex-portal-deployment-9c58cfbf-8nm7c`, `memex-portal-deployment-6c54db76fc-zb69f`, `memex-portal-deployment-6c54db76fc-s4j9h`, `memex-portal-deployment-89b8c6b84-5rkdc`, `memex-portal-deployment-54b59b5d89-9t4tx`, `memex-portal-deployment-867dc45877-xqs4p`, `memex-portal-deployment-6f64bf4b56-zd594`
Occurrences	7
First seen	2026-08-20 23:59:35Z
Last seen	2026-08-24 21:11:58Z

Recent log lines

2026-08-20 23:59:35Z memex-portal-deployment-9c58cfbf-8nm7c fail: MeshWeaver.Mesh.MeshNode[0]
      [DeleteNode] unexpected path=RolePlay/Scenery/_Access/Public_Access partial-deleted=0
      System.Threading.Tasks.TaskCanceledException: A task was canceled.
2026-08-21 05:36:22Z memex-portal-deployment-6c54db76fc-zb69f fail: MeshWeaver.Mesh.MeshNode[0]
      [DeleteNode] unexpected path=Video/PosterSkill/_Access/Public_Access partial-deleted=0
      System.Threading.Tasks.TaskCanceledException: A task was canceled.
2026-08-21 05:36:49Z memex-portal-deployment-6c54db76fc-s4j9h fail: MeshWeaver.Mesh.MeshNode[0]
      [DeleteNode] unexpected path=Chess/QueensGambit/_Access/Anonymous_Access partial-deleted=0
      System.Threading.Tasks.TaskCanceledException: A task was canceled.
2026-08-23 16:57:59Z memex-portal-deployment-89b8c6b84-5rkdc fail: MeshWeaver.Mesh.MeshNode[0]
      [DeleteNode] unexpected path=Chess/GambitHunt/_Access/Anonymous_Access partial-deleted=0
      System.Threading.Tasks.TaskCanceledException: A task was canceled.
2026-08-24 07:41:21Z memex-portal-deployment-54b59b5d89-9t4tx fail: MeshWeaver.Mesh.MeshNode[0]
      [DeleteNode] unexpected path=RolePlay/Scenery/_Access/Public_Access partial-deleted=0
      System.Threading.Tasks.TaskCanceledException: A task was canceled.
2026-08-24 14:16:22Z memex-portal-deployment-867dc45877-xqs4p fail: MeshWeaver.Mesh.MeshNode[0]
      [DeleteNode] unexpected path=Chess/README/_Access/Anonymous_Access partial-deleted=0
      System.Threading.Tasks.TaskCanceledException: A task was canceled.
2026-08-24 21:11:58Z memex-portal-deployment-6f64bf4b56-zd594 fail: MeshWeaver.Mesh.MeshNode[0]
      [DeleteNode] unexpected path=Chess/Play/_Access/Anonymous_Access partial-deleted=0
      System.Threading.Tasks.TaskCanceledException: A task was canceled.

_{Opened automatically from Admin/_LogIncident/d9d92bca2b00a3f9. Recurrences are folded into this issue rather than opening new ones.}

Merge pull request #2242 from Systemorph/fix/misreported-faults-log-f…

Fixed by #2242: DeleteNode no longer reports a spurious fail when a cancellation aborts the handler before any rows are touched — an aborted-before-work outcome is not a fault.

Reopened — this fault is happening again.

Still occurring: 6 more since the last update (13 total).

Last seen: 2026-08-25 20:36:24Z
Pods: memex-portal-deployment-9c58cfbf-8nm7c, memex-portal-deployment-6c54db76fc-zb69f, memex-portal-deployment-6c54db76fc-s4j9h, memex-portal-deployment-89b8c6b84-5rkdc, memex-portal-deployment-54b59b5d89-9t4tx, memex-portal-deployment-867dc45877-xqs4p, memex-portal-deployment-6f64bf4b56-zd594, memex-portal-deployment-6f64bf4b56-djkrh, memex-portal-deployment-6f64bf4b56-vvtv6, memex-portal-deployment-8447f69f67-fjp4v, memex-portal-deployment-6c7b9889c7-rkr8g, memex-portal-deployment-86779d495b-2hl8l, memex-portal-deployment-595d8b9995-9tcnj

Recent log lines

2026-08-25 14:56:28Z memex-portal-deployment-6c7b9889c7-rkr8g fail: MeshWeaver.Mesh.MeshNode[0]
      [DeleteNode] unexpected path=Chess/QueensGambit/_Access/Anonymous_Access partial-deleted=0
      System.Threading.Tasks.TaskCanceledException: A task was canceled.
2026-08-25 20:10:27Z memex-portal-deployment-86779d495b-2hl8l fail: MeshWeaver.Mesh.MeshNode[0]
      [DeleteNode] unexpected path=Video/Pipeline/_Access/Public_Access partial-deleted=0
      System.Threading.Tasks.TaskCanceledException: A task was canceled.
2026-08-25 20:36:24Z memex-portal-deployment-595d8b9995-9tcnj fail: MeshWeaver.Mesh.MeshNode[0]
      [DeleteNode] unexpected path=RolePlay/Guide/_Access/Public_Access partial-deleted=0
      System.Threading.Tasks.TaskCanceledException: A task was canceled.

Closing as redundant — the defect is fixed in current origin/main, and the fault has been dormant 23 days.

Dormant. Last seen: 2026-08-25 20:36:24Z (the reopen comment above, matching Admin/_LogIncident/d9d92bca2b00a3f9) — 23 days quiet as of 2026-09-18. Log ingest is live (incidents updating 2026-09-18T05:42Z) and the portals have not rolled in that window, so the trickle stopped under the same running image.

Fixed — with the code as evidence. Core origin/main = 229930bf2f29845323e0f350e73829b1bdb4928e.

git -C <core> grep -n "unexpected path=" origin/main -- src/          → no hits in code
git -C <core> grep -n "\[DeleteNode\] cancelled path=" origin/main -- src/
→ src/MeshWeaver.Mesh.Contract/MeshExtensions.cs:3937

The catch block in the [DeleteNode] handler now classifies before it logs (MeshExtensions.cs:3893):

var isCancelled = !isTimeout && CancellationClassifier.IsCooperativeCancellation(ex);

and the partial-deleted == 0 case is Debug, not fail: (line 3937):

[DeleteNode] cancelled path={Path} — {Cancellation}, partial-deleted=0. The operation was aborted before any node was removed, so nothing is inconsistent.

Both halves this ticket asked for are there, and the gating is exactly the one it prescribed:

isCancelled && partial.Count > 0 keeps a loud Error — [DeleteNode] CANCELLED MID-COMMIT … the subtree is left partially deleted — so a genuinely torn subtree is still the thing that shouts.
A timeout is a separate condition on its own branch with its own Error and a stage=/unanswered= breakdown (A recursive delete's commit stage can stall for its whole budget — pre-flight fan-out and budget nesting are fixed and deployed; the commit stall is unmeasured on memex-cloud #1198), so it is never folded into "cancelled".
The response text says "cancelled", not "Unexpected error", so the activity log a user reads matches the pod log.

The in-code comment names this issue: "🚨 A CANCELLATION IS NOT A FAULT — and with nothing deleted it is not even an inconsistency (#2182) … [DeleteNode] unexpected … partial-deleted=0 said 'unexpected' about a state that is neither unexpected nor a state: the node was never touched."

If the fault fires again the recurrence bot reopens automatically with fresh evidence — that is the designed behaviour, and it is why closing a dormant incident is safe rather than a bet.

Navigation Menu

Repository navigation

DeleteNode logs a spurious "fail" when a cancellation aborts the handler before any rows are touched #2182

Evidence

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

DeleteNode logs a spurious "fail" when a cancellation aborts the handler before any rows are touched #2182

Description

Evidence

Activity

rbuergi commented on Aug 25, 2026

systemorph commented on Sep 17, 2026

rbuergi commented on Sep 18, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions