Skip to content

feat(bin): add durable host resource telemetry recorder - #70

Merged
withally merged 7 commits into
mainfrom
fm/fm-crash-telemetry-recorder-t4
Aug 24, 2026
Merged

feat(bin): add durable host resource telemetry recorder#70
withally merged 7 commits into
mainfrom
fm/fm-crash-telemetry-recorder-t4

Conversation

@withally

Copy link
Copy Markdown
Owner

Intent

Build a lightweight resource-telemetry recorder for Firstmate in bin so the next Mac freeze is instantly diagnosable after a forced power-cycle. Provide one shellcheck-clean script with arm, disarm, status, and internal record modes, with its contract documented in the header. Every configurable 15-30 seconds, default about 20 seconds, append a small timestamped snapshot containing a memory_pressure summary, vm_stat, sysctl vm.swapusage, about 15 processes ranked by RSS and CPU from ps, total process count, cheap per-parent and coalition approximations, and disk free. Write append-only daily logs under state/telemetry with fsync or equivalent durability so at most the last interval is lost, rotate by day, cap total retained size around 200 MB, and prune oldest logs. Keep overhead negligible with one long-lived sleeping loop and no process storms; measure and state its overhead in the PR. Arm must detach idempotently with one instance per FM_HOME and a lock; disarm must stop cleanly; status must report running state and newest snapshot age. Do not auto-arm the recorder and do not install launchd agents. Ship colocated behavioral tests covering parseable snapshots, rotation, durability, and lock behavior with fake samplers where appropriate. A launchd plist generator is optional and, if included, must only print operator install instructions. Follow Firstmate shared-material rules: one sentence per Markdown line, plain dashes, shellcheck-clean bin scripts, colocated executable-interface tests, no agent co-author, and the repository lint contract.

What Changed

  • Added bin/fm-telemetry.sh, a never-auto-armed recorder with arm, disarm, status, and internal record/fsync modes: every 15-30s (default 20s, via FM_TELEMETRY_INTERVAL) it appends a bounded fm-telemetry-v1 snapshot with memory_pressure -Q, vm_stat, sysctl vm.swapusage, top-15 RSS/CPU processes plus total count and per-parent/PGID approximations from a single reused ps sample, and root-volume free space, to daily logs under state/telemetry/ that are fsync'd (plus F_FULLFSYNC) along with their directory and pruned oldest-first to FM_TELEMETRY_MAX_BYTES (default 200 MiB).
  • Singleton and lifecycle handling: one detached recorder per FM_HOME behind an atomically published symlink lock carrying PID/cadence/launch token, a holder-named guard symlink serializing reclaim-and-republish, owner tokens in argv so status and disarm share one liveness rule, an arm-time durability probe before detaching, and timestamped recorder diagnostics in state/telemetry/recorder.err trimmed to 32 KiB past 64 KiB; no launchd agent is installed.
  • Added tests/fm-telemetry.test.sh (15 cases with fake samplers) covering snapshot parseability and durability, interval clamping, daily rotation and cap pruning, temp cleanup, arm idempotence/disarm, guard and stale-lock races, and diagnostics bounding; listed the script in docs/scripts.md.

Overhead: steady state is a single sleeping Bash process. Each tick runs samplers sequentially with no overlapping schedules, reuses one ps result for all process-derived sections, and adds one short-lived interpreter process for the durable flush.

Risk Assessment

✅ Low: The recorder is a self-contained new script with no callers in the existing tree, its durability, UTC dating, cadence bound, singleton lock, guard ownership, bounded arm, and timestamped diagnostics all verified live on this machine, leaving only two narrow cosmetic/edge residuals.

Testing

Ran the colocated suite tests/fm-telemetry.test.sh (15/15 pass) and then exercised the recorder the way an operator would: armed it against a temp FM_HOME with real macOS samplers, confirmed idempotent re-arm on the same pid, watched status report a live recorder and fresh snapshot age, inspected a real snapshot containing memory_pressure, vm_stat, swapusage, top-15 RSS and CPU rankings, total process count, per-parent and coalition approximations and disk free, SIGKILLed the recorder to stand in for a forced power-cycle and verified every retained snapshot including the last one was complete and parseable, re-armed and disarmed cleanly, measured overhead at roughly 0.10s CPU per snapshot and ~0.5% of one core at the default cadence with a single sleeping process, and confirmed arming installs no launch agent and nothing else in the repo auto-arms it; all checks passed and temp state was cleaned up.

Evidence: Operator CLI transcript (arm, idempotent arm, status, SIGKILL power-cycle sim, recovery, disarm)

