Skip to content

fix(DicomReceiver): suppress late dcmrecv events after finalize#28

Merged
MichaelLeeHobbs merged 1 commit into
MichaelLeeHobbs:mainfrom
gt50:fix/suppress-late-dcmrecv-events
Jun 2, 2026
Merged

fix(DicomReceiver): suppress late dcmrecv events after finalize#28
MichaelLeeHobbs merged 1 commit into
MichaelLeeHobbs:mainfrom
gt50:fix/suppress-late-dcmrecv-events

Conversation

@gt50

@gt50 gt50 commented Jun 1, 2026

Copy link
Copy Markdown
Contributor

Summary

Follow-up to #27 (0.16.0). An end-to-end soak under extreme concurrency
(50 parallel single-file associations) surfaced a ~1/1500 residual: an
association left un-finalized from the consumer's view. Realistic batched
traffic was 100% clean; this only appears under pathological churn.

Root cause

dcmrecv's stdout can deliver a stray ASSOCIATION_RECEIVED (or FILE_RECEIVED)
for an association after the worker has finalized it and gone idle. The pool
bubbled the late event, so a consumer registered an association that never got
a matching ASSOCIATION_FINALIZED — stranding it until a consumer-side reaper
fired. Distinct from the #27 double-assignment race (that was the primary
cause; this is the last residual).

Fix

