Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
301 changes: 301 additions & 0 deletions dev-tasks/2026-07-12-answerer-abort-hard-stop-and-reengage-timing.md

Large diffs are not rendered by default.

51 changes: 51 additions & 0 deletions qa/d-caller-018-abort-hard-stop-live-verify/README.md
Original file line number Diff line number Diff line change
@@ -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 `<tr class="decode-cq">`, 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.
Original file line number Diff line number Diff line change
@@ -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**

Original file line number Diff line number Diff line change
@@ -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
```
Loading
Loading