Source: Operator CLI transcript (arm, idempotent arm, status, SIGKILL power-cycle sim, recovery, disarm)

$ bin/fm-telemetry.sh arm fm-telemetry: running pid=8092 interval=15s directory=.../state/telemetry $ bin/fm-telemetry.sh arm # idempotent, same pid fm-telemetry: already running pid=8092 interval=15s $ bin/fm-telemetry.sh status fm-telemetry: running pid=8092 interval=15s newest_snapshot_age=0s directory=.../state/telemetry == simulate a hard power-cycle: SIGKILL the recorder == $ kill -9 8092 ... SNAPSHOT_END timestamp=2026-08-24T09:26:10Z # last snapshot survived intact $ bin/fm-telemetry.sh status fm-telemetry: not running newest_snapshot_age=3s directory=.../state/telemetry (exit 1) $ bin/fm-telemetry.sh arm fm-telemetry: running pid=5214 interval=15s directory=.../state/telemetry $ bin/fm-telemetry.sh disarm fm-telemetry: stopped pid=5214 SNAPSHOT_BEGIN count: 7 / SNAPSHOT_END count: 7

$ FM_HOME=/tmp/fm-telemetry-e2e.PpvEfK FM_TELEMETRY_INTERVAL=15 bin/fm-telemetry.sh arm
fm-telemetry: running pid=8092 interval=15s directory=/tmp/fm-telemetry-e2e.PpvEfK/state/telemetry

$ bin/fm-telemetry.sh arm   # idempotent, same pid
fm-telemetry: already running pid=8092 interval=15s

$ bin/fm-telemetry.sh status
fm-telemetry: running pid=8092 interval=15s newest_snapshot_age=0s directory=/tmp/fm-telemetry-e2e.PpvEfK/state/telemetry
== simulate a hard power-cycle: SIGKILL the recorder (no trap, no clean shutdown) ==
$ kill -9 8092

$ tail -c 400 telemetry-$(date -u +%F).log   # last durable snapshot survived intact
OCESS_COUNTS_BY_PGID_COALITION_APPROX count pgid
63 715
14 99320
11 721
11 1171
10 1169
8 51679
6 1192
6 9651
6 35299
5 61817
5 97851
4 12494
4 30639
4 35598
4 38867
DISK_FREE_KIB
Filesystem     1024-blocks      Used Available Capacity iused      ifree %iused  Mounted on
/dev/disk3s1s1   971298980  12277016 391747212     4%  458725 3917472120    0%   /
SNAPSHOT_END timestamp=2026-08-24T09:26:10Z


$ bin/fm-telemetry.sh status   # stale lock is not trusted
fm-telemetry: not running newest_snapshot_age=3s directory=/tmp/fm-telemetry-e2e.PpvEfK/state/telemetry
(exit 1)

== post-crash recovery ==
$ bin/fm-telemetry.sh arm
fm-telemetry: running pid=5214 interval=15s directory=/tmp/fm-telemetry-e2e.PpvEfK/state/telemetry
$ bin/fm-telemetry.sh disarm
fm-telemetry: stopped pid=5214
$ bin/fm-telemetry.sh status
fm-telemetry: not running newest_snapshot_age=1s directory=/tmp/fm-telemetry-e2e.PpvEfK/state/telemetry
(exit 1)

== retained snapshots and their parse structure ==
7
7
total 88
-rw-r--r--@ 1 ivan  wheel      0 Aug 24 17:24 recorder.err
-rw-r--r--@ 1 ivan  wheel  43667 Aug 24 17:26 telemetry-2026-08-24.log
Evidence: Real captured snapshot from the armed recorder

Source: Real captured snapshot from the armed recorder

SNAPSHOT_BEGIN schema=fm-telemetry-v1 timestamp=2026-08-24T09:24:54Z epoch=1787563494 local_utc_offset=+0800 recorder_pid=8092 MEMORY_PRESSURE / System-wide memory free percentage: 40% VM_STAT / Pages free: 3983. ... SWAP_USAGE / vm.swapusage: total = 8192.00M used = 7605.69M free = 586.31M PROCESS_TABLE / PROCESS_TOTAL 798 TOP_RSS_KIB ... 15 rows / TOP_CPU_PERCENT ... 15 rows PROCESS_COUNTS_BY_PARENT / PROCESS_COUNTS_BY_PGID_COALITION_APPROX DISK_FREE_KIB / /dev/disk3s1s1 971298980 12277016 391739644 4% / SNAPSHOT_END timestamp=2026-08-24T09:24:54Z

SNAPSHOT_BEGIN schema=fm-telemetry-v1 timestamp=2026-08-24T09:24:54Z epoch=1787563494 local_utc_offset=+0800 recorder_pid=8092
MEMORY_PRESSURE
The system has 25769803776 (1572864 pages with a page size of 16384).
System-wide memory free percentage: 40%
VM_STAT
Mach Virtual Memory Statistics: (page size of 16384 bytes)
Pages free:                                     3983.
Pages active:                                 307475.
Pages inactive:                               305173.
Pages speculative:                              1358.
Pages throttled:                                   0.
Pages wired down:                             208968.
Pages purgeable:                                   6.
"Translation faults":                     5893038263.
Pages copy-on-write:                      1615632183.
Pages zero filled:                         747029964.
Pages reactivated:                          54114234.
Pages purged:                               15311150.
File-backed pages:                            192475.
Anonymous pages:                              421531.
Pages stored in compressor:                  2133626.
Pages occupied by compressor:                 685705.
Decompressions:                             47200356.
Compressions:                               56595105.
Pageins:                                    17806461.
Pageouts:                                     122076.
Swapins:                                       76986.
Swapouts:                                     562040.
Pages tagged:                                  97968.
Pages tagged resident:                         73573.
Pages tagged compressed:                       24395.
Pages tag-storage:                             49152.
Pages tag-storage holding tags:                 3870.
Pages tag-storage free:                          310.
Pages tag-storage non-tag pageable:            44882.
Pages tag-storage non-tag wired:                  90.
Bytes of compressed tags:                    3885120.
Tagged compressions:                         1068202.
Tagged decompressions:                        971890.
SWAP_USAGE
vm.swapusage: total = 8192.00M  used = 7605.69M  free = 586.31M  (encrypted)
PROCESS_TABLE
PROCESS_TOTAL 798
TOP_RSS_KIB pid ppid pgid cpu rss_kib etime command
53378  1135 53378   8.4 478160    01:55 claude
28358 28144 28358   3.9 439744    56:10 pi
73938  1135 73938   0.2 437312    05:46 claude
75647   715   715   0.0 378320 02:46:50 /Applications/Google Chrome.app/Contents/Frameworks/Google Chrome Framework.framework/Versions/151.0.7922.170/Helpers/Google Chrome Helper (Renderer).app/Contents/MacOS/Google Chrome Helper (Renderer)
  715     1   715   2.6 372688 06:21:20 /Applications/Google Chrome.app/Contents/MacOS/Google Chrome
50035 49993 49993   0.1 297248 02:21:21 /Users/ivan/.local/share/claude/versions/2.1.241
11068 10145 11068   0.0 253648 06:19:22 claude
 9273   715   715   0.0 246032 03:05:03 /Applications/Google Chrome.app/Contents/Frameworks/Google Chrome Framework.framework/Versions/151.0.7922.170/Helpers/Google Chrome Helper (Renderer).app/Contents/MacOS/Google Chrome Helper (Renderer)
  719     1   719   0.0 240816 06:21:20 /Applications/WhatsApp.app/Contents/MacOS/WhatsApp
22344 22274 22274   0.5 210816    44:21 /opt/homebrew/lib/node_modules/@openai/codex/node_modules/@openai/codex-darwin-arm64/vendor/aarch64-apple-darwin/bin/codex
99426 99320 99320   0.0 199680 01:54:13 /Applications/ChatGPT.app/Contents/Frameworks/Codex Framework.framework/Versions/151.0.7922.170/Helpers/Codex (Renderer).app/Contents/MacOS/Codex (Renderer)
99320     1 99320   0.0 189296 01:54:16 /Applications/ChatGPT.app/Contents/MacOS/ChatGPT
 2609  1715  2609   0.0 186768 06:19:30 claude
 4269   715   715   0.1 183520 01:45:57 /Applications/Google Chrome.app/Contents/Frameworks/Google Chrome Framework.framework/Versions/151.0.7922.170/Helpers/Google Chrome Helper (Renderer).app/Contents/MacOS/Google Chrome Helper (Renderer)
 9651  8857  9651   0.0 182544    23:52 /Applications/Google Chrome.app/Contents/MacOS/Google Chrome
TOP_CPU_PERCENT pid ppid pgid cpu rss_kib etime command
  702     1   702 100.9 119744 06:21:20 /Applications/cmux.app/Contents/MacOS/cmux
  338     1   338  49.7  15408 06:21:37 /usr/libexec/logd
 6021 61825 61817  16.2   6096    03:49 bash
53378  1135 53378   8.4 478160    01:55 claude
28358 28144 28358   3.9 439744    56:10 pi
 7855 12951 12494   3.6   3600    00:00 bash
 1065   715   715   3.0 108480 06:21:12 /Applications/Google Chrome.app/Contents/Frameworks/Google Chrome Framework.framework/Versions/151.0.7922.170/Helpers/Google Chrome Helper.app/Contents/MacOS/Google Chrome Helper
  519     1   519   2.7  17216 06:21:36 /usr/libexec/syspolicyd
  715     1   715   2.6 372688 06:21:20 /Applications/Google Chrome.app/Contents/MacOS/Google Chrome
 2474     1  2474   2.5  94528 06:19:57 /Applications/NordVPN.app/Contents/MacOS/NordVPN
 7940 53378  7940   1.9   2608    00:00 /bin/zsh
  411     1   411   1.0  38048 06:21:36 /System/Library/PrivateFrameworks/SkyLight.framework/Resources/WindowServer
 2439     1  2439   1.0  35600 06:19:58 /Library/PrivilegedHelperTools/com.nordvpn.macos.helper
  420     1   420   0.9  27360 06:21:36 /usr/sbin/coreaudiod
 1472  1169  1169   0.8  57040 06:21:03 /Applications/Wispr Flow.app/Contents/Frameworks/Wispr Flow Helper (Renderer).app/Contents/MacOS/Wispr Flow Helper (Renderer)
PROCESS_COUNTS_BY_PARENT count ppid
445 1
64 715
12 99320
10 721
10 1171
10 1713
9 1169
8 51679
7 13245
7 15351
7 22344
7 22801
6 99420
5 1192
5 9651
PROCESS_COUNTS_BY_PGID_COALITION_APPROX count pgid
65 715
14 99320
11 721
11 1171
10 1169
8 51679
7 7940
6 1192
6 9651
6 12494
6 35299
5 61817
4 30639
4 35598
4 38867
DISK_FREE_KIB
Filesystem     1024-blocks      Used Available Capacity iused      ifree %iused  Mounted on
/dev/disk3s1s1   971298980  12277016 391739644     4%  458725 3917396440    0%   /
SNAPSHOT_END timestamp=2026-08-24T09:24:54Z
Evidence: Measured overhead

Source: Measured overhead

per-tick full snapshot (real samplers): real 0.13 user 0.04 sys 0.06 (x3 runs, identical) 65s steady-state window on armed recorder: cputime 0:00.01 -> 0:00.05, 1 child process (the sleep), rss 2368 KiB => ~0.10s CPU per snapshot, ~0.5% of one core at the default 20s cadence

# per-tick cost of one full snapshot (real macOS samplers), FM_HOME=/tmp/fm-tel-tick.AQqHTo
tick1 real 0.13
tick1 user 0.04
tick1 sys 0.06
tick2 real 0.13
tick2 user 0.04
tick2 sys 0.06
tick3 real 0.13
tick3 user 0.04
tick3 sys 0.06

# steady-state recorder process (armed at 15s cadence)
 8092 01:07   0:00.05   0.0   2368 bash /Users/ivan/.no-mistakes/worktrees/37852af5566c/01M0SEQZ2XYDGD2MD4G1WSKNQY/bin/fm-telemetry.sh record fmtelemetry-1787563494-7975
snapshots written so far: 5
live child processes of recorder: 1 (the sleep)

# 65s steady-state window on the armed recorder
recorder pid=8092 window=65s cputime_start=0:00.01 cputime_end=0:00.05
 8092     1   0.0   2368 01:13 bash /Users/ivan/.no-mistakes/worktrees/37852af5566c/01M0SEQZ2XYDGD2MD4G1WSKNQY/bin/fm-telemetry.sh record fmtelemetry-1787563494-7975
snapshots so far: 5
descendant processes right now: 1
# => ~0.04s CPU per 65s in the loop process itself; ~0.10s CPU per full snapshot including samplers
# => ~0.5% of one core at the default 20s cadence, one sleeping bash + one sleep child between ticks

Pipeline

Updates from git push no-mistakes

✅ **intent** - passed

✅ No issues found.

✅ **Rebase** - passed

✅ No issues found.