Suppress both events when worker.finalized is set. The flag stays true
between finalize and the next beginAssociation (which resets it before a
genuinely new association's events arrive), so only strays are filtered. The
#25 late-FILE_RECEIVED-during-finalizing path is unaffected — finalized is
set inside finalizeAssociation, after pending pipe chunks are processed.

Validation

End-to-end (50-parallel single-file, 3000 associations, 300s consumer reaper):

0.16.0 this PR
final stranded associations 1 (held 90s) 0
start = summary = complete gap of 5 exact (1636 each)
FILE_RECEIVED with no active association errors 4 0

Tests

New unit test (finalize a worker, assert a late ASSOCIATION_RECEIVED doesn't
bubble). Full suite: 2020/2020.

Suggested release

Patch — 0.16.1.

@MichaelLeeHobbs

Copy link
Copy Markdown
Owner

Concern: suppressing FILE_RECEIVED can mask a premature-finalize bug and lose an image

Before this lands, I want to push back on the FILE_RECEIVED half of the guard. The ASSOCIATION_RECEIVED suppression is fine (it carries no payload). FILE_RECEIVED is different — it represents an object dcmrecv has already written to disk, so silently dropping it is potential data loss.

The invariant this should be measured against

ASSOCIATION_FINALIZED is, by design, the terminal event: every FILE_RECEIVED for an association must be emitted before it. That's the entire reason FINALIZED exists — we couldn't rely on Association Release being the last thing that matters, because a file may still be in-flight when Release arrives. So the pool drains pending file + instance work and only then emits FINALIZED. If a FILE_RECEIVED ever shows up after finalization, the bug is that finalization happened too early — not that the event needs hiding.

What the guard actually gates on

worker.finalized flips to true in beginFinalizeOnce() at the start of finalizeAssociation (line 1306) — inside the #25 drain window, before ASSOCIATION_FINALIZED is emitted. So the new if (worker.finalized) return in wireFileReceived suppresses any FILE_RECEIVED from finalize-start onward. A suppressed FILE_RECEIVED is therefore one that arrived after the association began finalizing — exactly the out-of-order case.

What happens to a suppressed file (data-loss path)

dcmrecv writes received objects into the worker's shared temp dir. The normal path (handleFileReceivedmoveAndEmitFile) moves the file into the association dir and emits FILE_STORED/INSTANCE_RECEIVED. The guard returns before any of that, so a suppressed file is never moved, never emitted, never counted, and is deleted with the worker temp dir on shutdown. If that file was genuine, it's gone — silently. (The FILE_RECEIVED branch also ships untested; the new unit test only covers ASSOCIATION_RECEIVED.)

What we need to confirm first

There are only two explanations for a post-finalize FILE_RECEIVED, and they demand opposite fixes:

  • (a) Genuine out-of-order / premature finalize — a real same-association file's event landed after finalize started. Candidate mechanisms worth checking: stdout-vs-stderr cross-stream delivery (the parser is fed line events from both streams, and Node gives no ordering guarantee between the two pipes), or the single-tick setImmediate deferral being insufficient under load. → FINALIZED fired before the work was done; suppressing the event loses the image and hides the bug. Correct fix is to make finalize genuinely wait (fix the drain/ordering) so FINALIZED is truly last.
  • (b) Spurious/duplicate dcmrecv log line carrying no new file. → harmless to drop, but this must be demonstrated, not assumed.

The PR suppresses by timing flag without establishing which case is occurring. We should confirm empirically: instrument every suppressed FILE_RECEIVED to record the file path, whether that path is already in worker.files (duplicate vs new), and which stream the source line came from. If any suppressed FILE_RECEIVED is a new path, it's a lost image — block and fix finalize timing instead.

Suggested split

  • Keep the ASSOCIATION_RECEIVED suppression (payload-free, and it's what the soak actually validated).
  • Do not silently drop FILE_RECEIVED. At minimum make it observable (emit an error/diagnostic) and non-destructive (relocate the file). Better: only drop a confirmed duplicate (path already handled); treat a new path as either a real late file to deliver or as evidence of a finalize-timing bug.

After the worker double-assignment race fix (0.16.0), an extreme-concurrency
soak (50-parallel single-file associations) left a ~1/1500 residual: an
association un-finalized from the consumer's view. Realistic batched traffic
was fully clean.

Root cause: dcmrecv's stdout can deliver a stray ASSOCIATION_RECEIVED for an
association after the worker already finalized it and went idle. The pool
bubbled it, so a consumer registered an association that never received a
matching ASSOCIATION_FINALIZED — stranding it until a consumer-side reaper
fired.

Fix: suppress ASSOCIATION_RECEIVED when worker.finalized is set. The flag stays
true between finalize and the next beginAssociation (which resets it before a
genuinely new association's events arrive), so only strays are filtered. The
event carries no payload, so suppression is non-destructive.

Scope: FILE_RECEIVED is intentionally NOT suppressed. It represents an object
already written to disk; a FILE_RECEIVED after finalize indicates finalization
fired too early (a drain/stream-ordering bug), not an event to hide — dropping
it would lose an image. Tracked separately for root-cause diagnosis.

Adds a unit test: finalize a worker, assert a late ASSOCIATION_RECEIVED does
not bubble.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
@gt50 gt50 force-pushed the fix/suppress-late-dcmrecv-events branch from 0d7d79e to 9ad1b1f Compare June 1, 2026 21:26
@gt50

gt50 commented Jun 1, 2026

Copy link
Copy Markdown
Contributor Author

Agreed on all points — done. I've dropped the FILE_RECEIVED guard and narrowed this PR to the ASSOCIATION_RECEIVED suppression only.

You're right that worker.finalized flips at finalize-start inside the #25 drain window, so the guard was suppressing mid-drain files too — and a post-finalize FILE_RECEIVED means finalization fired early (an event to fix, not hide). The ASSOCIATION_RECEIVED half is payload-free and is what the soak actually validated (it's what cleared the stuck activeAssociations).

For the file path I'll open a separate issue with instrumentation that records, for every post-finalize FILE_RECEIVED: the file path, whether it's already in worker.files (duplicate vs new), and which stream the source line came from. Your cross-stream point — the parser is fed line events from both stdout and stderr with no inter-pipe ordering guarantee — is the prime suspect. If any late event is a new path, that's a premature-finalize bug and I'll fix the drain/ordering so ASSOCIATION_FINALIZED is genuinely last, rather than dedup.

Branch force-pushed: DicomReceiver.ts is now +9 (the single ASSOCIATION_RECEIVED guard), full suite green.

@gt50

gt50 commented Jun 1, 2026

Copy link
Copy Markdown
Contributor Author

Confirmed the cross-stream question is structurally closed. I captured the source stream of both line types under normal completions: FILE ("Stored") and COMPLETE ("Release") are 100% stderr (350/350 and 7/7) — dcmrecv emits its whole association lifecycle on one stream, so there's no stdout/stderr split to reorder across.

Combined with the earlier worst-case run (0 post-finalize FILE_RECEIVED across 2600 files / 30 associations under a slow chunky forking sink at 24×100 concurrency), the FILE_RECEIVED path needs no guarding.

To be precise about scope: this rules out the cross-stream reorder. A same-stream chunk-timing late file (the #25 case) remains possible in theory, but it's non-destructive — your context-preservation processes it; only the guard I removed would have dropped it. So this PR stays ASSOCIATION_RECEIVED-only.

The diagnostic lived on a separate investigate/late-file-received branch (never on this PR); deleting it now. Ready for merge from my side.

@MichaelLeeHobbs MichaelLeeHobbs left a comment

Copy link
Copy Markdown
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Approved. Revision is correctly scoped: only the payload-free ASSOCIATION_RECEIVED is suppressed; FILE_RECEIVED suppression was removed (a post-finalize FILE_RECEIVED indicates premature finalization — a separate root-cause bug, not something to hide). Build/Lint/Test green; the Security Audit failure was the unrelated fast-xml-parser advisory, now fixed on main (5.8.0).

@MichaelLeeHobbs MichaelLeeHobbs merged commit 6719229 into MichaelLeeHobbs:main Jun 2, 2026
3 of 4 checks passed
@MichaelLeeHobbs

Copy link
Copy Markdown
Owner

Merged. The deferred root cause (why late dcmrecv events arrive after finalize, and the risk that a late FILE_RECEIVED indicates ASSOCIATION_FINALIZED firing too early) is tracked in #29.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants