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
7 changes: 4 additions & 3 deletions docs/trace-invariants.md
Original file line number Diff line number Diff line change
Expand Up @@ -263,9 +263,9 @@ to fire, and what grade that evidence supports. Where a check emits more than
one severity, the row says which evidence produces which — that is the
difference between a tool that reports rule trips and one that reports harm.

Three checks — `capture-arbiter-left-live`, `keychain-not-single-flighted`
and `writer-newline-lost` — are a different kind from the rest. Every other
check asserts the *absence* of a failure that has happened. Those three assert
Four checks — `capture-arbiter-left-live`, `capture-mic-still-live`,
`keychain-not-single-flighted` and `writer-newline-lost` — are a different kind from the rest. Every other
check asserts the *absence* of a failure that has happened. Those four assert
that a fix which has shipped is still engaged, so a hit means a regression
rather than a historical scar. They are marked **(regression)** below.

Expand All @@ -278,6 +278,7 @@ rather than a historical scar. They are marked **(regression)** below.
| `capture-handoff-missing` | Every `capture.stop` is followed by a `dictation.start`. **`tracing.md`'s "one shape the trace can only bound, not explain".** | Scoped by *event order*, never by a time window, so a long dictation is never mistaken for an orphan. Graded on how long the capture was held, because that is the only measurement of what was lost: under 0.7 s is a stray tap discarded by a minimum-length guard — an instrumentation gap, WARN; at or above it a real recording vanished with no reason line, ERROR. The 36-hit regrade that set the precedent for this whole document. |
| `capture-stop-missing` | Every `capture.start` is followed by a `capture.stop` — or by one of the arbiter's closes (`capture.orphan_prevented`, `capture.orphan_reclaimed`, `capture.stale_dropped`). | Two branches, two grades. Terminated by the **next `capture.start` in the same process**: the stream was demonstrably live across that whole span — ERROR, and this is the 11-hour-microphone shape. Terminated by **`app.launched`**: the process exited, and macOS reclaims a capture device when its owner dies, so the trace cannot say how long the microphone was live — WARN, stating that limit rather than asserting the duration. |
| `capture-arbiter-left-live` | **(regression)** When the arbiter refuses or reclaims a stream, the microphone actually goes off. | The Rust drops the cpal stream *before* writing the line, so the line existing means the mic is off. Only three log shapes contradict that, all of them explicit records rather than inferences; each is ERROR. See below. |
| `capture-mic-still-live` | **(regression)** When TTP drops a capture stream, CoreAudio stops running its input. | `capture.mic_still_live` is CoreAudio's answer, not an inference: after 2 s TTP's process still had input running and no newer capture had started. ERROR. It exists because `capture-arbiter-left-live` reads TTP's own bookkeeping and stayed silent through the 2026-09-27 cpal leak. |
| `capture-stop-without-start` | `capture.stop` only fires against an open capture. | An explicit `capture.stop_failed` record with its own error string — the app saying so, not the analyser inferring it. WARN: it means bookkeeping disagreed, not that a user lost anything. |
| `paste-result-missing` | Every `paste.decision` is followed by a `paste.result`. | Both carry the dictation id. The signature audit item A4 names for a panic under `panic = "abort"`, where `catch_unwind` cannot run. ERROR: the user's text went nowhere and nothing recorded why. In-flight-at-EOF dictations are exempt. |
| `paste-verify-missing` | Every successful `paste.result` is followed by a `paste.verify`. | Exact attribution, but the claim is only "landing unproven" — `paste.result` means the events reached the window server, which is not the same as arriving. WARN, because absence of proof is not proof of loss. |
Expand Down
12 changes: 9 additions & 3 deletions docs/tracing.md
Original file line number Diff line number Diff line change
Expand Up @@ -166,13 +166,15 @@ anything from a missing launch line.
| `hotkey.tap_rebuilt` | Re-arming stopped helping, so the tap was torn down and recreated. `CGEventTapEnable` on a tap the window server has written off is a no-op — only a fresh tap restores the Fn key. |
| `hotkey.stale_fn_cleared` | The Globe key was latched "held" and we forced it down. Keystrokes injected before this were being routed to the Globe shortcut layer. |
| `hotkey.timer_stall` | The 20 ms poll timer skipped `gap_ms`. The process was descheduled — nothing advanced during that window: no hotkey, no state machine, no in-flight dictation. TTP now holds an activity assertion for the whole Recording → Idle window (see `crate::activity`), so a stall spanning a dictation should no longer be possible; one that still appears is worth investigating. |
| `capture.start` | Which microphone actually served the recording, its rate/channels/format, whether it is the OS default, and what the user had asked for. `sample_limit` is the callback's backstop for this capture: past that many samples it stops writing, whoever does or does not own the stream. |
| `capture.stop` | Samples the callback delivered, and whether the OS default input changed while the user was talking. `sample_cap_hit:true` means the callback hit `sample_limit` and threw away everything after it. |
| `capture.start` | Which microphone actually served the recording, its rate/channels/format, whether it is the OS default, and what the user had asked for. `route` says why that device: `pinned` (picked in Settings), `pinned_missing` (the pick is not connected, the default stood in), `system_default`, `builtin_over_bluetooth` (the default is a Bluetooth headset, so the Mac's own microphone recorded and the headset stayed out of its call profile), `bluetooth_lid_closed` / `bluetooth_no_builtin` (the headset stayed because the built-in microphone is disconnected or absent). `sample_limit` is the callback's backstop for this capture: past that many samples it stops writing, whoever does or does not own the stream. |
| `capture.stop` | Samples the callback delivered, and whether the OS default input changed while the user was talking (`default_at_start` vs `default_now`; before 2026-09-27 it compared the device opened with the default, so every pinned dictation read `device_changed:true`). `sample_cap_hit:true` means the callback hit `sample_limit` and threw away everything after it. |
| `capture.duration_cap` | **The recording reached `limit_secs` (five minutes) and was stopped.** `stopped:false` means there was no recording left to stop; `hands_free` says which mode it was in, `null` when nothing was stopped. Before this line existed the cap sent a fake key release, which hands-free mode ignores, so an unattended hands-free session had no ceiling at all. What was captured is still transcribed. |
| `capture.stop_waited_for_start` | The stop path found a start still in flight and waited for it, so the recording is collected rather than orphaned. `ms` is how long it waited; **`timed_out:true` is the interesting one** — it means the 3-second settle window elapsed with the start still unfinished, which the constant's own comment says cannot happen. When it does, `capture_arbiter` is the only thing between the user and a live microphone. |
| `capture.orphan_prevented` | **The arbiter refused a start.** A stream had been built, and by the time it asked to go live the state machine no longer wanted one — `reason:"user_idle"` (the press already concluded; this is the 2026-08-30 shape) or `reason:"superseded_by_newer_press"`. The stream is torn down before this line is written, so the line means the microphone is off. `build_ms` is how long the start took to build; the incident's was 544 ms. |
| `capture.orphan_reclaimed` | **The Idle backstop closed a live capture nobody was coming to collect.** The reverse ordering: the start published in the gap between a stop that found nothing and the transition to Idle. Carries `samples`, the `device`, `wav_finalised`, `wav_deleted` and `sample_cap_hit`. The unusable WAV is deleted. As with `orphan_prevented`, the stream is dropped before the line is written. |
| `capture.stale_dropped` | A new `start_recording` found a capture still in `STATE` from a previous cycle and closed it. `samples` says how much it had written. One of these means an earlier cycle ended with the microphone open and neither the stop nor the backstop caught it. Carries the same `wav_finalised` / `wav_deleted` / `sample_cap_hit` as `orphan_reclaimed`, and the WAV is now deleted. It used to stay in `recordings/`, which is how the 2026-08-30 capture sat there as a 7.2 GB file for eleven days. |
| `capture.mic_released` | **CoreAudio's own answer to "did the microphone go off?"**, written 0.3 s after every stream drop (2 s if the first look still saw input). `site` names the path that dropped it: `stop`, `orphan_prevented`, `orphan_reclaimed`, `stale_dropped`. `released:true` is the normal line. `released:null` means no answer: `reason:"newer_capture"` (a dictation started in between, so input running would be about it), or the OS cannot say (before macOS 14, or not a Mac). Every other capture line reads TTP's bookkeeping; this one reads the HAL. |
| `capture.mic_still_live` | **TTP dropped the stream and CoreAudio still runs its input 2 s later**, with no newer capture to explain it: the orange dot staying on after the user let go. The 2026-09-27 cause was cpal 0.15.3 keeping streams on a mic picked by name alive through a reference cycle, eight clean start/stop pairs over one open microphone. Carries `site`, `device`, `after_ms`. Checked as `capture-mic-still-live`. |
| `capture.dead_input_detected` | The microphone has delivered nothing but zeros for `ms` past the grace period, **while the user is still talking**. Emitted once per capture. This is `dead_capture` said at second two instead of at the end: told early, the user loses one sentence and goes to fix their headphones. |
| `audio.duration` / `audio.signal` | How much audio, how loud. The silence gate drops a recording only when `rms_after_silence` is below `floor` **and** `speech_ms` (50 ms windows above `speech_window_floor`, itself `max(0.004, 4 × noise_floor)`) is under 300. `window_p50` / `window_p90` give the spread of 50 ms window levels, for calibrating those thresholds on real voices. `rescued_by_speech:true` marks a dictation the old average-only gate would have dropped. `peak` and `nonzero_ratio` distinguish a quiet room from a dead device. |
| `audio.convert` | Stereo 48 kHz → mono 16 kHz, and the size change. |
Expand Down Expand Up @@ -211,6 +213,8 @@ anything from a missing launch line.
| `history.saved` | Now also emitted when history is **off**, as `{"skipped":"history_disabled"}`. |
| `correction_window.started` | Carries `armed`. It used to be written unconditionally, including on the path that skipped arming. |
| `vad.armed` / `vad.fired` / `vad.disarmed` | The auto-stop watchdog: when it started, whether it cut the recording, and whether the stop that ended it was its own or the user's. |
| `hotkey.tap_deaf` | **The tap is enabled and hears nothing.** The hardware's own last-keyboard-event clock (`CGEventSourceSecondsSinceLastEventType`, HID state) is `missed_ms` ahead of the last key event the tap delivered, on two watchdog passes in a row. `rebuilt:true` means a fresh tap was installed (at most every 30 s, never abandoned). Every other health line calls such a tap healthy: on 2026-09-27 no key reached TTP from 16:22 to 16:37 under `tap_health {"enabled":true}`, and only the relaunch of an update brought it back. Not raised while secure input is on, nor within 2 s of TTP's own injected keystrokes. |
| `hotkey.secure_input` | Secure input turned `on` or off, and `owner`, the bundle id holding it. While it is on no tap receives keystrokes — a password field, or an app that forgot to release it — so presses going nowhere have a cause outside TTP. |
| `hotkey.tap_health` | **The event tap is alive.** Every five minutes while healthy, and immediately after a recovery. The absence of `hotkey.tap_*` lines used to be ambiguous between "fine" and "not running"; this settles it and bounds any outage to five minutes. |
| `permission.helper_shown` / `permission.helper_granted` / `permission.helper_closed` | The drag-to-authorize panel: which permission, whether TTP is running from a bundle at all (`bundle:false` is a dev binary — nothing to drag), whether that bundle is translocated or on a DMG (a grant there does not follow the app), how long the grant took, and why the panel went away. |
| `permission.tcc_reset` | **We are about to destroy the user's granted Accessibility permission.** `tccutil reset` is run when a stale-TCC state is detected, and until Polaris it left one `log_warn` and no trace line at all — so a user who was suddenly re-prompted had nothing explaining why. Emitted *before* the command runs, from the one function that runs it, carrying the two probe values that justified the decision (`api_trusted`, `ax_probe_ok`) plus the `bundle_id` and `version`. |
Expand Down Expand Up @@ -565,6 +569,7 @@ What that means for reading the log:
grep -E 'capture\.(orphan_prevented|orphan_reclaimed|stale_dropped)' ttp-trace.log

# The guarantee failing
grep 'capture.mic_still_live' ttp-trace.log
grep 'capture.reclaim' ttp-trace.log
grep 'capture.stop_waited_for_start' ttp-trace.log | grep '"timed_out":true'
```
Expand Down Expand Up @@ -629,7 +634,8 @@ replaced bundle.
|---|---|
| `update.available` | A check found `version` on the stable or `beta` channel. |
| `update.downloaded` | The bytes are staged in memory (`bytes`, `ms`). Nothing on disk has changed. |
| `update.download_failed` | The download failed; the next 4 h check retries. |
| `update.download_failed` | The download failed; the next hourly check retries. |
| `update.checked` | An hourly background check from Rust (first one 5 min after launch): `staged` (the version now waiting for a quiet moment), `up_to_date`, or `error`. It replaced a 4 h timer in the hidden webview that App Nap froze, so TTP only ever checked at launch. |
| `update.apply` | Install and relaunch, now. `trigger`: `idle` (2 min with no dictation, decided in Rust by `start_idle_applier` — the hidden webview's timers stop under App Nap), `button` (Settings) or `tray`. `staged:false` is a plain relaunch. |
| `update.idle_tick_late` | The idle applier's 10 s tick woke more than 5 s late (`late_ms`); that tick is skipped so a wake caused by a key press never relaunches. TTP holds an App Nap assertion while an update is staged, so this should be rare. |
| `update.install_failed` | The bundle was not replaced; the staged bytes are kept for the next quiet moment. |
Expand Down
2 changes: 1 addition & 1 deletion package.json
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
{
"name": "ttp",
"private": true,
"version": "3.2.4",
"version": "3.2.5",
"type": "module",
"scripts": {
"dev": "vite",
Expand Down
30 changes: 30 additions & 0 deletions scripts/trace_analyser/invariants.py
Original file line number Diff line number Diff line change
Expand Up @@ -95,6 +95,7 @@
"capture.start_failed", "capture.stop_failed", "dictation.rejected",
"hotkey.tap_armed", "hotkey.tap_rearmed", "hotkey.tap_rebuilt",
"hotkey.tap_abandoned", "hotkey.tap_create_failed", "hotkey.tap_health",
"hotkey.tap_deaf", "hotkey.secure_input", "update.checked",
"hotkey.stale_fn_cleared", "hotkey.timer_stall", "capture.start",
"capture.stop", "audio.duration", "audio.signal", "audio.rms",
"audio.convert", "whisper.request", "whisper.response", "whisper.retry",
Expand All @@ -119,6 +120,9 @@
"capture.orphan_prevented", "capture.orphan_reclaimed",
"capture.stale_dropped", "capture.stop_waited_for_start",
"capture.dead_input_detected",
# 2026-09-27: CoreAudio's own answer to "did the microphone go off?",
# written after every stream drop. `capture-mic-still-live` keys off it.
"capture.mic_released", "capture.mic_still_live",
"permission.tcc_reset", "permission.tcc_reset_result",
"permission.notify", "permission.notify_failed",
# Reconciled against the emitting source rather than added one at a time,
Expand Down Expand Up @@ -835,6 +839,32 @@ def check_arbiter_left_live(corpus: Corpus):
)


@invariant(
"capture-mic-still-live", ERROR,
"When TTP drops a capture stream, CoreAudio stops running its input",
"capture-arbiter-left-live reads TTP's bookkeeping, so it can only say "
"the stream was dropped. On 2026-09-27 that was not the same as the "
"microphone going off: cpal 0.15.3 kept every stream opened on a device "
"picked by name alive through a reference cycle, and eight clean "
"capture.start/capture.stop pairs sat over a microphone that never "
"closed. src-tauri/src/mic_release.rs now asks CoreAudio, 0.3 s and "
"again 2 s after each drop, whether this process still has input "
"running, and writes capture.mic_still_live when it does and no newer "
"capture explains it. Every such line is the orange dot staying on "
"after the user let go.",
)
def check_mic_still_live(corpus: Corpus):
for e in corpus.events:
if e.stage == "capture.mic_still_live":
yield Finding(
"capture-mic-still-live", ERROR,
f"microphone {e.get('device')} still live "
f"{e.get('after_ms')} ms after {e.get('site')} dropped the "
f"stream — it leaked below TTP",
ts=str(e.ts), index=e.index, detail=dict(e.payload),
)


@invariant(
"paste-result-missing", ERROR,
"Every paste.decision is followed by a paste.result",
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,12 @@
[2026-09-01 10:00:00.010] [········] app.launched {"arch":"aarch64","os":"macos","version":"3.1.6"}
[2026-09-01 10:00:00.020] [········] hotkey.press {"flags":"0x800000","held_ms":160}
[2026-09-01 10:00:00.021] [········] state.transition {"from":"Idle","to":"Recording"}
[2026-09-01 10:00:00.061] [········] capture.start {"channels":1,"device":"MacBook Air Microphone","format":"F32","is_os_default":true,"preferred":null,"rate":48000}
[2026-09-01 10:00:05.061] [········] hotkey.release {"flags":"0x0"}
[2026-09-01 10:00:05.062] [········] state.transition {"from":"Recording","to":"Processing"}
[2026-09-01 10:00:05.462] [········] capture.stop {"default_now":"MacBook Air Microphone","device":"MacBook Air Microphone","device_changed":false,"samples":240000}
[2026-09-01 10:00:07.462] [········] capture.mic_still_live {"after_ms":2000,"device":"MacBook Air Microphone","site":"stop"}
[2026-09-01 10:00:08.462] [········] hotkey.tap_armed {}
[2026-09-01 10:00:09.462] [········] hotkey.tap_armed {}
[2026-09-01 10:00:10.462] [········] hotkey.tap_armed {}
[2026-09-01 10:00:11.462] [········] hotkey.tap_armed {}
10 changes: 10 additions & 0 deletions scripts/trace_analyser/tests/make_fixtures.py
Original file line number Diff line number Diff line change
Expand Up @@ -753,6 +753,16 @@ def new(launched=True) -> Log:
tail(log, from_state=None)
out["capture-arbiter-left-live"] = log

log = new()
# The 2026-09-27 shape: a clean start/stop pair on a pinned microphone,
# and CoreAudio still running TTP's input two seconds later.
hotkey_cycle(log)
log.free("capture.mic_still_live",
{"after_ms": 2000, "device": "MacBook Air Microphone",
"site": "stop"}, ms=2000)
tail(log, from_state=None)
out["capture-mic-still-live"] = log

log = new()
# Eight sequential secret_reads of one account in one session, none of
# which waited on another. This is the pre-fix ladder, in milliseconds.
Expand Down
Loading
Loading