⚠️ **Review** - 2 infos
  • 🚨 bin/fm-telemetry.sh:223 - sync -f "$log_file" does not provide the required per-file durability on macOS, the only platform this recorder targets (it samples memory_pressure/vm_stat/vm.swapusage). Verified on this machine: macOS sync(8) takes no arguments and silently ignores them — sync -zzz /tmp/x and sync /nonexistent/path both exit 0 — and sync(2) documents "sync() may return before the buffers are completely flushed" with no device-cache flush (no F_FULLFSYNC). Three consequences: (1) the intent criterion "Write append-only daily logs ... with fsync or equivalent durability so at most the last interval is lost" is not met — after a forced power-cycle several intervals can be missing, which is exactly the diagnosis scenario; (2) the failure branch at lines 223-227 is unreachable on macOS because sync always exits 0, so the "durability failure" reporting only ever fires against the fake sync in tests/fm-telemetry.test.sh:53-59, which asserts a sync -f <file> contract macOS does not implement; (3) every tick triggers a whole-system buffer flush instead of one file fsync, which cuts against the negligible-overhead requirement on an already-thrashing host. Also makes the header claim at line 14 ("sync -f makes that log durable") false. Recommend a real fsync at the shared append boundary in append_snapshot — e.g. a small /usr/bin/python3 -c helper doing os.fsync(fd) plus Darwin fcntl(fd, F_FULLFSYNC) (one extra short-lived process per interval, still far from a process storm) — and correcting the header; or, if the weaker guarantee is deliberate, say so explicitly in the header and drop the unreachable failure branch.
  • ⚠️ bin/fm-telemetry.sh:118 - The lock directory is published non-atomically, so a concurrent arm/disarm can destroy a live recorder's lock and break the one-instance-per-FM_HOME invariant. acquire_lock does mkdir "$LOCK_DIR" (line 118) and only then writes token, interval and pid (lines 119-121). Concrete sequence: arm A spawns recorder A; recorder A completes mkdir; before its pid write lands, arm B runs — read_lock_owner finds no pid file, so lock_owner_is_live returns 1 (line 99), and line 301 [ ! -d "$LOCK_DIR" ] || remove_stale_lock deletes the live owner's lock dir. arm B then spawns recorder B, whose mkdir now succeeds. Two recorders append to the same daily log, and recorder A's release_lock (line 141) sees a pid/token mismatch so it never cleans up; a later disarm only stops B, leaving A running and unreachable forever. The same window makes disarm (line 322-325) print "not running" and delete the lock of a recorder that is in fact alive. Fix at the lock boundary: build the lock contents in a mktemp -d sibling and mv the fully-populated directory into place (atomic rename onto a nonexistent path), so LOCK_DIR is never observable in a half-initialized state.
  • ℹ️ bin/fm-telemetry.sh:207 - If mktemp fails for SAMPLE_TMP (line 207) or PROCESS_TMP (line 208), append_snapshot returns 1 without calling cleanup_snapshot_temps, so the already-created .snapshot.XXXXXX (and possibly .sample.XXXXXX) file is orphaned in TELEMETRY_DIR. record() keeps looping, so the leak repeats every interval, and these files are not matched by the telemetry-*.log glob in daily_log_bytes so they are invisible to the 200 MB cap. The most likely trigger — a full or near-full volume — is exactly the incident condition this tool is meant to survive. Call cleanup_snapshot_temps on those early-return paths.
  • ℹ️ bin/fm-telemetry.sh:77 - The intent specifies the cadence as "Every configurable 15-30 seconds, default about 20 seconds", but validate_configuration accepts FM_TELEMETRY_INTERVAL up to 3600 (line 77), and the header documents the range as 15..3600. The default of 20 is correct; only the upper bound is widened well beyond the stated range, which lets an operator configure a cadence that loses far more than the intended granularity. Confirm whether the 3600 ceiling is intended or the bound should be 30.
  • ℹ️ bin/fm-telemetry.sh:204 - Rotation keys the log filename on the local date (day=$(date '+%Y-%m-%d'), line 204, and the same expression in prune_daily_logs line 244) while every snapshot inside is stamped in UTC (line 202). For a machine at UTC+8 that means telemetry-2026-08-24.log opens with snapshots stamped 2026-08-23T16:00:00Z, so a reader correlating a freeze time against the filename can pick the wrong day's file. Either stamp the day in UTC too, or record the local timezone offset in SNAPSHOT_BEGIN so the two are reconcilable.

