diff --git a/dev-tasks/2026-07-12-answerer-abort-hard-stop-and-reengage-timing.md b/dev-tasks/2026-07-12-answerer-abort-hard-stop-and-reengage-timing.md new file mode 100644 index 0000000..865290f --- /dev/null +++ b/dev-tasks/2026-07-12-answerer-abort-hard-stop-and-reengage-timing.md @@ -0,0 +1,301 @@ +# Handoff: D-CALLER-018/016/019 — Abort must be a hard stop; re-engagement is needlessly delayed 30 s + +**Date:** 2026-07-12 +**Prepared by:** QA engineer (analysis of `logs/openswfz-20260712T211150Z.log`, Captain report) +**Status:** Awaiting developer action +**Defect IDs:** D-CALLER-018 (critical), D-CALLER-016 (high), D-CALLER-019 (medium, cleanup) +**Severity:** Critical — the operator's Abort action does not reliably stop the transmitter, and once +that happens there is currently **no recourse**: the armed engagement fires regardless of how many +times Abort is clicked. This is a repeat of the abort-race family first seen in D-CALLER-009/010; this +occurrence is a new root cause, not a regression of the earlier fix. + +--- + +## 0. Captain's stated requirement (authoritative — design to this) + +> Abort just means stop all and everything, bring the application to an idle state. Do not engage TX +> again unless the operator decides otherwise. When double-clicking a QSO already engaged it should +> switch to resume the QSO. When double-clicking a new CQ it should engage on the new one. And, not to +> forget, when a CQ is double-clicked it should engage immediately at the very first opportunity instead +> of waiting 30 seconds before engaging. + +Three separate defects below implement this. Read D-CALLER-018 first — it is the one that actually +explains the reported "it engages after an abort" behaviour. + +--- + +## 1. Context + +### 1.1 What the log shows + +Across `logs/openswfz-20260712T211150Z.log`, the Answerer engaged CX1RL three times in a row, ~29–30 s +apart, despite the operator aborting every single time: + +``` +23:18:30.754 pending CQ target 'CX1RL' — answering at A phase +23:18:30.766 KeyDown — PTT asserted +23:18:31.779 TX abort requested (HTTP) — cancelling active session (partner: CX1RL, state: TxAnswer) +23:18:31.861 KeyUp — PTT released +23:18:31.878 aborted to Idle (was: TxAnswer, partner: CX1RL) +23:18:31.892 pending target 'CX1RL' — late start (1.9 s into window); deferring to next occurrence ← re-armed, same request +23:18:36.599–23:18:38.427 FOURTEEN POST /api/v1/tx/abort calls, all 200 OK, all no-ops (state already Idle) +23:19:00.776 pending CQ target 'CX1RL' — answering at A phase ← fires anyway, 29 s later +23:19:00.778 KeyDown — PTT asserted +``` + +The same pattern repeats for LU1DA (23:13:30→23:14:00) and ZL4TT (23:17:30). This is not one glitch; it +is the system working exactly as coded, which is the problem. + +### 1.2 Root cause chain + +- `POST /api/v1/tx/engage-decode` (D-CALLER-012, `WebApp.cs` line 1251) is a **double-click** gesture: + abort whatever is running, then dispatch the clicked row (`AnswerCqAsync` for a `CQ ...` row, + `EngageAtAsync` for a directed report/RR73/73 row). This is legitimate, explicit operator intent — + double-clicking a row is asking to engage it — and per the Captain's requirement above, it is correct + for it to arm a fresh target immediately, including re-answering the same partner if they're still + calling CQ. +- The problem is that the **dedicated Abort button** (`POST /api/v1/tx/abort` → `QsoAnswererService.AbortAsync`, + line 257) cannot cancel that armed target once `_state` has returned to `Idle`: + + ```csharp + public async Task AbortAsync(CancellationToken ct = default) + { + if (_state == QsoState.Idle) return; // ← everything below is skipped, INCLUDING clearing + // _pendingTargetCallsign / _jumpPartner + ... + } + ``` + + `_pendingTargetCallsign` (armed by `AnswerCqAsync`/`ArmPendingTarget`, line 387) and `_jumpPartner` + (armed by `EngageAtAsync`, line 229) are **independent of `_state`** — they are consulted at the top of + `HandleIdleAsync` (lines 564 and 632) specifically so they can fire *while* Idle. Only + `SafeAbortToIdleAsync` (line 1263) clears them, and that method only runs as part of a state + transition *out of* an active session — never when the service is already sitting Idle with a pending + target quietly waiting for its window. + + Net effect: once a target is armed, the Abort button is a no-op for the remainder of that ~60 s + window (the 14 clicks at 23:18:36–38 prove this) and the engagement **will** fire. There is currently + no operator action that can prevent it. This directly contradicts "do not engage TX again unless the + operator decides otherwise." + +### 1.3 Secondary finding: needless 30 s delay + +`MaxLateStartSeconds = 1.5` (`QsoAnswererService.cs` line 139, added by D-CALLER-013) leaves very little +room: an FT8 tone is 12.64 s in a 15 s window, so the true physical ceiling is `15 − 12.64 = 2.36 s`. +Decode processing alone consumes 0.4–0.7 s in this log before a click is even possible. Every +manually-armed engagement in this session — both the original clicks and the abort-triggered +re-engagements — landed at 1.9 s or 3.7 s into its window, both past the 1.5 s cutoff, and both were +deferred a full 30 s (phase alternates every 15 s, so the next *matching-phase* window is always two +cycles away, never one). This is the "always skips two cycles" / "waiting 30 seconds" complaint. + +### 1.4 Tertiary finding: duplicate double-click handlers (noise, not the root cause) + +Every CQ row in `web/js/main.js` carries **two** independent `dblclick` listeners: + +- Line 733 (TX-D01, pre-dates D-CALLER-012): calls `postTxAnswerCq(...)` directly. +- Line 847 (D-CALLER-012): calls `postTxEngageDecode(...)` — abort, then dispatch, and its own + `Case A` (WebApp.cs line 1318) already reproduces exactly what the line-733 handler does. + +A single double-click fires both. The line-733 call always loses the race and returns 409 (log lines +894/910, 360/376, etc.) — harmless, but it is dead code doubling every double-click's network traffic +and cluttering the log with a guaranteed spurious 409 on every single engagement. Worth removing while +in this code, but it is not what caused the reported behaviour — D-CALLER-012's own Step 1 abort is +what's logged as "TX abort requested (HTTP)" in every instance above, not a separate Abort-button click. + +--- + +## 2. Branch + +Create a new branch off `main`: `fix/d-caller-018-abort-hard-stop`. No branch of this name currently +exists (verified 2026-07-12) and this is not an amendment to any in-flight work — start clean from `main`. + +--- + +## 3. Actions + +### 3.1 — D-CALLER-018: `AbortAsync` must unconditionally clear armed targets (Critical) + +**File:** `src/OpenWSFZ.Daemon/QsoAnswererService.cs`, `AbortAsync` (currently lines 257–280). + +Move the pending-target/jump-in clear (the same fields `SafeAbortToIdleAsync` clears at lines +1274–1278) **above** the `Idle` guard, so it always runs regardless of `_state`: + +```csharp +public async Task AbortAsync(CancellationToken ct = default) +{ + // D-CALLER-018: unconditionally clear any armed-but-not-yet-fired pending target or + // jump-in, regardless of current _state. A target armed by AnswerCqAsync / EngageAtAsync / + // TryEngageExternal fires independently of _state (it is specifically checked while Idle — + // see HandleIdleAsync). Previously this method returned immediately whenever _state was + // already Idle, which meant an armed target could NOT be cancelled by the operator once the + // service returned to Idle — it fired regardless, up to ~30 s later, no matter how many times + // Abort was clicked. Abort must be an unconditional hard stop: nothing may re-engage after it + // until the operator explicitly requests it again. See + // dev-tasks/2026-07-12-answerer-abort-hard-stop-and-reengage-timing.md. + lock (_stateLock) + { + _pendingTargetCallsign = null; + _pendingTargetFrequencyHz = 0.0; + _pendingTargetIsAPhase = false; + _pendingTargetSetAt = default; + _jumpPartner = null; + } + + if (_state == QsoState.Idle) return; + + _logger.LogInformation( + "TX abort requested (HTTP) — cancelling active session (partner: {Partner}, state: {State}).", + _partner, _state); + + _operatorAbortRequested = true; + _txCts.Cancel(); + + try + { + await _pttController.KeyUpAsync(ct).ConfigureAwait(false); + } + catch (Exception ex) + { + _logger.LogWarning(ex, "KeyUpAsync threw during abort — ignoring."); + } +} +``` + +No change needed to `SafeAbortToIdleAsync` — its own clear is now redundant in the pure-Abort path but +still correct/necessary for the watchdog-timeout and retry-exhaustion paths that don't go through +`AbortAsync` at all. + +**Do not** add any additional "latch" or cool-down flag. `engage-decode`'s Step 1 also calls +`AbortAsync`, then Step 2 deliberately re-arms a fresh target — that re-arm is a *new*, explicit operator +gesture (the double-click itself) and must keep working exactly as today. The fix above only guarantees +that a *separate, later* Abort-button click always wins and leaves nothing armed — it does not prevent +`engage-decode`'s own Step 2 from arming within the same request. + +### 3.2 — D-CALLER-016: raise the late-start threshold (High) + +**File:** `src/OpenWSFZ.Daemon/QsoAnswererService.cs`, line 139. + +```csharp +/// +/// Maximum number of seconds into a 15-second FT8 window that TX may still be started. +/// An FT8 signal is 12.64 s; the true physical ceiling is 15 - 12.64 = 2.36 s — starting any +/// later overruns into the next window and can prevent the far station from decoding cleanly. +/// D-CALLER-013 originally set this to 1.5 s, leaving only ~0.8-1.0 s of realistic click budget +/// after decode processing (0.4-0.7 s observed) — in practice this meant almost every manual +/// click (openswfz-20260712T211150Z.log: 1.9 s and 3.7 s observed) missed its window and was +/// deferred a full 30 s (phase alternates every 15 s, so the next matching-phase window is +/// always two cycles away, never one — see D-CALLER-016). 2.0 s leaves a 0.36 s hard safety +/// margin against overrun, comfortably covering the ~50-90 ms KeyDown/device-open jitter observed +/// in production logs, while catching realistic decode-to-click latency instead of nearly always +/// missing it. +/// +private const double MaxLateStartSeconds = 2.0; +``` + +Be honest in the PR description and with the Captain: this reduces *how often* the 30 s deferral is hit, +it does not eliminate it. A click that lands beyond ~2.3 s into its window genuinely cannot start a +12.64 s FT8 transmission in that window without overrunning — that remaining wait is FT8 protocol +physics (alternating 15 s slots), not a bug, and no threshold tuning removes it. Update the existing +D-CALLER-013 tests (`QsoAnswererServiceTests.cs` lines ~2351–2521) that assert the exact +`MaxLateStartSeconds` boundary — they currently use 1.5 s and 5 s/0.5 s/0.2 s fixtures; adjust the +"late" fixtures to land clearly past 2.0 s (e.g. keep 5 s) and the "timely" fixtures to land clearly +under it (e.g. keep 0.5 s, 0.2 s — both still pass) so the tests remain meaningful rather than just +re-encoding whatever the new constant is. + +### 3.3 — D-CALLER-019: remove the redundant legacy dblclick handler (Medium, cleanup) + +**File:** `web/js/main.js`, lines 727–776 (the TX-D01 `.decode-cq` dblclick handler that calls +`postTxAnswerCq` directly). + +Remove this block entirely. `D-CALLER-012`'s handler (line 841 onward) already reproduces it exactly: +its `Case A` dispatch (`WebApp.cs` line 1318) parses a `CQ ...` message and calls the identical +`AnswerCqAsync`, and additionally handles the abort-first step this old handler never did. Keeping both +means every CQ-row double-click fires two competing HTTP requests, one of which is guaranteed to lose +and return 409 — pure noise that made this session's log harder to diagnose. Confirm no other code +depends on the `inFlight` guard or `cqCycleStartUtc` dataset attribute this block referenced (the D-CALLER-012 +handler reads `tr.dataset.cqCycleStartUtc` independently at line 855, so it is unaffected by the removal). + +`postTxAnswerCq` itself (`web/js/api.js`) should remain — it is still the function `engage-decode`'s +front-end awaits indirectly is not — check whether anything else in `main.js` calls `postTxAnswerCq` +directly before deleting its import; if nothing else does, remove the now-unused import too. + +--- + +## 4. Acceptance criteria + +**AC-1 (D-CALLER-018).** With a pending target armed (e.g. via `engage-decode`) and the service already +back at `Idle`, clicking Abort clears the pending target. Confirm: advance time/inject the next +matching-phase batch and assert `IPttController.KeyDownAsync` is **not** called. Add this as an explicit +unit test in `QsoAnswererServiceTests.cs` — arm via `AnswerCqAsync` with a late-start time so it doesn't +fire immediately, call `AbortAsync`, then push the correct-phase batch and assert no TX. + +**AC-2 (D-CALLER-018).** Same as AC-1 but for a jump-in target (`EngageAtAsync`) instead of a pending +CQ target. + +**AC-3 (D-CALLER-018).** Regression: `AbortAsync` while genuinely mid-TX still cancels the active +transmission exactly as before (existing `AbortAsync` tests must continue to pass unmodified). + +**AC-4 (D-CALLER-016).** A click landing ≤2.0 s into the correct-phase window fires TX in that same +window. A click landing >2.0 s is deferred to the next matching-phase window (~30 s later) — update +existing D-CALLER-013 tests per §3.2 rather than duplicating them. + +**AC-5 (D-CALLER-019).** Double-clicking a CQ row produces exactly one outbound POST +(`/api/v1/tx/engage-decode`), not two. Confirm in the Network tab or via a front-end test that +`postTxAnswerCq` is no longer wired to CQ-row `dblclick`. + +**AC-6 (end-to-end, matches the Captain's stated requirement — verify with the `verify` skill against a +real session, not just unit tests).** +- Abort while mid-QSO with any partner → service reaches Idle and stays there; no TX fires afterward + regardless of what CQs continue to be decoded, until the operator takes a new explicit action. +- Double-clicking the CQ row of the station currently engaged → resumes/re-engages that same partner + (no behavioural change required here beyond AC-4's timing fix — `engage-decode`'s existing dispatch + already does this correctly once 3.1/3.2 land). +- Double-clicking a different station's CQ row while mid-QSO → aborts the current session and engages + the new one (existing D-CALLER-012 behaviour, unchanged). +- None of the above engagements take the needless extra 15 s cycle that 3.2 fixes. + +**AC-7.** `dotnet build OpenWSFZ.slnx -c Release` — 0 errors, 0 warnings. + +**AC-8.** Full test suite — 0 failures (current baseline ≥948 passed per project state notes; new/updated +tests add to the count). + +--- + +## 5. Live verification requirement + +This defect was only caught by reading a real operating log, not by unit tests — the existing D-CALLER-013 +unit tests all passed while this was broken, because none of them exercised "Abort while a target is +armed but the service is already Idle." Before merge, run a real loopback session (VB-CABLE or equivalent, +per the D-CALLER-013/014 annex notes on audio isolation) reproducing the exact sequence from +§1.1 — engage, abort mid-TX, then hammer the Abort button — and attach the resulting log excerpt to the +PR showing no re-engagement occurs. Unit tests alone are not sufficient sign-off for this class of defect. + +--- + +## 6. References + +- Evidence log: `logs/openswfz-20260712T211150Z.log` — lines 887–1115 (CX1RL sequence, most complete), + 296–392 (LU1DA), 683–733 (ZL4TT) +- `src/OpenWSFZ.Daemon/QsoAnswererService.cs`: + - `AbortAsync` — lines 257–280 (fix target, §3.1) + - `MaxLateStartSeconds` — line 139 (fix target, §3.2) + - `SafeAbortToIdleAsync` pending/jump clear — lines 1271–1279 (pattern to replicate in §3.1) + - `ArmPendingTarget` — lines 387–412 + - Pending-target consumption — lines 632–712 + - Jump-in consumption — lines 564–629 +- `src/OpenWSFZ.Web/WebApp.cs`: + - `POST /api/v1/tx/abort` — lines 1101–1117 + - `POST /api/v1/tx/engage-decode` — lines 1251–1408 (Step 1 abort-and-poll at 1282–1303, Step 2 + dispatch at 1305–1396) +- `web/js/main.js`: + - TX-D01 legacy CQ-row dblclick handler — lines 727–776 (removal target, §3.3) + - D-CALLER-012 dblclick handler — lines 841–887 + - Dedicated Abort button handler — lines 1366–1385 (unaffected; the bug was server-side) +- `dev-tasks/2026-06-27-d-caller-013-late-tx-guard.md` — original `MaxLateStartSeconds` rationale + (1.5 s chosen without production click-latency data; this task supersedes that value) +- `dev-tasks/2026-06-26-d-caller-009-rearm-race.md`, `dev-tasks/2026-06-27-d-caller-010-dblclick-abort.md` + — prior occurrences of the same abort-race defect family, on the Caller side; different root cause, + same category of mistake (assuming an abort-adjacent action has fully settled when it hasn't, or that + "Idle" implies "nothing pending") +- `tests/OpenWSFZ.Daemon.Tests/QsoAnswererServiceTests.cs` lines 2351–2521 — existing D-CALLER-013 + late-start tests to extend (§3.1 new tests) and adjust (§3.2) diff --git a/qa/d-caller-018-abort-hard-stop-live-verify/README.md b/qa/d-caller-018-abort-hard-stop-live-verify/README.md new file mode 100644 index 0000000..c56c4d8 --- /dev/null +++ b/qa/d-caller-018-abort-hard-stop-live-verify/README.md @@ -0,0 +1,51 @@ +# D-CALLER-018/016 abort hard-stop — live verification + +`live_verify_abort_hardstop.py` is the live, hardware-in-the-loop verification required by +`dev-tasks/2026-07-12-answerer-abort-hard-stop-and-reengage-timing.md` §5. It starts a real, +isolated `OpenWSFZ.Daemon` instance (own scratch port/config, never touches the Captain's real +config) and drives it over its real HTTP/WebSocket API — no `FakeTimeProvider`, no mocked +`IPttController` — reproducing the exact production sequence from +`logs/openswfz-20260712T211150Z.log` (arm a pending CQ target, let the late-start guard defer it, +hammer the dedicated Abort button while Idle, wait past the next matching-phase window, confirm no +re-engagement). + +Run it after `dotnet build OpenWSFZ.slnx -c Release`: + +``` +python qa/d-caller-018-abort-hard-stop-live-verify/live_verify_abort_hardstop.py +``` + +Requires a real audio output device (no virtual cable needed — `AudioOnlyPttController`'s CQ +transmission doesn't require a decode input). Exit 0 = PASS, 1 = FAIL, 2 = ENVIRONMENT-UNAVAILABLE +(report still written in that case). + +## `live-reports/` — what's in here + +- **`2026-07-12T221248Z-d3eff84.md` — PASS.** Run against the fix (`AbortAsync`'s unconditional + clear + `MaxLateStartSeconds = 2.0`). Both phases pass: A (sanity control — a timely arm fires a + real transmission, then Abort mid-TX stops it promptly — AC-3 live regression) and B (the actual + defect — a late-armed target is hammered with Abort while Idle, then never fires ~30 s later). +- **`2026-07-12T221403Z-d3eff84.md` — FAIL, deliberate control run.** Same script, run with + `QsoAnswererService.cs`'s fix temporarily reverted (`git stash` of just that file) to prove the + script actually catches the regression rather than false-passing. Phase B fails exactly as the + production log did: `Q9BUG` fires ~29 s after the 14-click Abort hammer + (`"QsoAnswererService: pending CQ target 'Q9BUG' at 1600 Hz - answering at A phase."` in the log + tail). The fix was restored and rebuilt immediately after this run. +- **`2026-07-12T221518Z-d3eff84.md` — PASS.** Final confirmation run with the fix restored, kept + as the PR's attached evidence per dev-task §5. + +(An earlier run, `2026-07-12T221048Z-d3eff84.md`, failed on a script bug — a regex requiring the +literal em dash `—` that the daemon's console sink silently downgrades to a plain hyphen on +Windows, the same encoding gotcha `qa/tx-keying-live-verify/live_verify_keying.py` already +documents — not a product bug. Fixed in the script and the report was deleted to avoid confusion.) + +## AC-5 (D-CALLER-019 front-end cleanup) — verified separately, not by this script + +The `web/js/main.js` dblclick-handler cleanup (removing the redundant legacy `postTxAnswerCq` +listener) was verified live in a real headless Chromium browser against a real running daemon: +loaded the real `index.html`, injected a synthetic `decode` WebSocket frame so the real, +unmodified `handleDecodes()` created a real ``, then performed a real +browser double-click on it. Result: exactly one outbound `POST /api/v1/tx/engage-decode`, zero +`POST /api/v1/tx/answer-cq` calls, zero console errors. That one-off Playwright driver was not +committed (this repo has no Node/Playwright dependency anywhere else) — the result is recorded +here for the record; see the PR description for the raw evidence. diff --git a/qa/d-caller-018-abort-hard-stop-live-verify/live-reports/2026-07-12T221248Z-d3eff84.md b/qa/d-caller-018-abort-hard-stop-live-verify/live-reports/2026-07-12T221248Z-d3eff84.md new file mode 100644 index 0000000..ac45c26 --- /dev/null +++ b/qa/d-caller-018-abort-hard-stop-live-verify/live-reports/2026-07-12T221248Z-d3eff84.md @@ -0,0 +1,51 @@ +# D-CALLER-018/016 — Abort hard-stop live verification + +- **Run at (UTC):** 2026-07-12T22:12:48.012619+00:00 +- **Git commit:** `d3eff84` (branch `fix/d-caller-018-abort-hard-stop`) +- **Script:** `qa/d-caller-018-abort-hard-stop-live-verify/live_verify_abort_hardstop.py` +- **Dev-task:** `dev-tasks/2026-07-12-answerer-abort-hard-stop-and-reengage-timing.md` §5 + +## WebSocket `txState` events received (UTC wall clock) + +| # | Wall-clock (UTC) | state | partner | keying | +|---|---|---|---|---| +| 1 | `2026-07-12T22:12:00.171+00:00` | `TxAnswer` | `Q9CTRL` | `False` | +| 2 | `2026-07-12T22:12:00.179+00:00` | `TxAnswer` | `Q9CTRL` | `True` | +| 3 | `2026-07-12T22:12:00.294+00:00` | `TxAnswer` | `Q9CTRL` | `False` | +| 4 | `2026-07-12T22:12:00.297+00:00` | `Idle` | `None` | `False` | + +## Result + +**PASS** + +## Notes + +Binary under test: `D:\Projects\claude\OpenWSFZ\src\OpenWSFZ.Daemon\bin\Release\net10.0\OpenWSFZ.Daemon.exe` +Binary last-write time (UTC): `2026-07-12T22:00:17.718254+00:00` +QsoAnswererService.cs last-write time (UTC): `2026-07-12T22:00:15.132822+00:00` +Daemon process start time (UTC): `2026-07-12T22:11:49.158859+00:00` +Rebuild check: compiled binary postdates the source edits = `True`; process started after binary was built = `True` + +### Phase A — sanity control (timely arm) + AC-3 live regression (abort mid-TX) + +Arming `Q9CTRL` at `2026-07-12T22:12:00Z` — 0.15 s into window `2026-07-12T22:12:00Z` (timely, ≤ 2.0 s) — expect immediate fire. +POST /api/v1/tx/answer-cq (Q9CTRL) → HTTP 200 +Real `keying: true` observed for `Q9CTRL`: `True` +POST /api/v1/tx/abort (mid-TX, at `2026-07-12T22:12:00Z`) → HTTP 200 +`keying: false` observed after mid-TX abort: `True` +GET /api/v1/tx/status after Phase A abort: `{'state': 'Idle', 'partner': None, 'autoAnswerEnabled': False, 'role': 'answerer', 'callerPartnerSelect': 'First', 'keying': False}` +**Phase A result: PASS** + +### Phase B — D-CALLER-018 repro: hammer Abort while Idle with a deferred target + +Arming `Q9BUG` at `2026-07-12T22:12:22Z` — 7.00 s into window `2026-07-12T22:12:15Z` (late, > 2.0 s) — expect deferral, no fire. +POST /api/v1/tx/answer-cq (Q9BUG) → HTTP 200 +Late-start deferral log line found for `Q9BUG`: `True` (7.0 s into window) +No transmission for `Q9BUG` fired on the first (late) window: `True` +Hammered POST /api/v1/tx/abort x14 while Idle (2026-07-12T22:12:23Z .. 2026-07-12T22:12:24Z) — statuses: [200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200] +Waiting until `2026-07-12T22:12:48Z` (next matching-phase window `2026-07-12T22:12:45Z` + 3 s buffer) to confirm no re-engagement... +GET /api/v1/tx/status after wait: `{'state': 'Idle', 'partner': None, 'autoAnswerEnabled': False, 'role': 'answerer', 'callerPartnerSelect': 'First', 'keying': False}` +'answering at ... phase' log line ever appeared for `Q9BUG` (would prove re-engagement): `False` +No WS txState event names `Q9BUG` as partner after the abort hammer: `True` +**Phase B result: PASS** + diff --git a/qa/d-caller-018-abort-hard-stop-live-verify/live-reports/2026-07-12T221403Z-d3eff84.md b/qa/d-caller-018-abort-hard-stop-live-verify/live-reports/2026-07-12T221403Z-d3eff84.md new file mode 100644 index 0000000..bd4e1dd --- /dev/null +++ b/qa/d-caller-018-abort-hard-stop-live-verify/live-reports/2026-07-12T221403Z-d3eff84.md @@ -0,0 +1,177 @@ +# D-CALLER-018/016 — Abort hard-stop live verification + +- **Run at (UTC):** 2026-07-12T22:14:03.027221+00:00 +- **Git commit:** `d3eff84` (branch `fix/d-caller-018-abort-hard-stop`) +- **Script:** `qa/d-caller-018-abort-hard-stop-live-verify/live_verify_abort_hardstop.py` +- **Dev-task:** `dev-tasks/2026-07-12-answerer-abort-hard-stop-and-reengage-timing.md` §5 + +## WebSocket `txState` events received (UTC wall clock) + +| # | Wall-clock (UTC) | state | partner | keying | +|---|---|---|---|---| +| 1 | `2026-07-12T22:13:15.171+00:00` | `TxAnswer` | `Q9CTRL` | `False` | +| 2 | `2026-07-12T22:13:15.177+00:00` | `TxAnswer` | `Q9CTRL` | `True` | +| 3 | `2026-07-12T22:13:15.296+00:00` | `TxAnswer` | `Q9CTRL` | `False` | +| 4 | `2026-07-12T22:13:15.298+00:00` | `Idle` | `None` | `False` | +| 5 | `2026-07-12T22:14:00.189+00:00` | `TxAnswer` | `Q9BUG` | `False` | +| 6 | `2026-07-12T22:14:00.192+00:00` | `TxAnswer` | `Q9BUG` | `True` | + +## Result + +**FAIL** + +## Notes + +Binary under test: `D:\Projects\claude\OpenWSFZ\src\OpenWSFZ.Daemon\bin\Release\net10.0\OpenWSFZ.Daemon.exe` +Binary last-write time (UTC): `2026-07-12T22:12:57.964266+00:00` +QsoAnswererService.cs last-write time (UTC): `2026-07-12T22:12:52.960224+00:00` +Daemon process start time (UTC): `2026-07-12T22:13:06.356628+00:00` +Rebuild check: compiled binary postdates the source edits = `True`; process started after binary was built = `True` + +### Phase A — sanity control (timely arm) + AC-3 live regression (abort mid-TX) + +Arming `Q9CTRL` at `2026-07-12T22:13:15Z` — 0.15 s into window `2026-07-12T22:13:15Z` (timely, ≤ 2.0 s) — expect immediate fire. +POST /api/v1/tx/answer-cq (Q9CTRL) → HTTP 200 +Real `keying: true` observed for `Q9CTRL`: `True` +POST /api/v1/tx/abort (mid-TX, at `2026-07-12T22:13:15Z`) → HTTP 200 +`keying: false` observed after mid-TX abort: `True` +GET /api/v1/tx/status after Phase A abort: `{'state': 'Idle', 'partner': None, 'autoAnswerEnabled': False, 'role': 'answerer', 'callerPartnerSelect': 'First', 'keying': False}` +**Phase A result: PASS** + +### Phase B — D-CALLER-018 repro: hammer Abort while Idle with a deferred target + +Arming `Q9BUG` at `2026-07-12T22:13:37Z` — 7.00 s into window `2026-07-12T22:13:30Z` (late, > 2.0 s) — expect deferral, no fire. +POST /api/v1/tx/answer-cq (Q9BUG) → HTTP 200 +Late-start deferral log line found for `Q9BUG`: `True` (7.0 s into window) +No transmission for `Q9BUG` fired on the first (late) window: `True` +Hammered POST /api/v1/tx/abort x14 while Idle (2026-07-12T22:13:38Z .. 2026-07-12T22:13:39Z) — statuses: [200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200] +Waiting until `2026-07-12T22:14:03Z` (next matching-phase window `2026-07-12T22:14:00Z` + 3 s buffer) to confirm no re-engagement... +GET /api/v1/tx/status after wait: `{'state': 'TxAnswer', 'partner': 'Q9BUG', 'autoAnswerEnabled': False, 'role': 'answerer', 'callerPartnerSelect': 'First', 'keying': True}` +'answering at ... phase' log line ever appeared for `Q9BUG` (would prove re-engagement): `True` +No WS txState event names `Q9BUG` as partner after the abort hammer: `False` +**Phase B result: FAIL** + + +**Daemon log tail (last 120 lines) — diagnostic aid on failure:** +``` +[00:13:38 INF] Writing value of type 'TxStatusResponse' as Json. +[00:13:38 INF] Executed endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:38 INF] Request finished HTTP/1.1 POST http://127.0.0.1:18768/api/v1/tx/abort - 200 null application/json; charset=utf-8 1.5407ms +[00:13:38 DBG] Connection id "0HNN0CB02PM1A", Request id "0HNN0CB02PM1A:00000001": started reading request body. +[00:13:38 DBG] Connection id "0HNN0CB02PM1A", Request id "0HNN0CB02PM1A:00000001": done reading request body. +[00:13:38 DBG] Connection id "0HNN0CB02PM1A" disconnecting. +[00:13:38 DBG] Connection id "0HNN0CB02PM1A" stopped. +[00:13:38 DBG] Connection id "0HNN0CB02PM1A" sending FIN because: "The Socket transport's send loop completed gracefully." +[00:13:38 DBG] Connection id "0HNN0CB02PM1B" accepted. +[00:13:38 DBG] Connection id "0HNN0CB02PM1B" started. +[00:13:38 INF] Request starting HTTP/1.1 POST http://127.0.0.1:18768/api/v1/tx/abort - application/json 2 +[00:13:38 DBG] 1 candidate(s) found for the request path '/api/v1/tx/abort' +[00:13:38 DBG] Request matched endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:38 DBG] Static files was skipped as the request already matched an endpoint. +[00:13:38 INF] Executing endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:38 INF] Setting HTTP status code 200. +[00:13:38 INF] Writing value of type 'TxStatusResponse' as Json. +[00:13:38 INF] Executed endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:38 INF] Request finished HTTP/1.1 POST http://127.0.0.1:18768/api/v1/tx/abort - 200 null application/json; charset=utf-8 1.012ms +[00:13:38 DBG] Connection id "0HNN0CB02PM1B", Request id "0HNN0CB02PM1B:00000001": started reading request body. +[00:13:38 DBG] Connection id "0HNN0CB02PM1B", Request id "0HNN0CB02PM1B:00000001": done reading request body. +[00:13:38 DBG] Connection id "0HNN0CB02PM1B" disconnecting. +[00:13:38 DBG] Connection id "0HNN0CB02PM1B" stopped. +[00:13:38 DBG] Connection id "0HNN0CB02PM1B" sending FIN because: "The Socket transport's send loop completed gracefully." +[00:13:39 DBG] Connection id "0HNN0CB02PM1C" accepted. +[00:13:39 DBG] Connection id "0HNN0CB02PM1C" started. +[00:13:39 INF] Request starting HTTP/1.1 POST http://127.0.0.1:18768/api/v1/tx/abort - application/json 2 +[00:13:39 DBG] 1 candidate(s) found for the request path '/api/v1/tx/abort' +[00:13:39 DBG] Request matched endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 DBG] Static files was skipped as the request already matched an endpoint. +[00:13:39 INF] Executing endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 INF] Setting HTTP status code 200. +[00:13:39 INF] Writing value of type 'TxStatusResponse' as Json. +[00:13:39 INF] Executed endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 INF] Request finished HTTP/1.1 POST http://127.0.0.1:18768/api/v1/tx/abort - 200 null application/json; charset=utf-8 1.1806ms +[00:13:39 DBG] Connection id "0HNN0CB02PM1C", Request id "0HNN0CB02PM1C:00000001": started reading request body. +[00:13:39 DBG] Connection id "0HNN0CB02PM1C", Request id "0HNN0CB02PM1C:00000001": done reading request body. +[00:13:39 DBG] Connection id "0HNN0CB02PM1C" disconnecting. +[00:13:39 DBG] Connection id "0HNN0CB02PM1C" stopped. +[00:13:39 DBG] Connection id "0HNN0CB02PM1C" sending FIN because: "The Socket transport's send loop completed gracefully." +[00:13:39 DBG] Connection id "0HNN0CB02PM1D" accepted. +[00:13:39 DBG] Connection id "0HNN0CB02PM1D" started. +[00:13:39 INF] Request starting HTTP/1.1 POST http://127.0.0.1:18768/api/v1/tx/abort - application/json 2 +[00:13:39 DBG] 1 candidate(s) found for the request path '/api/v1/tx/abort' +[00:13:39 DBG] Request matched endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 DBG] Static files was skipped as the request already matched an endpoint. +[00:13:39 INF] Executing endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 INF] Setting HTTP status code 200. +[00:13:39 INF] Writing value of type 'TxStatusResponse' as Json. +[00:13:39 INF] Executed endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 INF] Request finished HTTP/1.1 POST http://127.0.0.1:18768/api/v1/tx/abort - 200 null application/json; charset=utf-8 1.3044ms +[00:13:39 DBG] Connection id "0HNN0CB02PM1D", Request id "0HNN0CB02PM1D:00000001": started reading request body. +[00:13:39 DBG] Connection id "0HNN0CB02PM1D", Request id "0HNN0CB02PM1D:00000001": done reading request body. +[00:13:39 DBG] Connection id "0HNN0CB02PM1D" disconnecting. +[00:13:39 DBG] Connection id "0HNN0CB02PM1D" stopped. +[00:13:39 DBG] Connection id "0HNN0CB02PM1D" sending FIN because: "The Socket transport's send loop completed gracefully." +[00:13:39 DBG] Connection id "0HNN0CB02PM1E" accepted. +[00:13:39 DBG] Connection id "0HNN0CB02PM1E" started. +[00:13:39 INF] Request starting HTTP/1.1 POST http://127.0.0.1:18768/api/v1/tx/abort - application/json 2 +[00:13:39 DBG] 1 candidate(s) found for the request path '/api/v1/tx/abort' +[00:13:39 DBG] Request matched endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 DBG] Static files was skipped as the request already matched an endpoint. +[00:13:39 INF] Executing endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 INF] Setting HTTP status code 200. +[00:13:39 INF] Writing value of type 'TxStatusResponse' as Json. +[00:13:39 INF] Executed endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 INF] Request finished HTTP/1.1 POST http://127.0.0.1:18768/api/v1/tx/abort - 200 null application/json; charset=utf-8 1.3724ms +[00:13:39 DBG] Connection id "0HNN0CB02PM1E", Request id "0HNN0CB02PM1E:00000001": started reading request body. +[00:13:39 DBG] Connection id "0HNN0CB02PM1E", Request id "0HNN0CB02PM1E:00000001": done reading request body. +[00:13:39 DBG] Connection id "0HNN0CB02PM1E" disconnecting. +[00:13:39 DBG] Connection id "0HNN0CB02PM1E" stopped. +[00:13:39 DBG] Connection id "0HNN0CB02PM1E" sending FIN because: "The Socket transport's send loop completed gracefully." +[00:13:39 DBG] Connection id "0HNN0CB02PM1F" accepted. +[00:13:39 DBG] Connection id "0HNN0CB02PM1F" started. +[00:13:39 INF] Request starting HTTP/1.1 POST http://127.0.0.1:18768/api/v1/tx/abort - application/json 2 +[00:13:39 DBG] 1 candidate(s) found for the request path '/api/v1/tx/abort' +[00:13:39 DBG] Request matched endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 DBG] Static files was skipped as the request already matched an endpoint. +[00:13:39 INF] Executing endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 INF] Setting HTTP status code 200. +[00:13:39 INF] Writing value of type 'TxStatusResponse' as Json. +[00:13:39 INF] Executed endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 INF] Request finished HTTP/1.1 POST http://127.0.0.1:18768/api/v1/tx/abort - 200 null application/json; charset=utf-8 0.991ms +[00:13:39 DBG] Connection id "0HNN0CB02PM1F", Request id "0HNN0CB02PM1F:00000001": started reading request body. +[00:13:39 DBG] Connection id "0HNN0CB02PM1F", Request id "0HNN0CB02PM1F:00000001": done reading request body. +[00:13:39 DBG] Connection id "0HNN0CB02PM1F" disconnecting. +[00:13:39 DBG] Connection id "0HNN0CB02PM1F" stopped. +[00:13:39 DBG] Connection id "0HNN0CB02PM1F" sending FIN because: "The Socket transport's send loop completed gracefully." +[00:13:39 DBG] Connection id "0HNN0CB02PM1G" accepted. +[00:13:39 DBG] Connection id "0HNN0CB02PM1G" started. +[00:13:39 INF] Request starting HTTP/1.1 POST http://127.0.0.1:18768/api/v1/tx/abort - application/json 2 +[00:13:39 DBG] 1 candidate(s) found for the request path '/api/v1/tx/abort' +[00:13:39 DBG] Request matched endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 DBG] Static files was skipped as the request already matched an endpoint. +[00:13:39 INF] Executing endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 INF] Setting HTTP status code 200. +[00:13:39 INF] Writing value of type 'TxStatusResponse' as Json. +[00:13:39 INF] Executed endpoint 'HTTP: POST /api/v1/tx/abort' +[00:13:39 INF] Request finished HTTP/1.1 POST http://127.0.0.1:18768/api/v1/tx/abort - 200 null application/json; charset=utf-8 1.1347ms +[00:13:39 DBG] Connection id "0HNN0CB02PM1G", Request id "0HNN0CB02PM1G:00000001": started reading request body. +[00:13:39 DBG] Connection id "0HNN0CB02PM1G", Request id "0HNN0CB02PM1G:00000001": done reading request body. +[00:13:39 DBG] Connection id "0HNN0CB02PM1G" disconnecting. +[00:13:39 DBG] Connection id "0HNN0CB02PM1G" stopped. +[00:13:39 DBG] Connection id "0HNN0CB02PM1G" sending FIN because: "The Socket transport's send loop completed gracefully." +[00:13:41 INF] Heartbeat: captureActive=True, audioActive=True, dataFlowing=True +[00:13:45 DBG] Window emitted (180000 samples, cycle 22:13:30). +[00:13:45 INF] Cycle skipped - RMS 0.000E+000 is below silence guard (threshold 1.000E-006). +[00:13:46 INF] Heartbeat: captureActive=True, audioActive=True, dataFlowing=True +[00:13:51 INF] Heartbeat: captureActive=True, audioActive=True, dataFlowing=True +[00:13:56 INF] Heartbeat: captureActive=True, audioActive=True, dataFlowing=True +[00:14:00 DBG] Window emitted (180000 samples, cycle 22:13:45). +[00:14:00 INF] Cycle skipped - RMS 0.000E+000 is below silence guard (threshold 1.000E-006). +[00:14:00 INF] QsoAnswererService: pending CQ target 'Q9BUG' at 1600 Hz - answering at A phase. +[00:14:00 INF] QsoAnswererService: watchdog armed for 4 minutes. +[00:14:00 DBG] QsoAnswererService: state  TxAnswer (partner: Q9BUG). +[00:14:00 INF] QsoAnswererService: TX  "Q9BUG Q1OFZ JO33" at 1600 Hz. +[00:14:00 DBG] TX audio loaded: 606720 samples (12640 ms). +[00:14:00 INF] TX KeyDown - starting playback on device '{0.0.0.00000000}.{a12483ac-beb4-484c-999b-d79c8f932997}' (606720 samples). +[00:14:00 DBG] TX: opened output device '{0.0.0.00000000}.{a12483ac-beb4-484c-999b-d79c8f932997}'. +[00:14:01 INF] Heartbeat: captureActive=True, audioActive=True, dataFlowing=True +``` diff --git a/qa/d-caller-018-abort-hard-stop-live-verify/live-reports/2026-07-12T221518Z-d3eff84.md b/qa/d-caller-018-abort-hard-stop-live-verify/live-reports/2026-07-12T221518Z-d3eff84.md new file mode 100644 index 0000000..0787ae9 --- /dev/null +++ b/qa/d-caller-018-abort-hard-stop-live-verify/live-reports/2026-07-12T221518Z-d3eff84.md @@ -0,0 +1,51 @@ +# D-CALLER-018/016 — Abort hard-stop live verification + +- **Run at (UTC):** 2026-07-12T22:15:18.015831+00:00 +- **Git commit:** `d3eff84` (branch `fix/d-caller-018-abort-hard-stop`) +- **Script:** `qa/d-caller-018-abort-hard-stop-live-verify/live_verify_abort_hardstop.py` +- **Dev-task:** `dev-tasks/2026-07-12-answerer-abort-hard-stop-and-reengage-timing.md` §5 + +## WebSocket `txState` events received (UTC wall clock) + +| # | Wall-clock (UTC) | state | partner | keying | +|---|---|---|---|---| +| 1 | `2026-07-12T22:14:30.170+00:00` | `TxAnswer` | `Q9CTRL` | `False` | +| 2 | `2026-07-12T22:14:30.177+00:00` | `TxAnswer` | `Q9CTRL` | `True` | +| 3 | `2026-07-12T22:14:30.295+00:00` | `TxAnswer` | `Q9CTRL` | `False` | +| 4 | `2026-07-12T22:14:30.297+00:00` | `Idle` | `None` | `False` | + +## Result + +**PASS** + +## Notes + +Binary under test: `D:\Projects\claude\OpenWSFZ\src\OpenWSFZ.Daemon\bin\Release\net10.0\OpenWSFZ.Daemon.exe` +Binary last-write time (UTC): `2026-07-12T22:14:10.677522+00:00` +QsoAnswererService.cs last-write time (UTC): `2026-07-12T22:14:07.988721+00:00` +Daemon process start time (UTC): `2026-07-12T22:14:15.675283+00:00` +Rebuild check: compiled binary postdates the source edits = `True`; process started after binary was built = `True` + +### Phase A — sanity control (timely arm) + AC-3 live regression (abort mid-TX) + +Arming `Q9CTRL` at `2026-07-12T22:14:30Z` — 0.15 s into window `2026-07-12T22:14:30Z` (timely, ≤ 2.0 s) — expect immediate fire. +POST /api/v1/tx/answer-cq (Q9CTRL) → HTTP 200 +Real `keying: true` observed for `Q9CTRL`: `True` +POST /api/v1/tx/abort (mid-TX, at `2026-07-12T22:14:30Z`) → HTTP 200 +`keying: false` observed after mid-TX abort: `True` +GET /api/v1/tx/status after Phase A abort: `{'state': 'Idle', 'partner': None, 'autoAnswerEnabled': False, 'role': 'answerer', 'callerPartnerSelect': 'First', 'keying': False}` +**Phase A result: PASS** + +### Phase B — D-CALLER-018 repro: hammer Abort while Idle with a deferred target + +Arming `Q9BUG` at `2026-07-12T22:14:52Z` — 7.00 s into window `2026-07-12T22:14:45Z` (late, > 2.0 s) — expect deferral, no fire. +POST /api/v1/tx/answer-cq (Q9BUG) → HTTP 200 +Late-start deferral log line found for `Q9BUG`: `True` (7.0 s into window) +No transmission for `Q9BUG` fired on the first (late) window: `True` +Hammered POST /api/v1/tx/abort x14 while Idle (2026-07-12T22:14:53Z .. 2026-07-12T22:14:54Z) — statuses: [200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200] +Waiting until `2026-07-12T22:15:18Z` (next matching-phase window `2026-07-12T22:15:15Z` + 3 s buffer) to confirm no re-engagement... +GET /api/v1/tx/status after wait: `{'state': 'Idle', 'partner': None, 'autoAnswerEnabled': False, 'role': 'answerer', 'callerPartnerSelect': 'First', 'keying': False}` +'answering at ... phase' log line ever appeared for `Q9BUG` (would prove re-engagement): `False` +No WS txState event names `Q9BUG` as partner after the abort hammer: `True` +**Phase B result: PASS** + diff --git a/qa/d-caller-018-abort-hard-stop-live-verify/live_verify_abort_hardstop.py b/qa/d-caller-018-abort-hard-stop-live-verify/live_verify_abort_hardstop.py new file mode 100644 index 0000000..e959cad --- /dev/null +++ b/qa/d-caller-018-abort-hard-stop-live-verify/live_verify_abort_hardstop.py @@ -0,0 +1,675 @@ +#!/usr/bin/env python3 +"""Live, hardware-in-the-loop verification of D-CALLER-018/016 +(dev-task 2026-07-12-answerer-abort-hard-stop-and-reengage-timing.md) against a real, isolated +OpenWSFZ.Daemon instance. + +WHY THIS EXISTS: dev-task section 5 states plainly that this defect was only caught by reading a +real operating log, not by unit tests — every existing D-CALLER-013 unit test passed the whole +time this was broken, because none of them exercised "Abort while a target is armed but the +service is already Idle." This script reproduces that exact production sequence +(logs/openswfz-20260712T211150Z.log, CX1RL/23:18:30-23:19:00) against a real running daemon over +its real HTTP/WebSocket API, with a real background service loop and real wall-clock FT8 cycle +timing (no FakeTimeProvider) — not a mock. Modelled on +qa/tx-keying-live-verify/live_verify_keying.py's precedent (real isolated daemon, real audio +device via AudioOnlyPttController, no CAT/serial rig or virtual-audio-cable required since this +defect lives entirely in QsoAnswererService's Idle-state bookkeeping, not the decoder). + +WHAT IT PROVES, IN TWO PHASES: + + Phase A (sanity control + AC-3 live regression): arms a pending CQ target timely (< 2.0 s into + its answer window) so it fires immediately — proving the harness can produce a REAL keyed + transmission (ruling out "audio device silently failed to open" as a false PASS) — then + calls the dedicated Abort endpoint mid-transmission and confirms KeyUp/Idle follow promptly. + This is the AC-3 regression: AbortAsync while genuinely mid-TX must keep working exactly as + before the fix. + + Phase B (the actual bug, AC-1 live): arms a second, different pending CQ target late (> 2.0 s + into its answer window) so the late-start guard defers it — reproducing "pending target ... + late start ... deferring to next occurrence" from the log while the service sits Idle with + the target still armed. Then hammers the dedicated Abort endpoint (matching the log's 14 + no-op clicks) while Idle, then waits past the next occurrence of that target's matching-phase + window (~30 s later) and confirms NO transmission fires and the partner never appears in any + txState broadcast — the exact "no recourse" defect from the log, now fixed. + + AC-2 (jump-in / EngageAtAsync) is deliberately NOT exercised live here: AbortAsync's fix clears + _pendingTargetCallsign and _jumpPartner in the same unconditional lock block (same code path, + same guard removed), and the jump-in unit test + (AbortAsync_WhileIdleWithDeferredJumpInTarget_ClearsTarget_NoSubsequentTx) was confirmed to FAIL + against the pre-fix code and PASS against the fix (see PR description) — reproducing it live via + engage-decode's directed-message dispatch would materially lengthen this script for coverage + that unit tests already prove is code-identical to Phase B below. + +REQUIRES: the Release daemon built (`dotnet build OpenWSFZ.slnx -c Release` from the repo root — +this script does not build it for you) and a real audio output device (does not need to be +audible or a virtual cable — CQ transmission via AudioOnlyPttController does not require a decode +input). + +Exit code 0 on PASS, 1 on FAIL, 2 if the environment prerequisites aren't met (e.g. no Release +binary found) — the report still gets written in the exit-2 case, marked +ENVIRONMENT-UNAVAILABLE, so a CI-less environment doesn't produce a false PASS or a +silently-missing report. +""" +import base64 +import json +import os +import platform +import re +import shutil +import socket +import struct +import subprocess +import sys +import tempfile +import threading + +# Windows console default (cp1252/OEM) cannot encode the — / ≤ characters used in this script's +# own notes strings; reconfigure stdout/stderr to UTF-8 so `print()` never crashes mid-report +# (the report FILE is always UTF-8 regardless — this only affects console echo). +if hasattr(sys.stdout, "reconfigure"): + sys.stdout.reconfigure(encoding="utf-8", errors="replace") + sys.stderr.reconfigure(encoding="utf-8", errors="replace") +import time +import urllib.error +import urllib.request +from datetime import datetime, timedelta, timezone +from pathlib import Path + +REPO_ROOT = Path(__file__).resolve().parents[2] +REPORTS_DIR = Path(__file__).resolve().parent / "live-reports" + +PORT = 18768 # distinct scratch port from decode-filter-synth-verify's 18765 / tx-keying's 18767 +BASE = f"http://127.0.0.1:{PORT}" + +OUR_CALLSIGN = "Q1OFZ" +OUR_GRID = "JO33" +PHASE_A_TARGET = "Q9CTRL" # sanity-control target, timely arm, aborted mid-TX (AC-3 live) +PHASE_B_TARGET = "Q9BUG" # the actual D-CALLER-018 repro target, late arm, hammered while Idle + +MAX_LATE_START_SECONDS = 2.0 # must track QsoAnswererService.cs's MaxLateStartSeconds (D-CALLER-016) + +# Tolerant of whatever dash character actually lands in the console sink: the source uses an +# em dash (—), but Windows console best-fit fallback encoding can silently substitute a plain +# ASCII hyphen (confirmed precedent: qa/tx-keying-live-verify/live_verify_keying.py's own +# KEYDOWN_START_RE comment) — match on the surrounding words only, not the punctuation. +LATE_START_LOG_RE = re.compile( + r"pending target '(?P\S+)'.*?late start \((?P[\d.]+) s into window\).*?" + r"deferring to next occurrence") +ANSWERING_LOG_RE = re.compile( + r"pending CQ target '(?P\S+)' at \S+ Hz.*?answering at \S+ phase") + + +# ── HTTP helpers ───────────────────────────────────────────────────────────── + +def http_get(path): + with urllib.request.urlopen(f"{BASE}{path}", timeout=5) as resp: + return json.loads(resp.read().decode("utf-8")) + +def http_post(path, body=None): + data = json.dumps(body if body is not None else {}).encode("utf-8") + req = urllib.request.Request(f"{BASE}{path}", data=data, method="POST", + headers={"Content-Type": "application/json"}) + with urllib.request.urlopen(req, timeout=5) as resp: + return resp.status, json.loads(resp.read().decode("utf-8")) + +def wait_for_daemon_ready(timeout_s=15): + deadline = time.time() + timeout_s + while time.time() < deadline: + try: + return http_get("/api/v1/status") + except (urllib.error.URLError, ConnectionError): + time.sleep(0.3) + raise TimeoutError(f"Daemon did not respond on {BASE} within {timeout_s}s.") + + +# ── Audio device resolution (loopback-safe defaults — no cable required) ───── + +INPUT_DEVICE_SUBSTRINGS = ("cable output", "voicemeeter out") +OUTPUT_DEVICE_SUBSTRINGS = ("cable input", "voicemeeter in", "speakers") + +def resolve_devices(): + """Prefers a real virtual-cable/voicemeeter/speakers device over devices[0], which can be a + stale/disconnected virtual device that silently fails to open — see + qa/tx-keying-live-verify/live_verify_keying.py's precedent for why devices[0] is unsafe.""" + devices = http_get("/api/v1/audio/devices") + outputs = http_get("/api/v1/audio/output-devices") + + input_dev = next( + (d for sub in INPUT_DEVICE_SUBSTRINGS for d in devices if sub in d["name"].lower()), + devices[0] if devices else None) + output_dev = next( + (d for sub in OUTPUT_DEVICE_SUBSTRINGS for d in outputs if sub in d["name"].lower()), + outputs[0] if outputs else None) + return input_dev, output_dev + + +# ── Minimal dependency-free WebSocket client (RFC 6455) ────────────────────── +# Loopback connections bypass the SEC-002B passphrase gate server-side, so no auth frame needed. + +class MinimalWsClient: + def __init__(self, host, port, path): + self._sock = socket.create_connection((host, port), timeout=10) + self._sock.settimeout(1.0) + self._buf = b"" + self._closed = False + self._handshake(host, port, path) + + def _handshake(self, host, port, path): + key = base64.b64encode(os.urandom(16)).decode("ascii") + req = ( + f"GET {path} HTTP/1.1\r\n" + f"Host: {host}:{port}\r\n" + "Upgrade: websocket\r\n" + "Connection: Upgrade\r\n" + f"Sec-WebSocket-Key: {key}\r\n" + "Sec-WebSocket-Version: 13\r\n" + "\r\n" + ).encode("ascii") + self._sock.sendall(req) + + self._sock.settimeout(10) + while b"\r\n\r\n" not in self._buf: + chunk = self._sock.recv(4096) + if not chunk: + raise ConnectionError("Socket closed during WS handshake.") + self._buf += chunk + header_end = self._buf.index(b"\r\n\r\n") + 4 + headers = self._buf[:header_end].decode("iso-8859-1") + self._buf = self._buf[header_end:] + if " 101 " not in headers.split("\r\n")[0]: + raise ConnectionError(f"WS handshake failed: {headers.splitlines()[0]!r}") + self._sock.settimeout(1.0) + + def _recv_more(self): + try: + chunk = self._sock.recv(65536) + except socket.timeout: + return False + if not chunk: + self._closed = True + return False + self._buf += chunk + return True + + def read_frame(self): + while True: + if len(self._buf) < 2: + if not self._recv_more(): + return None + continue + b0, b1 = self._buf[0], self._buf[1] + opcode = b0 & 0x0F + masked = (b1 & 0x80) != 0 + plen = b1 & 0x7F + offset = 2 + if plen == 126: + if len(self._buf) < offset + 2: + if not self._recv_more(): + return None + continue + plen = struct.unpack(">H", self._buf[offset:offset + 2])[0] + offset += 2 + elif plen == 127: + if len(self._buf) < offset + 8: + if not self._recv_more(): + return None + continue + plen = struct.unpack(">Q", self._buf[offset:offset + 8])[0] + offset += 8 + mask_key = b"" + if masked: + if len(self._buf) < offset + 4: + if not self._recv_more(): + return None + continue + mask_key = self._buf[offset:offset + 4] + offset += 4 + if len(self._buf) < offset + plen: + if not self._recv_more(): + return None + continue + payload = self._buf[offset:offset + plen] + if masked: + payload = bytes(b ^ mask_key[i % 4] for i, b in enumerate(payload)) + self._buf = self._buf[offset + plen:] + + if opcode == 0x8: # close + self._closed = True + return None + if opcode == 0x9: # ping -> pong + self._send_frame(0xA, payload) + continue + if opcode == 0x1: # text + return payload.decode("utf-8", errors="replace") + continue + + def _send_frame(self, opcode, payload=b""): + mask_key = os.urandom(4) + masked_payload = bytes(b ^ mask_key[i % 4] for i, b in enumerate(payload)) + b0 = 0x80 | opcode + length = len(payload) + if length < 126: + header = struct.pack("!BB", b0, 0x80 | length) + elif length < 65536: + header = struct.pack("!BBH", b0, 0x80 | 126, length) + else: + header = struct.pack("!BBQ", b0, 0x80 | 127, length) + self._sock.sendall(header + mask_key + masked_payload) + + def close(self): + try: + self._send_frame(0x8, b"") + except OSError: + pass + try: + self._sock.close() + except OSError: + pass + + +def ws_reader_thread(client, events, stop_flag, errors): + import traceback + try: + while not stop_flag["stop"] and not client._closed: + msg = client.read_frame() + if msg is None: + continue + now = datetime.now(timezone.utc) + try: + parsed = json.loads(msg) + except json.JSONDecodeError: + continue + if parsed.get("type") == "txState": + events.append((now, parsed)) + except Exception: + errors.append(traceback.format_exc()) + + +# ── FT8 15-second cycle helpers (must track QsoAnswererService.cs's IsAPhase/RoundDownTo15s) ─ + +def floor15(dt): + sec = (dt.second // 15) * 15 + return dt.replace(second=sec, microsecond=0) + +def is_a_phase(dt): + return dt.second % 30 == 0 + +def next_boundary(now=None): + now = now or datetime.now(timezone.utc) + ws = floor15(now) + nb = ws + timedelta(seconds=15) + while nb <= now: + nb += timedelta(seconds=15) + return nb + +def sleep_until(target_dt): + now = datetime.now(timezone.utc) + delta = (target_dt - now).total_seconds() + if delta > 0: + time.sleep(delta) + +def iso_z(dt): + return dt.astimezone(timezone.utc).strftime("%Y-%m-%dT%H:%M:%SZ") + + +# ── Daemon process management ───────────────────────────────────────────────── + +def resolve_daemon_binary(): + exe_name = "OpenWSFZ.Daemon.exe" if platform.system() == "Windows" else "OpenWSFZ.Daemon" + candidate = REPO_ROOT / "src" / "OpenWSFZ.Daemon" / "bin" / "Release" / "net10.0" / exe_name + if candidate.exists(): + return candidate + raise FileNotFoundError( + "Release daemon binary not found. Build it first: " + "dotnet build OpenWSFZ.slnx -c Release") + +def start_daemon(binary, config_path, log_path): + log_file = open(log_path, "w", encoding="utf-8") + proc = subprocess.Popen( + [str(binary), "--port", str(PORT), "--config", str(config_path)], + stdout=log_file, stderr=subprocess.STDOUT, cwd=str(REPO_ROOT)) + return proc, log_file + +def stop_daemon(proc, log_file): + if proc.poll() is None: + proc.terminate() + try: + proc.wait(timeout=5) + except subprocess.TimeoutExpired: + proc.kill() + log_file.close() + + +# ── Report writer ───────────────────────────────────────────────────────────── + +def write_report(status, timestamp_table, environment_note=None, extra_notes=None): + REPORTS_DIR.mkdir(parents=True, exist_ok=True) + ts = datetime.now(timezone.utc) + sha = subprocess.run(["git", "rev-parse", "--short", "HEAD"], cwd=str(REPO_ROOT), + capture_output=True, text=True).stdout.strip() or "unknown" + branch = subprocess.run(["git", "branch", "--show-current"], cwd=str(REPO_ROOT), + capture_output=True, text=True).stdout.strip() or "unknown" + fname = REPORTS_DIR / f"{ts.strftime('%Y-%m-%dT%H%M%SZ')}-{sha}.md" + + lines = [ + "# D-CALLER-018/016 — Abort hard-stop live verification", + "", + f"- **Run at (UTC):** {ts.isoformat()}", + f"- **Git commit:** `{sha}` (branch `{branch}`)", + f"- **Script:** `qa/d-caller-018-abort-hard-stop-live-verify/live_verify_abort_hardstop.py`", + f"- **Dev-task:** `dev-tasks/2026-07-12-answerer-abort-hard-stop-and-reengage-timing.md` §5", + "", + ] + + if environment_note: + lines += ["## Environment", "", environment_note, ""] + + if timestamp_table: + lines += ["## WebSocket `txState` events received (UTC wall clock)", "", + "| # | Wall-clock (UTC) | state | partner | keying |", + "|---|---|---|---|---|"] + for i, (t, ev) in enumerate(timestamp_table, start=1): + lines.append( + f"| {i} | `{t.isoformat(timespec='milliseconds')}` | " + f"`{ev.get('state')}` | `{ev.get('partner')}` | `{ev.get('keying')}` |") + lines.append("") + + lines += ["## Result", "", f"**{status}**", ""] + + if extra_notes: + lines += ["## Notes", "", extra_notes, ""] + + fname.write_text("\n".join(lines), encoding="utf-8") + return fname + + +# ── Main ───────────────────────────────────────────────────────────────────── + +def main(): + try: + binary = resolve_daemon_binary() + except FileNotFoundError as e: + fname = write_report("ENVIRONMENT-UNAVAILABLE", [], environment_note=str(e)) + print(f"ENVIRONMENT UNAVAILABLE — report written to {fname}") + return 2 + + binary_mtime = datetime.fromtimestamp(binary.stat().st_mtime, tz=timezone.utc) + source_file = REPO_ROOT / "src" / "OpenWSFZ.Daemon" / "QsoAnswererService.cs" + source_mtime = (datetime.fromtimestamp(source_file.stat().st_mtime, tz=timezone.utc) + if source_file.exists() else None) + + scratch = Path(tempfile.mkdtemp(prefix="owsfz-abort-hardstop-verify-")) + config_path = scratch / "config.json" + logs_dir = scratch / "logs" + logs_dir.mkdir(parents=True, exist_ok=True) + daemon_log_path = scratch / "daemon.log" + + proc = None + log_file = None + ws_client = None + notes = [] + ok = False + + try: + # ── Phase 0: throwaway start, just to enumerate real audio devices ── + config_path.write_text("{}", encoding="utf-8") + proc, log_file = start_daemon(binary, config_path, daemon_log_path) + wait_for_daemon_ready() + input_dev, output_dev = resolve_devices() + stop_daemon(proc, log_file) + + # ── Phase 1: write the FINAL config ────────────────────────────────── + config = { + "audioDeviceId": input_dev["id"] if input_dev else None, + "audioOutputDeviceId": output_dev["id"] if output_dev else None, + "port": PORT, + "decodingEnabled": True, + "logLevel": "Debug", # Debug so the "late start ... deferring" line is captured + "decodeLog": { + "enabled": True, + "path": str(logs_dir / "ALL.TXT").replace("\\", "/"), + "dialFrequencyMHz": 7.074, + }, + "tx": { + "autoAnswer": False, # armed at runtime via POST /tx/answer-cq below + "callsign": OUR_CALLSIGN, + "grid": OUR_GRID, + "retryCount": 0, + "watchdogMinutes": 4, + "rxAudioOffsetHz": 1500, + "txAudioOffsetHz": 1500, + "holdTxFreq": False, + "role": "Answerer", + "callerPartnerSelect": "First", + "qsoConfirmation": False, + }, + } + config_path.write_text(json.dumps(config, indent=2), encoding="utf-8") + + # ── Phase 2: the real, correctly-configured daemon start ──────────── + proc_start_time = datetime.now(timezone.utc) + proc, log_file = start_daemon(binary, config_path, daemon_log_path) + wait_for_daemon_ready() + + # ── Phase 3: WebSocket client + reader thread ──────────────────────── + ws_client = MinimalWsClient("127.0.0.1", PORT, "/api/v1/ws") + events = [] + reader_errors = [] + stop_flag = {"stop": False} + reader = threading.Thread( + target=ws_reader_thread, args=(ws_client, events, stop_flag, reader_errors), daemon=True) + reader.start() + + notes.append(f"Binary under test: `{binary}`") + notes.append(f"Binary last-write time (UTC): `{binary_mtime.isoformat()}`") + notes.append(f"QsoAnswererService.cs last-write time (UTC): " + f"`{source_mtime.isoformat() if source_mtime else 'unknown'}`") + notes.append(f"Daemon process start time (UTC): `{proc_start_time.isoformat()}`") + notes.append( + f"Rebuild check: compiled binary postdates the source edits = " + f"`{binary_mtime >= source_mtime if source_mtime else 'unknown'}`; " + f"process started after binary was built = `{proc_start_time >= binary_mtime}`") + notes.append("") + + # ═══════════════════════════════════════════════════════════════════ + # Phase A: sanity control + AC-3 live regression — timely arm fires + # immediately (proves the harness produces a real keyed transmission), + # then Abort mid-TX must stop it promptly exactly as before the fix. + # ═══════════════════════════════════════════════════════════════════ + notes.append("### Phase A — sanity control (timely arm) + AC-3 live regression (abort mid-TX)") + notes.append("") + + nb = next_boundary() + sleep_until(nb + timedelta(milliseconds=150)) + arm_a_time = datetime.now(timezone.utc) + window_a_start = floor15(arm_a_time) + cq_cycle_a = window_a_start - timedelta(seconds=15) + secs_in_a = (arm_a_time - window_a_start).total_seconds() + + notes.append( + f"Arming `{PHASE_A_TARGET}` at `{iso_z(arm_a_time)}` — {secs_in_a:.2f} s into window " + f"`{iso_z(window_a_start)}` (timely, ≤ {MAX_LATE_START_SECONDS} s) — expect immediate fire.") + + status_a, _ = http_post("/api/v1/tx/answer-cq", { + "callsign": PHASE_A_TARGET, + "frequencyHz": 1500.0, + "cqCycleStartUtc": iso_z(cq_cycle_a), + }) + notes.append(f"POST /api/v1/tx/answer-cq ({PHASE_A_TARGET}) → HTTP {status_a}") + + # Wait for a real keying:true event for PHASE_A_TARGET. + deadline = time.time() + 5 + saw_keying_true_a = False + while time.time() < deadline: + for t, e in events: + if t >= arm_a_time and e.get("keying") is True and e.get("partner") == PHASE_A_TARGET: + saw_keying_true_a = True + break + if saw_keying_true_a: + break + time.sleep(0.1) + notes.append(f"Real `keying: true` observed for `{PHASE_A_TARGET}`: `{saw_keying_true_a}`") + + # Abort mid-TX (AC-3 live regression). + abort_mid_tx_time = datetime.now(timezone.utc) + status_abort_a, _ = http_post("/api/v1/tx/abort") + notes.append(f"POST /api/v1/tx/abort (mid-TX, at `{iso_z(abort_mid_tx_time)}`) → HTTP {status_abort_a}") + + deadline = time.time() + 5 + saw_keying_false_after_abort_a = False + while time.time() < deadline: + for t, e in events: + if t >= abort_mid_tx_time and e.get("keying") is False: + saw_keying_false_after_abort_a = True + break + if saw_keying_false_after_abort_a: + break + time.sleep(0.1) + notes.append( + f"`keying: false` observed after mid-TX abort: `{saw_keying_false_after_abort_a}`") + + time.sleep(0.5) + status_a_final = http_get("/api/v1/tx/status") + notes.append(f"GET /api/v1/tx/status after Phase A abort: `{status_a_final}`") + phase_a_ok = ( + saw_keying_true_a + and saw_keying_false_after_abort_a + and status_a_final.get("state") == "Idle" + ) + notes.append(f"**Phase A result: {'PASS' if phase_a_ok else 'FAIL'}**") + notes.append("") + + # ═══════════════════════════════════════════════════════════════════ + # Phase B: the actual D-CALLER-018 defect — late arm defers, then the + # dedicated Abort button is hammered while Idle with the target still + # armed. Before the fix this was a no-op and the target fired anyway + # ~30 s later; after the fix it must never fire. + # ═══════════════════════════════════════════════════════════════════ + notes.append("### Phase B — D-CALLER-018 repro: hammer Abort while Idle with a deferred target") + notes.append("") + + nb2 = next_boundary() + late_offset = 7.0 # comfortably > MaxLateStartSeconds (2.0 s), comfortably < window (15 s) + sleep_until(nb2 + timedelta(seconds=late_offset)) + arm_b_time = datetime.now(timezone.utc) + window_b_start = floor15(arm_b_time) + cq_cycle_b = window_b_start - timedelta(seconds=15) + secs_in_b = (arm_b_time - window_b_start).total_seconds() + + notes.append( + f"Arming `{PHASE_B_TARGET}` at `{iso_z(arm_b_time)}` — {secs_in_b:.2f} s into window " + f"`{iso_z(window_b_start)}` (late, > {MAX_LATE_START_SECONDS} s) — expect deferral, no fire.") + + status_b, _ = http_post("/api/v1/tx/answer-cq", { + "callsign": PHASE_B_TARGET, + "frequencyHz": 1600.0, + "cqCycleStartUtc": iso_z(cq_cycle_b), + }) + notes.append(f"POST /api/v1/tx/answer-cq ({PHASE_B_TARGET}) → HTTP {status_b}") + + # Give the wakeup channel a moment to be processed, then check for the deferral log line. + time.sleep(1.0) + log_text_mid = daemon_log_path.read_text(encoding="utf-8", errors="ignore") + defer_match = None + for m in LATE_START_LOG_RE.finditer(log_text_mid): + if m.group("callsign") == PHASE_B_TARGET: + defer_match = m + notes.append( + f"Late-start deferral log line found for `{PHASE_B_TARGET}`: `{bool(defer_match)}`" + + (f" ({defer_match.group('secs')} s into window)" if defer_match else "")) + + # Confirm no fire happened yet. + no_fire_yet = not any( + t >= arm_b_time and e.get("partner") == PHASE_B_TARGET and e.get("keying") is True + for t, e in events) + notes.append(f"No transmission for `{PHASE_B_TARGET}` fired on the first (late) window: `{no_fire_yet}`") + + # Hammer the dedicated Abort button while Idle with the target still armed — matches the + # log's 14 no-op clicks. + hammer_start = datetime.now(timezone.utc) + hammer_statuses = [] + for _ in range(14): + st, _ = http_post("/api/v1/tx/abort") + hammer_statuses.append(st) + time.sleep(0.1) + hammer_end = datetime.now(timezone.utc) + notes.append( + f"Hammered POST /api/v1/tx/abort x14 while Idle ({iso_z(hammer_start)} .. " + f"{iso_z(hammer_end)}) — statuses: {hammer_statuses}") + + # Wait past the NEXT occurrence of the matching-phase window (~30 s later) plus a buffer. + next_matching_window = window_b_start + timedelta(seconds=30) + wait_until = next_matching_window + timedelta(seconds=3) + notes.append( + f"Waiting until `{iso_z(wait_until)}` (next matching-phase window " + f"`{iso_z(next_matching_window)}` + 3 s buffer) to confirm no re-engagement...") + sleep_until(wait_until) + + log_text_final = daemon_log_path.read_text(encoding="utf-8", errors="ignore") + answering_match_after_hammer = None + for m in ANSWERING_LOG_RE.finditer(log_text_final): + if m.group("callsign") == PHASE_B_TARGET: + answering_match_after_hammer = m + no_fire_after_hammer = not any( + t >= hammer_end and e.get("partner") == PHASE_B_TARGET + for t, e in events) + + status_b_final = http_get("/api/v1/tx/status") + notes.append(f"GET /api/v1/tx/status after wait: `{status_b_final}`") + notes.append( + f"'answering at ... phase' log line ever appeared for `{PHASE_B_TARGET}` " + f"(would prove re-engagement): `{bool(answering_match_after_hammer)}`") + notes.append( + f"No WS txState event names `{PHASE_B_TARGET}` as partner after the abort hammer: " + f"`{no_fire_after_hammer}`") + + phase_b_ok = ( + bool(defer_match) + and no_fire_yet + and all(s == 200 for s in hammer_statuses) + and not answering_match_after_hammer + and no_fire_after_hammer + and status_b_final.get("state") == "Idle" + and status_b_final.get("partner") is None + ) + notes.append(f"**Phase B result: {'PASS' if phase_b_ok else 'FAIL'}**") + notes.append("") + + stop_flag["stop"] = True + if reader_errors: + notes.append("**WS reader thread raised an exception:**") + notes.append("```") + notes.extend(reader_errors) + notes.append("```") + + ok = phase_a_ok and phase_b_ok + + if not ok: + log_lines = log_text_final.splitlines() + tail = log_lines[-120:] if len(log_lines) > 120 else log_lines + notes.append("") + notes.append("**Daemon log tail (last 120 lines) — diagnostic aid on failure:**") + notes.append("```") + notes.extend(tail) + notes.append("```") + + status = "PASS" if ok else "FAIL" + timestamp_table = list(events) + fname = write_report(status, timestamp_table, extra_notes="\n".join(notes)) + print(f"{status} — report written to {fname}") + for line in notes: + print(line) + return 0 if ok else 1 + + finally: + if ws_client is not None: + stop_flag = locals().get("stop_flag") + if stop_flag is not None: + stop_flag["stop"] = True + ws_client.close() + if proc is not None and log_file is not None: + stop_daemon(proc, log_file) + shutil.rmtree(scratch, ignore_errors=True) + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/src/OpenWSFZ.Daemon/QsoAnswererService.cs b/src/OpenWSFZ.Daemon/QsoAnswererService.cs index 813650e..c4774da 100644 --- a/src/OpenWSFZ.Daemon/QsoAnswererService.cs +++ b/src/OpenWSFZ.Daemon/QsoAnswererService.cs @@ -133,10 +133,18 @@ public sealed class QsoAnswererService : BackgroundService, IQsoController /// /// Maximum number of seconds into a 15-second FT8 window that TX may still be started. - /// An FT8 signal is 12.64 s; starting later than this causes overrun into the next window. - /// A 1.5 s threshold leaves ~0.86 s margin (15 - 12.64 - 1.5 = 0.86 s). + /// An FT8 signal is 12.64 s; the true physical ceiling is 15 - 12.64 = 2.36 s — starting any + /// later overruns into the next window and can prevent the far station from decoding cleanly. + /// D-CALLER-013 originally set this to 1.5 s, leaving only ~0.8-1.0 s of realistic click budget + /// after decode processing (0.4-0.7 s observed) — in practice this meant almost every manual + /// click (openswfz-20260712T211150Z.log: 1.9 s and 3.7 s observed) missed its window and was + /// deferred a full 30 s (phase alternates every 15 s, so the next matching-phase window is + /// always two cycles away, never one — see D-CALLER-016). 2.0 s leaves a 0.36 s hard safety + /// margin against overrun, comfortably covering the ~50-90 ms KeyDown/device-open jitter observed + /// in production logs, while catching realistic decode-to-click latency instead of nearly always + /// missing it. /// - private const double MaxLateStartSeconds = 1.5; + private const double MaxLateStartSeconds = 2.0; /// /// Written by immediately after setting the pending target, @@ -256,6 +264,24 @@ public Task EngageAtAsync( /// public async Task AbortAsync(CancellationToken ct = default) { + // D-CALLER-018: unconditionally clear any armed-but-not-yet-fired pending target or + // jump-in, regardless of current _state. A target armed by AnswerCqAsync / EngageAtAsync / + // TryEngageExternal fires independently of _state (it is specifically checked while Idle — + // see HandleIdleAsync). Previously this method returned immediately whenever _state was + // already Idle, which meant an armed target could NOT be cancelled by the operator once the + // service returned to Idle — it fired regardless, up to ~30 s later, no matter how many times + // Abort was clicked. Abort must be an unconditional hard stop: nothing may re-engage after it + // until the operator explicitly requests it again. See + // dev-tasks/2026-07-12-answerer-abort-hard-stop-and-reengage-timing.md. + lock (_stateLock) + { + _pendingTargetCallsign = null; + _pendingTargetFrequencyHz = 0.0; + _pendingTargetIsAPhase = false; + _pendingTargetSetAt = default; + _jumpPartner = null; + } + if (_state == QsoState.Idle) return; _logger.LogInformation( diff --git a/tests/OpenWSFZ.Daemon.Tests/QsoAnswererServiceTests.cs b/tests/OpenWSFZ.Daemon.Tests/QsoAnswererServiceTests.cs index 2ce3eb2..337e9a4 100644 --- a/tests/OpenWSFZ.Daemon.Tests/QsoAnswererServiceTests.cs +++ b/tests/OpenWSFZ.Daemon.Tests/QsoAnswererServiceTests.cs @@ -58,8 +58,8 @@ public async Task InitializeAsync() }); var adifLog = new AdifLogWriter(store, NullLogger.Instance); - // D-CALLER-013: inject a FakeTimeProvider at the start of an A-phase window - // (second = 0 → 0 s into the window ≤ MaxLateStartSeconds = 1.5 s) so the + // D-CALLER-013/016: inject a FakeTimeProvider at the start of an A-phase window + // (second = 0 → 0 s into the window ≤ MaxLateStartSeconds = 2.0 s) so the // late-start guard always passes for the shared SUT. // Tests that determine phase from the real clock (D-TX-UI-007 wakeup tests) // use DateTimeOffset.UtcNow directly inside AnswerCqAsync — they are not @@ -2348,7 +2348,7 @@ public async Task QsoComplete_CatConnectedOn20m_AdifFileHasCorrectBand() } } - // ── D-CALLER-013: late-start guard (MaxLateStartSeconds = 1.5 s) ───────── + // ── D-CALLER-013/016: late-start guard (MaxLateStartSeconds = 2.0 s) ───── /// /// Controllable used by D-CALLER-013 tests so the late-start @@ -2403,7 +2403,7 @@ private static (QsoAnswererService sut, IPttController ptt, public async Task PendingTarget_LateStart_IsDeferred_ThenFiresNextCycle() { // FakeTime = 5 s into the :00 A-phase window (17:30:05). - // RoundDownTo15s(17:30:05) = 17:30:00 → secondsIntoWindow = 5.0 > 1.5 → late. + // RoundDownTo15s(17:30:05) = 17:30:00 → secondsIntoWindow = 5.0 > 2.0 (D-CALLER-016) → late. var fakeTime = new FakeTimeProvider( new DateTimeOffset(2026, 6, 27, 17, 30, 5, TimeSpan.Zero)); var (sut, ptt, channel, stopCts) = BuildLateStartSut(fakeTime); @@ -2427,7 +2427,7 @@ await sut.AnswerCqAsync(PartnerCall, AudioFreqHz, await ptt.DidNotReceive().KeyDownAsync(Arg.Any()); // Advance FakeTime to 0.5 s into the next A-phase window (17:30:30.5). - // 0.5 s ≤ 1.5 s → guard passes → TX must fire. + // 0.5 s ≤ 2.0 s → guard passes → TX must fire. fakeTime.UtcNow = new DateTimeOffset(2026, 6, 27, 17, 30, 30, 500, TimeSpan.Zero); // Batch 2: CycleStart :15 (B-phase) → +15 s = :30 A-phase ✓ (same phase, next occurrence). @@ -2447,7 +2447,7 @@ await sut.AnswerCqAsync(PartnerCall, AudioFreqHz, public async Task PendingTarget_TimelyStart_FiresImmediately() { // FakeTime = 0.5 s into the :00 A-phase window. - // 0.5 s ≤ 1.5 s → guard does not defer → TX fires on the first correct-phase batch. + // 0.5 s ≤ 2.0 s → guard does not defer → TX fires on the first correct-phase batch. var fakeTime = new FakeTimeProvider( new DateTimeOffset(2026, 6, 27, 17, 30, 0, 500, TimeSpan.Zero)); var (sut, ptt, channel, stopCts) = BuildLateStartSut(fakeTime); @@ -2476,7 +2476,7 @@ await sut.AnswerCqAsync(PartnerCall, AudioFreqHz, [Fact(DisplayName = "D-CALLER-013 C: Jump-in — late double-click (5 s in) is deferred; fires at next occurrence")] public async Task JumpIn_LateStart_IsDeferred_ThenFiresNextCycle() { - // FakeTime = 5 s into the :00 A-phase window → late for A-phase TX. + // FakeTime = 5 s into the :00 A-phase window → late for A-phase TX (> 2.0 s, D-CALLER-016). var fakeTime = new FakeTimeProvider( new DateTimeOffset(2026, 6, 27, 17, 30, 5, TimeSpan.Zero)); var (sut, ptt, channel, stopCts) = BuildLateStartSut(fakeTime); @@ -2522,7 +2522,7 @@ await sut.EngageAtAsync( public async Task JumpIn_TimelyStart_FiresImmediately() { // FakeTime = 0.2 s into the :00 A-phase window. - // 0.2 s ≤ 1.5 s → guard does not defer → TX fires on the first correct-phase batch. + // 0.2 s ≤ 2.0 s → guard does not defer → TX fires on the first correct-phase batch. var fakeTime = new FakeTimeProvider( new DateTimeOffset(2026, 6, 27, 17, 30, 0, 200, TimeSpan.Zero)); var (sut, ptt, channel, stopCts) = BuildLateStartSut(fakeTime); @@ -2551,6 +2551,103 @@ await sut.EngageAtAsync( await ptt.DisposeAsync(); } + // ── D-CALLER-018: AbortAsync must be a hard stop, even while already Idle ──── + + [Fact(DisplayName = "D-CALLER-018 AC-1: AbortAsync while Idle with a deferred pending CQ target clears it — no subsequent TX")] + public async Task AbortAsync_WhileIdleWithDeferredPendingTarget_ClearsTarget_NoSubsequentTx() + { + // Reproduces the exact production sequence from + // dev-tasks/2026-07-12-answerer-abort-hard-stop-and-reengage-timing.md §1.1: a target is + // armed, its first opportunity is a late start (deferred to the next matching-phase + // occurrence, per D-CALLER-013/016), and — critically — while it sits Idle waiting for that + // next occurrence, the operator clicks Abort. Before the D-CALLER-018 fix, AbortAsync + // no-opped whenever _state was already Idle, so the deferred target fired anyway ~30 s later + // regardless of the abort (the log showed 14 Abort clicks, all no-ops, followed by TX firing). + // This test proves it no longer does. + var fakeTime = new FakeTimeProvider( + new DateTimeOffset(2026, 6, 27, 17, 30, 5, TimeSpan.Zero)); // 5 s into A-phase window → late + var (sut, ptt, channel, stopCts) = BuildLateStartSut(fakeTime); + await sut.StartAsync(stopCts.Token); + + await sut.AnswerCqAsync(PartnerCall, AudioFreqHz, + new DateTimeOffset(2026, 6, 27, 17, 29, 15, TimeSpan.Zero), + CancellationToken.None); + sut._wakeupChannel.Reader.TryRead(out _); // drain wakeup + + // First matching-phase batch: late-start guard defers (target remains armed for the next + // occurrence — this is the "quietly waiting" state the bug exploited). + channel.Writer.TryWrite(new DecodeBatch( + new DateTimeOffset(2026, 6, 27, 17, 29, 45, TimeSpan.Zero), + Array.Empty())); + await Task.Delay(300); + sut.State.Should().Be(QsoState.Idle, "late-start guard defers TX but leaves the service Idle"); + await ptt.DidNotReceive().KeyDownAsync(Arg.Any()); + + // Operator clicks Abort while sitting Idle with the deferred target still armed. + await sut.AbortAsync(); + + // Advance to a timely point in the next matching-phase window — absent the fix, this is + // exactly where the deferred target would fire (see "D-CALLER-013 A" above). + fakeTime.UtcNow = new DateTimeOffset(2026, 6, 27, 17, 30, 30, 500, TimeSpan.Zero); + channel.Writer.TryWrite(new DecodeBatch( + new DateTimeOffset(2026, 6, 27, 17, 30, 15, TimeSpan.Zero), + Array.Empty())); + await Task.Delay(300); + + sut.State.Should().Be(QsoState.Idle, + "Abort must be a hard stop — no TX may fire after an Idle-state abort"); + await ptt.DidNotReceive().KeyDownAsync(Arg.Any()); + + await stopCts.CancelAsync(); + await sut.StopAsync(CancellationToken.None); + await ptt.DisposeAsync(); + } + + [Fact(DisplayName = "D-CALLER-018 AC-2: AbortAsync while Idle with a deferred jump-in target clears it — no subsequent TX")] + public async Task AbortAsync_WhileIdleWithDeferredJumpInTarget_ClearsTarget_NoSubsequentTx() + { + // Same scenario as AC-1 but for a jump-in target armed via EngageAtAsync (double-click on a + // directed report/RR73/73 row) rather than a pending CQ target armed via AnswerCqAsync. + var fakeTime = new FakeTimeProvider( + new DateTimeOffset(2026, 6, 27, 17, 30, 5, TimeSpan.Zero)); // 5 s into A-phase window → late + var (sut, ptt, channel, stopCts) = BuildLateStartSut(fakeTime); + await sut.StartAsync(stopCts.Token); + + await sut.EngageAtAsync( + PartnerCall, AudioFreqHz, + new DateTimeOffset(2026, 6, 27, 17, 29, 15, TimeSpan.Zero), // their B-phase decode + EngagePoint.SendReport, + CancellationToken.None); + sut._wakeupChannel.Reader.TryRead(out _); // drain wakeup + + // First matching-phase batch: late-start guard defers. + channel.Writer.TryWrite(new DecodeBatch( + new DateTimeOffset(2026, 6, 27, 17, 29, 45, TimeSpan.Zero), + Array.Empty())); + await Task.Delay(300); + sut.State.Should().Be(QsoState.Idle, "late-start guard defers jump-in TX but leaves the service Idle"); + await ptt.DidNotReceive().KeyDownAsync(Arg.Any()); + + // Operator clicks Abort while sitting Idle with the deferred jump-in target still armed. + await sut.AbortAsync(); + + // Advance to a timely point in the next matching-phase window — absent the fix, this is + // exactly where the deferred jump-in would fire (see "D-CALLER-013 C" above). + fakeTime.UtcNow = new DateTimeOffset(2026, 6, 27, 17, 30, 30, 300, TimeSpan.Zero); + channel.Writer.TryWrite(new DecodeBatch( + new DateTimeOffset(2026, 6, 27, 17, 30, 15, TimeSpan.Zero), + Array.Empty())); + await Task.Delay(300); + + sut.State.Should().Be(QsoState.Idle, + "Abort must be a hard stop — no jump-in TX may fire after an Idle-state abort"); + await ptt.DidNotReceive().KeyDownAsync(Arg.Any()); + + await stopCts.CancelAsync(); + await sut.StopAsync(CancellationToken.None); + await ptt.DisposeAsync(); + } + // ── decode-panel-filtering: automation gating (tasks 3.2–3.4) ──────────── /// Simple mutable test double — no broadcast, just state. diff --git a/web/js/main.js b/web/js/main.js index 58d2926..51c50f1 100644 --- a/web/js/main.js +++ b/web/js/main.js @@ -9,7 +9,7 @@ import { connect } from './ws.js'; import { getConfig, getFrequencies, postTune, postAudioOffset, getTxStatus, postTxEnable, postTxDisable, postTxAbort, - postTxAnswerCq, postTxSelectResponder, postTxCallCq, postTxStopCq, + postTxSelectResponder, postTxCallCq, postTxStopCq, postTxCallerPartnerSelect, getApiKey, getPropModes, postLogQso, postTxEngageDecode, @@ -724,55 +724,15 @@ function handleDecodes(results) { // Store cycle-start UTC string as a data attribute for the dblclick handler. tr.dataset.cqCycleStartUtc = parseFt8CycleStartUtc(r.time); - // CQ row highlighting and double-click-to-answer (TX-D01, cq-row-dblclick-to-answer). + // CQ row highlighting (TX-D01). The double-click-to-answer gesture itself is handled + // exclusively by the D-CALLER-012 engage-decode listener below (D-CALLER-019 removed the + // redundant legacy postTxAnswerCq dblclick handler that used to live here — it always lost + // the race against engage-decode's own abort-then-dispatch and produced a guaranteed + // spurious 409 on every double-click; see + // dev-tasks/2026-07-12-answerer-abort-hard-stop-and-reengage-timing.md). if (r.message.startsWith('CQ ')) { tr.classList.add('decode-cq'); tr.style.cursor = 'pointer'; - - let inFlight = false; - tr.addEventListener('dblclick', async (event) => { - event.preventDefault(); // best-effort: browsers don't reliably - // treat text selection as dblclick's - // preventable default action - // Explicitly clear whatever the native double-click "select word" behavior just - // selected. preventDefault() alone was confirmed insufficient (cq-dblclick-after.mjs, - // task 4.3 first pass — a stray "CQ " selection remained). An earlier attempt fixed - // this with `user-select: none` on .decode-cq in app.css, but that blocked ALL text - // selection on every CQ row permanently — including a deliberate click-and-drag to - // copy a callsign, which the Captain reported as a regression. Clearing the selection - // here instead only removes what THIS double-click produced, leaving ordinary - // click-and-drag selection on CQ rows fully working the rest of the time. - window.getSelection()?.removeAllRanges(); - if (inFlight) return; // guard already-queued duplicate events - inFlight = true; - tr.style.pointerEvents = 'none'; // belt-and-suspenders for mouse - const callsign = extractCqCallsign(r.message); - if (!callsign) { - inFlight = false; - tr.style.pointerEvents = ''; - return; - } - const cqCycleStartUtc = tr.dataset.cqCycleStartUtc; - try { - const status = await postTxAnswerCq(callsign, r.freqHz, cqCycleStartUtc); - renderTxPanel(status.state, status.partner, status.autoAnswerEnabled, undefined, status.keying); - // Delay guard reset to block a rapid repeat double-click (~130–185 ms interval). - // On success the operator does not need to retry; 400 ms is harmless (D-TX-UI-005). - setTimeout(() => { - inFlight = false; - tr.style.pointerEvents = ''; - }, 400); - } catch (err) { - // On error, reset immediately so the operator can retry. - inFlight = false; - tr.style.pointerEvents = ''; - if (/** @type {any} */ (err)?.status === 409) { - console.warn('TX not Idle — CQ double-click ignored.'); - } else { - console.error('postTxAnswerCq error:', err); - } - } - }); } // Highlight any row addressed to the operator's callsign in red. @@ -844,7 +804,15 @@ function handleDecodes(results) { // The dblclick then calls engage-decode which performs the abort + re-engage // atomically on the server. let engageInFlight = false; - tr.addEventListener('dblclick', async () => { + tr.addEventListener('dblclick', async (event) => { + event.preventDefault(); // best-effort: browsers don't reliably + // treat text selection as dblclick's + // preventable default action + // D-CALLER-019: this listener is now the only dblclick handler on CQ rows (the redundant + // legacy postTxAnswerCq handler was removed above). Carry forward its stray-selection + // cleanup so double-clicking still doesn't leave a "CQ " text selection behind — see the + // history this cleanup used to live under, above the removed block. + window.getSelection()?.removeAllRanges(); if (engageInFlight) return; engageInFlight = true;