Svc::FileUplink emits FileReceived before the file is durably closed, causing spurious file-not-found

[Mikefly123]

Summary

FileUplink::handleEndPacket() (lib/fprime/Svc/FileUplink/FileUplink.cpp:153) logs the FileReceived completion event before calling goToStartMode() (line 160), which is what actually calls this->m_file.osFile.close() (line 196). On our Zephyr FATFS build, Os::File::close() maps directly to fs_close() (lib/fprime-zephyr/fprime-zephyr/Os/File.cpp:85-87), which is what commits the file's directory entry. A consumer that reacts to FileReceived (ground automation, a follow-up FileManager.CalculateCrc/ListDirectory, etc.) can race ahead of the actual filesystem commit and see the file as nonexistent.

Reproduction

On hardware (PROVES V5e, RP2350, Zephyr FATFS), immediately issuing FileManager.CalculateCrc on a path right after its FileUplink.FileReceived event fires intermittently (~15-25% observed rate) returns CalculateCrcFailed ... status 11 (ENOENT-equivalent), even with the correct filename and even after multi-second settle delays in some sessions (ruling out a trivial timing/sync race and suggesting something more structural, e.g. a directory-entry cache not yet flushed). Confirmed independent of filename reuse (fresh, never-before-used filenames reproduce it identically) and independent of which ZephyrUartDriver revision is used (reproducible on both the pre- and post-#457-fix driver, since neither touches this code path) -- confirming this is pre-existing and unrelated to the #457 UART fix.

Suggested fix

Emit FileReceived after goToStartMode()'s close() call completes, not before -- i.e. reorder so the close happens first. This is an upstream nasa/fprime code path (Svc/FileUplink/FileUplink.cpp), so a fix here would need to go upstream eventually, but filing locally first since it manifests concretely on this project's Zephyr FATFS build.

Severity

Moderate -- causes intermittent (not corruption, just "not found yet") failures for any ground automation that acts immediately on FileReceived. Workaround is a short settle delay before the first post-upload file access, but that's a symptom mask, not a fix.

Related to #457 (found during that investigation) but is a separate bug, not fixed by that PR.

🤖 Generated with Claude Code

https://claude.ai/code/session_01WpBURCutAx8281i59nj6fo

[Mikefly123]

Verification attempt: temporary local patch (reverted, not merged)

To verify the diagnosis, applied a temporary local-only patch to lib/fprime/Svc/FileUplink/FileUplink.cpp (never committed/pushed): moved this->m_file.osFile.close() to execute before log_ACTIVITY_HI_FileReceived(...) in handleEndPacket(), leaving goToStartMode()'s existing close as a second (expected-harmless) call.

Result: this made things worse, not better. Ran the full matrix (uplink 1/3/4/5/6/8/10 chunks + 5x5-chunk repeats + downlink 1/3/5) from a clean fsFormat.FORMAT:

• Before the patch (current merged fix only): 11/15 pass, ~4/15 fail with the FileReceived-then-status 11 signature, randomly interspersed among otherwise-successful transfers.
• With the patch applied: 8/15 pass, 7/15 fail -- and critically, once the signature started occurring partway through the session, every subsequent file access failed the same way for the rest of the session, rather than the random intersperse pattern seen without the patch. This looks like the early double-close is triggering some form of progressive filesystem/handle-table degradation on this Zephyr FATFS build, not fixing the race.

This contradicts my assumption that ZephyrFile::close() (fprime-zephyr/Os/File.cpp:85-87, fs_close()) is safe to call twice on the same handle. It's plausible that:

• the first (early) fs_close() doesn't actually flush/commit in time either (so the race persists), and/or
• calling fs_close() a second time on an already-closed handle corrupts or leaks something in Zephyr's file-object table, causing cascading failures for unrelated files later in the session.

The patch has been fully reverted (verified via git diff/git status showing zero diff on FileUplink.cpp); the merged #457 fix (RX back-pressure only) remains unaffected -- NO_OP and normal operation reverified after reverting and reflashing.

Conclusion: the fix for this issue needs more care than a naive reorder -- likely needs to either (a) confirm whether a single early close (without the redundant second close in goToStartMode()) is sufficient and safe, which would require also modifying goToStartMode() to skip the close if already done (e.g. a guard flag), or (b) investigate why the early close doesn't reliably prevent the race even once, before concluding a reorder is the right fix direction at all. Not re-attempting further in this session; leaving as an open follow-up.

🤖 Generated with Claude Code

https://claude.ai/code/session_01WpBURCutAx8281i59nj6fo

[Mikefly123]

Root cause confirmed: TcSecurityDeframer's synchronous per-command sequence-number persist races with FileUplink/FileManager/FileDownlink/PrmDb on the shared filesystem

Long investigation, several dead ends corrected along the way (documented below for
the record — useful context if this resurfaces). Root cause is now confirmed with
both statistical A/B evidence and a captured mechanism trace.

What actually backs storage

The FATFS mount at / is backed by the physical SD card over SPI (spi0/sdhc0,
CONFIG_DISK_DRIVER_SDMMC=y), not the internal QSPI flash storage_partition
that FsFormat.FORMAT targets. Devicetree's fstab { ffs1 {...} } has no
partition/disk-name binding, and Zephyr's FAT fstab codegen
(subsys/fs/fat_fs.c:573) sets .storage_dev = NULL for the mount, resolving via
the disk-access registry -- the only disk-access driver enabled is the SD card.
FsFormat.FORMAT's "OK" response is with respect to an orphaned, unrelated
partition and is not evidence about the real filesystem's health.

Status 11 decode

Os::File::Status value 11 = OTHER_ERROR, not DOESNT_EXIST (1).
Os::Zephyr::File::open() collapses every nonzero fs_open() return into
OTHER_ERROR, discarding the real errno -- this is why the original symptom was
ambiguous. Added TEMP DIAG instrumentation (an SWD-readable RAM ring buffer, since
Fw::Logger::log is a no-op on this build -- CONFIG_CONSOLE is not set) to
capture the raw fs_open/fs_write/fs_close/fs_sync return codes directly.

Campaign data

20-run campaign (10 uplinks to /name.bin, 10 to //name.bin, 5-chunk/1020-byte
files, immediate CalculateCrc) on the unmodified code: 3/20 passed (15%). No
/ vs // difference. Every failure polled at 1s/5s/30s stayed failed the whole
window, but a different filename uplinked right after a failure routinely succeeded
-- not a stuck resource. Write-side calls (open->write->sync->close) always
returned rc=0; failures were 100% on the read side: fs_open(FS_O_READ) from
FileManager.CalculateCrc intermittently returned rc=-2 (-ENOENT) for a file
whose own write+close had just completed successfully.

A durability discriminator (uplink until CRC passes, SWD warm reset to force a full
FatFS remount, recheck) showed: passing files stayed correct after remount (data is
genuinely durable, not a stale-cache read), and failing files stayed absent after
remount (not a delayed-visibility race that resolves with time/a fresh mount -- the
data for that file was never durably written). Stable per-file outcome, not random
per-attempt flakiness.

Two theories tested and refuted -- included for the record

• exFAT/FAT format mismatch (retracted). Initially concluded the build wasn't
  actually compiling exFAT support (CONFIG_FS_FATFS_EXFAT=y) based on the vendored
  ffconf.h's hardcoded FF_FS_EXFAT 0 default -- missed Zephyr's
  ZEPHYR_CONFIG_OVERRIDE mechanism. Ground-truth check: compile_commands.json
  confirms ff.c compiles with -DZEPHYR_CONFIG_OVERRIDE=zephyr_fatfs_config.h,
  and that generated header does #define FF_FS_EXFAT CONFIG_FS_FATFS_EXFAT.
  Confirmed via nm on the compiled ff.c.obj: it contains load_xdir,
  store_xdir, xdir_sum -- exFAT-only internal functions that only exist when
  FF_FS_EXFAT=1. exFAT support is genuinely compiled in; this was not the cause.
• CONFIG_FS_FATFS_REENTRANT=y (tested, no effect). Hypothesized that
  FF_FS_TINY=1 (Zephyr forces this unconditionally -- a single shared sector
  window buffer across all open file objects) combined with no internal FatFs
  locking (FF_FS_REENTRANT=0 by default) was the hazard, given FileUplink,
  FileManager, FileDownlink, and PrmDb are all active components on
  independent threads. Enabled CONFIG_FS_FATFS_REENTRANT=y, rebuilt, reflashed,
  reran the identical 20-run campaign: 4/20 passed (20%) -- statistically
  indistinguishable from baseline, and ListDirectory still reported "0 files" in
  every check. FatFs's own internal lock did not close the race, meaning the
  collision was happening below FatFs's API surface, not within it.

Confirmed root cause

TcSecurityDeframer::dataIn_handler (added in #447) persists the authenticated
sequence number to a file on every accepted command frame:

this->m_sequenceNumber = parseResult.securityHeader.sequenceNumber;
this->writeSequenceNumber(this->m_sequenceNumber);   // 4-byte U32 file write

TcSecurityDeframer is a passive component -- this write executes synchronously
on whatever thread is processing the incoming command frame (the comm/deframing
pipeline), not on its own serialized thread. Since every uplink DATA packet is
itself an accepted command frame, this writer fires on essentially every packet of
every uplink, interleaved with FileUplink's own filesystem calls on a different
thread, both touching the SD-card-backed FatFs mount with no coordination between
them.

A/B test (10x 1000-byte/5-chunk uplinks, unique names, immediate CRC):

	Writer enabled (current behavior)	Writer disabled (TEMP, uncommitted)
Pass rate	1/10 (10%)	10/10 (100%)

Full 20-run campaign with the writer disabled: 20/20 (100%), including a
parallel-stress variant (CalculateCrc on an older file fired while a new uplink
was still in flight) which also passed.

Captured mechanism (SWD ring-buffer trace, writer-enabled run, chronological):

 4  open   0  18   <- uplinked file opened (CREATE|WRITE), stays open...
 5  open   0  82   <-\
 6  write  4   4      | seq-num writer's FULL open->write->sync->close cycle
 7  sync   0   0      | executes WHILE the uplinked file's own handle (opened
 8  close  0   0   <-/  at slot 4) is still open, before its own data writes
 9  write 256 256  <- uplink data write #1 (of the file opened at slot 4)
10  write 256 256  <- uplink data write #2
11  write 256 256  <- uplink data write #3
...
21  close  0   0   <- uplinked file finally closes (rc=0, reports success)
...
26  open  -2   1   <- subsequent CalculateCrc read-open: ENOENT

The seq-num writer's complete open/write/sync/close cycle runs inside the
uplink's own open-file window, on a different thread, with no serialization between
them -- followed shortly by a failed read-open for that exact file.

Stress tests, writer disabled: 1000-chunk (204,000 byte) uplink passed
(CRC-verified), 1000-chunk downlink passed (204,000/204,000 bytes byte-correct,
~8.1 kB/s). Both previously gated on this bug are now clean.

Why this didn't show up until now, and won't stay hidden

This is rate-dependent on command/packet density, not something UART-specific.
At UART speeds the collision window is comparatively rare (hence 15-20% rather than
100%), but the mechanism only cares about how often an accepted command frame
lands while a filesystem operation from another component is in flight -- it will
get worse, not better, on faster links (LoRa at higher SF/BW, or S-band), where
much higher command/telemetry throughput means more opportunities per second for
the interleaving to occur.

Recommended fix direction (not yet implemented)

Move the sequence-number persistence off the synchronous per-command path.
Proposed: write-ahead batched persistence -- persist the sequence number every
Nth accepted command (or on a timer) rather than every single one, storing
current + N ahead of time so a power-loss between writes still leaves the
on-disk value safely at-or-ahead of the last actually-processed sequence number
(preserving the anti-replay guarantee from #426 -- the stored value only ever needs
to be >= the highest sequence number a legitimate command could have used before
loss of power, not exactly equal to it). This bounds the write frequency to
whatever cadence is chosen while keeping the security property intact. Also worth
considering, independent of the batching change: moving the write off the
passive/synchronous command-processing path entirely (e.g. into an active
component or queued call) so it can never interleave with another component's
filesystem operation regardless of how it's triggered.

No code has been pushed. TcSecurityDeframer.cpp (writer disabled) and prj.conf
(CONFIG_FS_FATFS_REENTRANT=y, confirmed non-contributory but harmless) remain as
local, uncommitted diffs pending a decision on the fix shape.

[Mikefly123]

Fix verified end-to-end from a clean flash + bench power-cycle (2026-07-22)

Previous late-session failure walls (8/20 → 0/20 → 1/20 → 0/5) did not reproduce after removing the two confounds they correlated with: GDS auth-seq desync and long continuous board uptime (hours of SWD-only resets). After a bench power-cycle and a fresh SWD flash of the fix/461-seq-persistence tip (write-ahead batched persistence, stride 100, torn-write-safe {value, ~value} record, fail-safe high-water advance only on OP_OK):

Check	Result
10× NO_OP + ListDirectory //	10/10, OK
3× 1-chunk uplinks (CRC value compare)	3/3
20× 5-chunk uplink campaign, unique names, persistence active	20/20
10× 1000-byte uplinks, persistence active	10/10
204 KB (1000-chunk) single-file uplink	CRC exact match, 8.1 KB/s
204 KB downlink back	byte-identical, 7.2 KB/s
SequenceNumberPersistFailed / SequenceNumberRecordInvalid events	zero
Stride-boundary persist writes during campaign (seq 9965 → 10000+ → 10077+)	clean, no uplink impact

For comparison, the pre-fix baseline with the synchronous per-command writer was 1/10 on the same 5-chunk campaign; disabling the writer gave 10/10 and 20/20 — the batched write-ahead design now matches the writer-disabled numbers with persistence active, which is the property the fix needed to prove.

One rig note from the stress run: the stock test_downlink_large harness false-fails on out-of-order board EVR timestamps (board stamped OpCodeDispatched at .999 of the prior second), tripping the test API's chronological sequence search while the on-board operation actually succeeded — worth a tolerant-wait cleanup in the permanent suite, unrelated to this fix.

PR from fix/461-seq-persistence to follow.