🔧 Fix: fix(telemetry): real fsync, atomic lock, UTC dating, temp cleanup
5 issues (3 warnings, 2 infos) still open:

  • ⚠️ bin/fm-telemetry.sh:219 - The durable-flush helper fsyncs the log file but never its containing directory, so the required guarantee "a forced power-cycle loses at most the final interval" (header lines 15-16, intent: "fsync or equivalent durability so at most the last interval is lost") does not hold across daily rotation. Concrete sequence: at 00:00 UTC append_snapshot computes a new day and cat &gt;&gt; &#34;$log_file&#34; creates telemetry-<newday>.log; fsync(2)+F_FULLFSYNC make the file's data and inode durable, but the new directory entry in state/telemetry lives only in the parent directory's dirty metadata. A power-cycle a few intervals later can leave the volume with no link to that inode, so every snapshot taken since rotation is gone - not one interval, but all of them - which is exactly the freeze-diagnosis window this tool exists for. Fix at the same shared boundary: in the Python helper, after flushing the file, also dfd = os.open(os.path.dirname(path), os.O_RDONLY); os.fsync(dfd) (and F_FULLFSYNC on darwin), or do it only when the file was just created. One extra open/fsync per tick, no new process.
  • ⚠️ bin/fm-telemetry.sh:318 - A recorder started through the documented token-less record mode (header line 8 documents record [owner-token], and line 318 deliberately synthesizes manual-&lt;epoch&gt;-&lt;pid&gt;) is invisible to status and destructive to disarm, because the synthesized token never appears in the process's argv while lock_owner_is_live requires *fm-telemetry.sh*record*$LOCK_TOKEN* (line 120). Verified live on this machine: with FM_HOME=/tmp/tmtest ... fm-telemetry.sh record &amp; running as pid 58177 and the lock symlink reading 58177:30:manual-1787561827-58177, status printed fm-telemetry: not running newest_snapshot_age=2s and exited 1, and disarm printed fm-telemetry: not running while deleting the live recorder's lock and leaving pid 58177 alive. That is a wrong label reported without any error, plus a lock deletion that lets a subsequent arm run a second recorder against the same FM_HOME until the displaced one reaches the top of its loop (up to one full interval). Fix at the token boundary: make the token always part of argv - e.g. have token-less record synthesize the token and re-exec &#34;$SCRIPT_PATH&#34; record &#34;$token&#34; - so liveness detection has a single rule for every recorder.
  • ⚠️ bin/fm-telemetry.sh:360 - arm detaches the recorder with &gt;/dev/null 2&gt;&amp;1, permanently discarding every diagnostic the loop emits, and nothing validates FM_TELEMETRY_PYTHON before detaching. Concrete state: on a Mac without Command Line Tools, /usr/bin/python3 is the developer-tools shim and exits non-zero. append_snapshot still appends the snapshot at line 272, then fsync_file fails, so each tick prints "durability flush failed" and "snapshot failed" into /dev/null and the loop continues forever (record only propagates tick_rc under FM_TELEMETRY_RECORD_ONCE, line 342). The operator sees status: running ... newest_snapshot_age=3s - a healthy-looking recorder whose logs carry none of the durability the header promises, discovered only after the freeze it was meant to survive. Fail fast instead: during arm, run fsync_file against a probe file in TELEMETRY_DIR and refuse to detach with a clear message if it fails, and/or send recorder stderr to a bounded file under state/telemetry rather than /dev/null.
  • ℹ️ bin/fm-telemetry.sh:132 - remove_stale_lock's re-read guard narrows but does not close the stale-reclaim race, so two recorders can still coexist for up to one interval. Line 128 reads observed, line 132 re-reads and compares - both reads see the same stale target - and only then does line 133 rm -f run. If another arm's recorder publishes its symlink in the gap between the compare and the rm, the rm deletes a live owner's lock; the displaced recorder does not notice until owns_lock is re-checked at the top of its loop (line 329), i.e. after a full FM_TELEMETRY_INTERVAL of both recorders appending to the same daily log. The system does self-heal (the loser stands down and release_lock correctly refuses to remove the new owner's link), so this is bounded, not corrupting. Note the new regression at tests/fm-telemetry.test.sh:262 cannot catch it: it runs the arms with FM_TELEMETRY_INTERVAL=30 but only waits 50 x 0.1s for convergence, so a real double-recorder would exceed the window and the test's passing does not prove the race is gone. Closing it needs a serialization point around reclaim-plus-republish (an atomic mkdir mutex directory held across the readlink/rm/ln sequence), not a second readlink.
  • ℹ️ bin/fm-telemetry.sh:373 - Two cold arm invocations racing produce a spurious failure, contrary to "Arm must detach idempotently with one instance per FM_HOME". Both arms see no lock, both spawn recorders; the loser's recorder hits acquire_lock's return 2 and dies with fail &#34;recorder already running&#34;, so its arm's wait loop sees the child gone (line 368), breaks, and exits 1 with "recorder did not acquire its lock" even though a healthy recorder is running for that FM_HOME. Re-check lock_owner_is_live after the child exits and, when another recorder owns the lock, print the already-running line and return 0 as the idempotent path does at line 354. The concurrency test at tests/fm-telemetry.test.sh:282 masks this because it discards each arm's status and output.

🔧 Fix: fix(telemetry): durable dir flush, argv tokens, guarded locks, arm probe
3 issues (1 error, 2 infos) still open:

  • 🚨 bin/fm-telemetry.sh:500 - arm can block forever. The poll loop at lines 490-499 has two exits: the child died (kill -0 ... || break), or tries reached 30 (~3s) with the child STILL ALIVE. In the second case control falls through to wait &#34;$child_pid&#34; at line 500, which blocks until the detached recorder exits - i.e. never. Verified live on this machine: with a PATH ps shim that returns nothing (so lock_owner_is_live never becomes true), arm was still blocked after 28s while the recorder it spawned held the lock (readlink .record.lock -> 4712:15:fmtelemetry-...) and ps -p 4712 showed a healthy fm-telemetry.sh record &lt;token&gt;. The same code path is reachable without any shim in the environment this tool exists for: on a loaded/freezing Mac the nohup'd child can need more than 3s to reach its ln -s (bash startup + validate + mkdir + guard_acquire, which itself spins up to 10s under contention), after which it acquires the lock and loops forever while the parent arm never returns. This is a regression introduced by the round-2 fix for review-10; before it, arm timed out and exited. It also makes tests/fm-telemetry.test.sh:378 (test_concurrent_arms_over_a_stale_lock_keep_one_recorder, which has no timeout and does a bare wait) able to hang the whole suite rather than fail. Fix: only wait when the child is known dead - e.g. break out of the loop with a flag, and on the timeout path re-check lock_owner_is_live in a bounded loop (or reap with kill -0 polling) instead of an unbounded wait.
  • ℹ️ bin/fm-telemetry.sh:164 - The mkdir guard is a breakable lease, so the header's absolute claim at lines 26-27 ("Every lock reclaim-and-republish sequence is serialized by an atomic mkdir guard directory, so a stale lock can never be retired on top of a fresh one") is not guaranteed. guard_age_seconds reads GUARD_DIR's mtime, which is stamped once at mkdir and never refreshed, and guard_acquire rm -rfs any guard older than GUARD_STALE_SECONDS=10 (line 164-166). If holder P1 stalls for more than 10s inside the critical section - acquire_lock runs ps -p via lock_owner_is_live, which can take seconds on the memory-thrashing host this tool targets - P2 deletes P1's guard and mkdirs its own, so both are in the readlink/rm/ln sequence at once and the review-9 race is back: P2's remove_stale_lock can delete a lock P1 has just republished. Worse, guard_release (line 174) rmdirs unconditionally without checking ownership, so P1's exit then removes P2's guard and admits a third process. Consequence is bounded (the displaced recorder stands down at the top of its next loop, up to one FM_TELEMETRY_INTERVAL of two recorders appending to the same daily log), but it is not the "never" the header states. Closing it needs an owner token inside the guard directory that guard_release verifies before rmdir, and a stale-break that re-verifies ownership rather than trusting a fixed 10s lease - or the header claim should be softened to match.
  • ℹ️ bin/fm-telemetry.sh:567 - status reports a stale, benign diagnostic as if it were current. report_diagnostics prints tail -n 1 recorder.err whenever the file is non-empty, and the lines have no timestamps, so an operator cannot tell whether the reported failure happened seconds or weeks ago; the file is only ever cleared by 64 KiB of churn in trim_diagnostics. Concretely, a successful idempotent arm race writes an alarming line into it: two cold arms both pass the checks at lines 470-484, both call nohup ... 2&gt;&gt;&#34;$DIAGNOSTICS_LOG&#34;, and the loser's recorder hits guarded_acquire_lock -> 2 -> fail &#34;recorder already running&#34; (line 435), whose stderr lands in recorder.err. The parent arm then correctly treats this as success (line 501-504) and returns 0, yet every subsequent status on that healthy recorder permanently prints newest diagnostic in .../recorder.err: fm-telemetry: recorder already running. Either timestamp diagnostic lines (so age is visible) or do not route the expected lost-race message into the persisted diagnostics stream.

🔧 Fix: fix(telemetry): bounded arm, owner-verified guard, timestamped diagnostics
2 infos still open:

  • ℹ️ bin/fm-telemetry.sh:527 - arm's acquisition deadline (30 x 0.1s = ~3s, line 527) is shorter than the worst-case wait its own child can legitimately incur, so a healthy starting recorder can be killed and reported as a failure. guard_acquire (line 181) spins up to 200 x 0.05s = 10s while another fm-telemetry process holds the guard, and the child calls it via guarded_acquire_lock before it ever publishes a lock. Concrete sequence: arm A and a concurrent disarm/arm B contend for the guard on a loaded host; A's child sits in guard_acquire past 3s; A exits the poll loop with child_alive=1, read_lock_owner finds no lock (LOCK_PID empty != child_pid), so line 549 TERMs the child and line 560 exits 1 with "recorder did not acquire its lock" - even though nothing was wrong. Worse, the TERM can land after the child published the guard (line 183) or the lock (line 213) but before its traps are installed at line 475, leaving a stale guard or lock symlink behind; both are self-healing on the next arm, but the operator sees an unexplained failure with no recorder running. The already-present re-check at line 556 does not help, because the pid it would name is the one arm just killed. Fix by deriving arm's deadline from the guard ceiling (e.g. >= 12s) rather than a fixed 3s, and/or waiting for the child to leave guard_acquire before treating it as failed.
  • ℹ️ bin/fm-telemetry.sh:333 - The header states at line 35 "Every diagnostic carries a UTC timestamp and status reports the newest one with its age", but the durable-flush helper writes an unstamped line into that exact stream: line 333 emits fm-telemetry: F_FULLFSYNC unsupported for &lt;path&gt; on the helper's stderr, which in record mode is the recorder's stderr, i.e. state/telemetry/recorder.err. report_diagnostics then does stamp=${newest#fm-telemetry: }; stamp=${stamp%% *} (lines 630-631), yielding the literal token F_FULLFSYNC, diagnostic_age fails to parse it, and status prints newest diagnostic (age unknown) .... Reachable whenever state/ lives on a filesystem without F_FULLFSYNC (network mount, non-APFS external volume) - precisely a case where the operator most needs to know how current the warning is. Route that message through the same diagnostic-style fm-telemetry: &lt;utc&gt; &lt;message&gt; shape (or have the shell wrapper stamp helper stderr) so the documented invariant actually holds.
✅ **Test** - passed

✅ No issues found.

  • bash tests/fm-telemetry.test.sh (all 15 behavioral tests pass: snapshot parseability, UTC daily keying, fsync file+directory durability, durability-failure surfacing, temp cleanup, 15-30s cadence validation, rotation to cap, arm idempotency/disarm, tokenless recorder, arm durability probe, bounded diagnostics, guard reclaim, lost start-up race, concurrent-arm convergence)
  • Real operator run with real macOS samplers: FM_HOME=&lt;tmp&gt; FM_TELEMETRY_INTERVAL=15 bin/fm-telemetry.sh arm, repeated arm (same pid), status, disarm, status
  • Forced power-cycle simulation: kill -9 &lt;recorder pid&gt; mid-run, then verified the tail of telemetry-&lt;UTC date&gt;.log ends in a complete SNAPSHOT_END and 7/7 snapshots are begin/end balanced
  • Post-crash recovery: bin/fm-telemetry.sh status reports not running over the stale lock (exit 1), then arm starts a fresh recorder and disarm stops it
  • Snapshot content check on real data: memory_pressure summary, vm_stat, sysctl vm.swapusage, TOP_RSS_KIB and TOP_CPU_PERCENT (15 rows each), PROCESS_TOTAL 798, per-parent and PGID-coalition approximations, df -k /
  • Overhead measurement: /usr/bin/time -p env FM_TELEMETRY_RECORD_ONCE=1 bin/fm-telemetry.sh record x3 (0.04u+0.06s, 0.13s wall per tick) and a 65s ps -o time= window on the armed recorder (0.01 -> 0.05 CPU seconds, 1 child = the sleep)
  • No-auto-arm / no-launchd check: grep -rln fm-telemetry . matches only the script and its test; launchctl list and ~/Library/LaunchAgents show no telemetry job or plist after arming
⚠️ **Document** - 1 info
  • ℹ️ docs/scripts.md:1 - docs/scripts.md is presented as the bin/ toolbelt inventory but is not exhaustive: ~33 existing bin/ scripts and libs (e.g. fm-lint.sh, fm-procevent.sh, fm-startup-memory-budget.sh, fm-stow-cascade.sh, fm-doc-audience-check.sh) have no row. Nothing enforces coverage, so the table silently drifts. A follow-up could either complete it or add a coverage check to bin/fm-doc-audience-check.sh; out of scope for this change.
✅ **Lint** - passed

✅ No issues found.

✅ **Push** - passed

✅ No issues found.

@withally
withally merged commit 6545983 into main Aug 24, 2026
13 checks passed
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.

1 participant