fix(worker): transcribe the speech, not the padded track - #48
Merged
Conversation
`WhisperEngine._transcribe` decoded a speaker's recording, found the
audible regions with the amplitude gate and then handed faster-whisper
the *whole* array, marking the speech with `clip_timestamps`. The library
shrinks the array only inside its `vad_filter` branch -- `if vad_filter
and clip_timestamps == "0"`, then `audio = np.concatenate(audio_chunks)`
-- and setting clips is exactly what skips that branch, so log-mel
extraction ran over the padding too and scaled with the padded length of
a track rather than with what was said. That is why the worker's memory
limit had to be raised from 6Gi to 12Gi in production.
The gated speech is now concatenated here and handed over as one short
array, with `clip_timestamps` re-expressed on that timeline and the
returned segment times mapped back onto the recording's afterwards.
Measured end to end through the real `_transcribe`, on a 100-minute
mostly-padding track of the shape the recording that started this has --
187 clips, 41.2 minutes of speech, bit-exact zero between them. Both runs
back to back on the same idle machine, `tiny`/int8, beam 8:
peak RSS wall clock CPU
before 5025 MB 331 s 1276 s
after 2441 MB 318 s 1255 s
Peak resident memory falls by 2.58 GB, 51%, and it now scales with speech
rather than with session length -- a four-hour meeting no longer costs
more than a one-hour one for the same amount of talking. The `before`
peak moves a few percent between runs (an earlier pair gave 5214 MB); the
`after` peak did not move at all across four runs, because it is set by
the size of the speech and that is the same array every time.
Wall clock is unchanged within run-to-run noise, which is the expected
result and not a disappointment: the extraction that was allocating those
gigabytes is a small share of the time, and this change deliberately
keeps the encoder work identical (see below).
`tiny` rather than `large-v3` because those weights are not on the
measuring machine. The term that moves is the log-mel extraction, which
does not depend on the model at all; large-v3's ~1.55 GB of resident
weights adds to both rows equally, putting the old path at ~6.5 GB
against a 6Gi (6.44 GB) limit and the new one at ~3.9 GB. Segment counts
differ a little between runs of identical code, so they are not a signal
either way -- CTranslate2 is not bit-reproducible across threads.
The clip boundaries stay, on the new timeline. They are what stops an
encoder window spanning two utterances spoken minutes apart:
`segment_size = min(nb_max_frames, content_frames - seek, seek_clip_end -
seek)` caps a window at the clip it began in. Dropping them -- plain
concatenation plus `restore_speech_timestamps`, the library's own helper
-- was measured emitting a single 258-second segment covering four
utterances spoken 9 s, 47 s, 96 s and 150 s into a recording, because
that helper resolves a segment's `start` and `end` independently.
So the restore is our own arithmetic, and **a segment is attributed to
the clip its encoder window came from, never to the clip its reported
times fall in**. `Segment.seek` is that window's first log-mel frame, and
the seek loop never decodes a window from outside the clip it is walking,
so the frame names one clip and only one. Comparing it against our own
clip boundaries on the library's `round(ts * frames_per_second)` grid,
then clamping the result into that clip, gives the guarantee the change
needs: a restored segment always lies inside the file-timeline extent of
the clip whose window produced it.
Reading the clip off the times cannot give that. A decoded `end` is
`time_offset + end_timestamp_position * time_precision` and
`_split_segments_by_timestamps` caps neither it nor the seek positions it
derives at the window's content, so a tail segment routinely claims audio
the window never held. On the 187-clip track above, with the times-based
rule, 57 of 462 segments reported an `end` past their clip and 5 of them
overran by more than half the segment -- coming back 20 to 31 seconds
from where they were spoken, one of them carrying 14 seconds of text. The
error is always exactly one removed gap, so on a session with three
utterances forty minutes apart it is forty minutes. That is the same
silent wrong timestamp the library's helper produces; relocating it into
our own file would not have made it acceptable.
Nothing at any test tier observed the library behaviour all of this rests
on, and a fake model cannot: a fake breaks the way its author imagined.
`test_a_window_never_spans_two_clips` therefore drives the real
`generate_segments` with a stand-in `self` -- no weights, no download, so
it stays out of the `slow` marker -- and asserts that the windows the real
seek loop schedules tile exactly the frame ranges this adapter computes.
It fails if `segment_size` stops being capped at the clip, if
`Segment.seek` stops being the window's first frame, or if the boundary
rounding changes. `pyproject.toml` pins `faster-whisper>=1.1` with no
upper bound and Renovate merges on a green build, so that test is the
only upper bound there is.
The per-clip encoder cost is deliberately not fixed here. 187 clips still
pay a 30-second window each, and that is the trade: the 2.2x of encoder
work is bought with segment timestamps wrong by up to 258 seconds, and a
meeting protocol whose entire output is "who said what, when" cannot
spend correctness on CPU time. Making clips longer (`_MERGE_GAP_SECONDS`)
recovers it later without touching any of this.
`charts/sturnus/values.yaml` is fixed in the same commit: the comment
above `resources` still claimed `vad_filter` was what kept the padded
length out of the decoder, and it never costed the extraction term at
all. The numbers are unchanged -- requests 4Gi, limits 6Gi -- because the
point is that they are true again, so the 12Gi override in the deployment
repo can be reverted rather than replaced.
0.5.1 (#46) landed in the same method: it closes the `log_prob_threshold` veto that let Whisper's invented subtitle credits through, and it logs what the guard discarded. Both are additive to what this branch does and both are kept. Two of main's tests were dropped rather than merged, because they pin the mechanism this branch inverts: `test_the_model_is_given_the_whole_array_and_ the_clips_the_gate_found` and `test_offsets_are_returned_unchanged` assert that the model receives the padded array and that offsets pass through unmapped. Neither is true any more -- the model is handed the concatenated speech and the offsets are restored -- and the replacements (`test_the_model_is_handed_the_speech_and_not_the_padded_track`, `test_segment_times_come_back_on_the_recordings_own_timeline`) assert the same properties of the new arrangement. main's two logging tests predate `_FakeSegment.seek` and now go through `_as_decoded_from`, the helper this branch added for exactly that. Main's closing comment about `clip_timestamps` starting language detection at the first clip is superseded: the model no longer sees the padding at all, which is a stronger version of the same statement.
TheMeinerLP
added a commit
that referenced
this pull request
Aug 21, 2026
#43 (silent-audio detection) and #48 (transcribe the speech, not the padded track) landed while this waited. Two conflicts, both additive: `tests/infrastructure/test_repositories.py` needed `select` and `update` from sqlalchemy rather than one or the other -- #43's repository test reads a column back, this branch's compare-and-set writes one. `docs/operations.md` section 5 gained two independent troubleshooting entries at the same anchor: this branch's `/queue` walkthrough and #43's 'a speaker's audio arrives with no level'. Both stay; they answer different questions and neither supersedes the other.
TheMeinerLP
added a commit
that referenced
this pull request
Aug 21, 2026
…content
OpenTelemetry traces and metrics, plus structured logging shaped for Loki.
Squashed to a single commit on top of main. Two earlier commits on this
branch carried fixtures with the literal shape of a credential -- an AWS
access key id and a Discord bot token -- which secret scanning detects,
correctly, whether or not either string opens anything. Both are now
assembled from parts at import: identical at runtime, so the tests still
prove the redaction catches those exact shapes, with nothing in the file
for a scanner or a reader to mistake for a credential. Rewriting the tip
alone would not have helped; a scan reads every commit in the pull
request, so the literals had to leave the history.
**Redaction is an allowlist, not a denylist.** Unregistered field names are
dropped, `bytes` is dropped as a class (audio and wrapped data keys are
always bytes, so that closes the highest-value leak by construction),
strings are pattern-scrubbed and capped, and every replacement is visible
(`«redacted:discord_token»`) rather than silent.
**The leak this branch closed.** With `STURNUS_LOG_LEVEL=DEBUG` the Discord
voice `secret_key` reached the logs and would have reached Loki.
Reproduced:
discord/ext/voice_recv/gateway.py:57
log.debug("Received op %s: \n%s", op, pformat(data))
-> {'mode': ..., 'secret_key': [1, 2, ..., 32], 'ssrc': ...}
Not a redaction failure: `extra={"secret_key": ...}` was dropped, and so was
`extra={"voice_ready": {...}}`. The key arrived already formatted into a
third-party logger's *message string*, which a field allowlist cannot
touch. The cause was `root.setLevel(min(resolved_level,
resolved_third_party))`, which put 28 unclamped third-party loggers at
DEBUG -- every logger absent from the enumerated clamp list inherits from
root, and one list cannot be complete about libraries it does not import.
That `min()` was never load-bearing (Python checks the *originating*
logger's effective level on propagation, never root's), so removing it
costs nothing and closes the hole. `THIRD_PARTY_FLOOR` replaces the
enumeration as the structural half of the fix, and
`tests/observability/test_third_party_log_floor.py` asserts the property
over `logging.Logger.manager.loggerDict` rather than over a list.
`discord.voice_state` is pinned at INFO rather than silenced: DEBUG is where
the leak lives, but INFO is the connect narrative -- handshake attempts,
endpoint, close codes, resume -- and it is the evidence base for telling
the three capture failures apart. Pinning needed a `NEVER_ABOVE`
counterpart: `NEVER_BELOW` is applied as `max(level, floor)` and can only
ever make a logger *quieter*, so an INFO entry there was a no-op at the
deployed `WARNING` default -- the logger still ended at WARNING and the
line the entry was written to keep was still gone.
**The metrics answer questions this project actually had.**
`sturnus.transcription.decoded_seconds` divided by wall time is the
real-time factor: a job that "finished" a 100-minute recording in 43
seconds reports an impossible, unmistakable number -- where the symptom
everyone saw, an empty transcript, looked exactly like a participant who
never spoke and was misread as one for a day. `position_seconds`,
`total_seconds` and `seconds_since_progress` are **observable instruments,
not synchronous gauges**: a gauge only changes when a call site sets it, so
a decoder that wedges freezes it and `seconds_since_progress` -- the actual
alert -- could never grow. The SDK calls these callbacks once per export
interval instead, which is also what lets them emit nothing at all while
the worker is idle, so the series goes stale rather than reporting a
finished job's numbers forever. The stall clock starts before the library
call, since the collapse happened inside feature extraction. Labels are
`model` only: no session, job, guild or user id, which would be unbounded
cardinality and a record of who was in a voice channel when, kept for as
long as the metric store keeps anything.
`sturnus.job.outcome` reported `done` for every failed job, because
`process_one` returns True after `queue.fail(...)` exactly as it does after
`queue.complete(...)` -- the boolean means "work was attempted", never
"work succeeded", and a metric that reports failures as successes is worse
than no metric because it will be believed. The label is now recorded by
the transitions that decide a job's terminal state, and `crashed` is the
one the worker loop still owns.
**Rebased onto #48, which rewrote the same method.** The transcription
mechanics are main's: the model is handed the gated speech concatenated,
`clip_timestamps` is re-expressed on that timeline, and every returned
segment goes back onto the recording's through
`_on_the_original_timeline(segment.start, segment.end, segment.seek, ...)`,
where `Segment.seek` -- the encoder window the segment was decoded from --
is what names its clip. The observability is re-expressed on top: the
segment generator is drained by a loop and not a comprehension, so
`TRANSCRIPTION_PROGRESS` sees each segment as it arrives rather than only
after the job has already finished.
Progress is reported on the *concatenated* timeline -- `advance(segment.end)`
and not the restored end -- because the denominator is
`duration_after_vad`, which since #48 is the concatenated speech. Reporting
a restored end against it would put a job that had decoded its first clip
at several hundred percent. `telemetry.TranscriptionProgress` and
`docs/operations.md` § 7.5 say so; they described the whole file before.
Two call sites arrived from main that the merge could not have seen, both
of them what `tests/test_logging_discipline.py` R2 and R6 forbid, and for
the reason R6 exists: `%s` on an exception prints `str(exc)` verbatim into
the message `observability.scrub_event` forwards to Sentry.
`RecordingService._report_silent_audio` (#48) was three `log.warning`
calls, two interpolating an exception and one passing `display_name`; it is
now `speaker.audio_silent`, `speaker.silent_warning_failed` and
`speaker.silent_record_failed` through `log_event`/`log_exception`, with
`display_name` gone -- the channel message renders the mention, and the
operator has the id. `RequeueConfirmView._disable` (#49) is now
`queue.view_disable_failed` the same way.
TheMeinerLP
added a commit
that referenced
this pull request
Aug 21, 2026
…content (#50) OpenTelemetry traces and metrics, plus structured logging shaped for Loki. Squashed to a single commit on top of main. Two earlier commits on this branch carried fixtures with the literal shape of a credential -- an AWS access key id and a Discord bot token -- which secret scanning detects, correctly, whether or not either string opens anything. Both are now assembled from parts at import: identical at runtime, so the tests still prove the redaction catches those exact shapes, with nothing in the file for a scanner or a reader to mistake for a credential. Rewriting the tip alone would not have helped; a scan reads every commit in the pull request, so the literals had to leave the history. **Redaction is an allowlist, not a denylist.** Unregistered field names are dropped, `bytes` is dropped as a class (audio and wrapped data keys are always bytes, so that closes the highest-value leak by construction), strings are pattern-scrubbed and capped, and every replacement is visible (`«redacted:discord_token»`) rather than silent. **The leak this branch closed.** With `STURNUS_LOG_LEVEL=DEBUG` the Discord voice `secret_key` reached the logs and would have reached Loki. Reproduced: discord/ext/voice_recv/gateway.py:57 log.debug("Received op %s: \n%s", op, pformat(data)) -> {'mode': ..., 'secret_key': [1, 2, ..., 32], 'ssrc': ...} Not a redaction failure: `extra={"secret_key": ...}` was dropped, and so was `extra={"voice_ready": {...}}`. The key arrived already formatted into a third-party logger's *message string*, which a field allowlist cannot touch. The cause was `root.setLevel(min(resolved_level, resolved_third_party))`, which put 28 unclamped third-party loggers at DEBUG -- every logger absent from the enumerated clamp list inherits from root, and one list cannot be complete about libraries it does not import. That `min()` was never load-bearing (Python checks the *originating* logger's effective level on propagation, never root's), so removing it costs nothing and closes the hole. `THIRD_PARTY_FLOOR` replaces the enumeration as the structural half of the fix, and `tests/observability/test_third_party_log_floor.py` asserts the property over `logging.Logger.manager.loggerDict` rather than over a list. `discord.voice_state` is pinned at INFO rather than silenced: DEBUG is where the leak lives, but INFO is the connect narrative -- handshake attempts, endpoint, close codes, resume -- and it is the evidence base for telling the three capture failures apart. Pinning needed a `NEVER_ABOVE` counterpart: `NEVER_BELOW` is applied as `max(level, floor)` and can only ever make a logger *quieter*, so an INFO entry there was a no-op at the deployed `WARNING` default -- the logger still ended at WARNING and the line the entry was written to keep was still gone. **The metrics answer questions this project actually had.** `sturnus.transcription.decoded_seconds` divided by wall time is the real-time factor: a job that "finished" a 100-minute recording in 43 seconds reports an impossible, unmistakable number -- where the symptom everyone saw, an empty transcript, looked exactly like a participant who never spoke and was misread as one for a day. `position_seconds`, `total_seconds` and `seconds_since_progress` are **observable instruments, not synchronous gauges**: a gauge only changes when a call site sets it, so a decoder that wedges freezes it and `seconds_since_progress` -- the actual alert -- could never grow. The SDK calls these callbacks once per export interval instead, which is also what lets them emit nothing at all while the worker is idle, so the series goes stale rather than reporting a finished job's numbers forever. The stall clock starts before the library call, since the collapse happened inside feature extraction. Labels are `model` only: no session, job, guild or user id, which would be unbounded cardinality and a record of who was in a voice channel when, kept for as long as the metric store keeps anything. `sturnus.job.outcome` reported `done` for every failed job, because `process_one` returns True after `queue.fail(...)` exactly as it does after `queue.complete(...)` -- the boolean means "work was attempted", never "work succeeded", and a metric that reports failures as successes is worse than no metric because it will be believed. The label is now recorded by the transitions that decide a job's terminal state, and `crashed` is the one the worker loop still owns. **Rebased onto #48, which rewrote the same method.** The transcription mechanics are main's: the model is handed the gated speech concatenated, `clip_timestamps` is re-expressed on that timeline, and every returned segment goes back onto the recording's through `_on_the_original_timeline(segment.start, segment.end, segment.seek, ...)`, where `Segment.seek` -- the encoder window the segment was decoded from -- is what names its clip. The observability is re-expressed on top: the segment generator is drained by a loop and not a comprehension, so `TRANSCRIPTION_PROGRESS` sees each segment as it arrives rather than only after the job has already finished. Progress is reported on the *concatenated* timeline -- `advance(segment.end)` and not the restored end -- because the denominator is `duration_after_vad`, which since #48 is the concatenated speech. Reporting a restored end against it would put a job that had decoded its first clip at several hundred percent. `telemetry.TranscriptionProgress` and `docs/operations.md` § 7.5 say so; they described the whole file before. Two call sites arrived from main that the merge could not have seen, both of them what `tests/test_logging_discipline.py` R2 and R6 forbid, and for the reason R6 exists: `%s` on an exception prints `str(exc)` verbatim into the message `observability.scrub_event` forwards to Sentry. `RecordingService._report_silent_audio` (#48) was three `log.warning` calls, two interpolating an exception and one passing `display_name`; it is now `speaker.audio_silent`, `speaker.silent_warning_failed` and `speaker.silent_record_failed` through `log_event`/`log_exception`, with `display_name` gone -- the channel message renders the mention, and the operator has the id. `RequeueConfirmView._disable` (#49) is now `queue.view_disable_failed` the same way.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Passing the whole decoded array with
clip_timestampsmade faster-whisper run log-mel extraction over the entire padded file — a speaker's track is mostly bit-exact zero. Measured 4954 MB for extraction alone on a 100-minute recording, which forced the production worker's memory limit from 6Gi to 12Gi as a stopgap.This concatenates the gated speech first, so memory scales with speech instead of with session length.
Memory falls 51%. Speed does not change, deliberately — the design keeps one window boundary per clip so no encoder window ever spans a seam. Packing windows full would be roughly 2.2x faster and is a separate decision, unsafe until timestamp attribution is trustworthy, which is what this branch establishes.
The library's own shape was tried first and fails
Doing what faster-whisper's
vad_filterbranch does — concatenate, thenrestore_speech_timestamps— was measured end to end and broke badly: six utterances at known offsets came back as two segments, one of them 258 seconds long, becauserestore_speech_timestampsresolves a segment'sstartandendindependently and nearly every 30-second window contains a join. A probed 1.00 s segment centred on a seam restored to 33.77 s.Keeping
clip_timestampson the concatenated timeline preservessegment_size = min(nb_max_frames, content_frames - seek, seek_clip_end - seek), so a window can never cross a clip boundary.The attribution blocker, found by all three reviewers independently
The first implementation picked a segment's clip from the midpoint of its reported times. That is safe against the ±5 ms frame-grid rounding it argued about — and not against the decoder reporting an
endpast the real audio in its window, which faster-whisper never clamps.Reproduced on the real engine with that code: 57 of 462 segments reported an
endpast their clip, and 5 overran by more than half their own length, restoring 20–31 s from where they were spoken — one carrying 14 s of text. The displacement is always exactly one removed gap, so on a sparse recording it is minutes.Fixed by reading
Segment.seek— the first log-mel frame of the window the segment was decoded from — instead of inferring the clip from the times, then clamping into that clip's extent. Guarantee: a restored segment always lies inside the file-timeline extent of the clip whose window produced it, whatever the decoder claimed.A test for the library behaviour the design rests on
test_a_window_never_spans_two_clipsdrives the realgenerate_segmentsloop with no model weights: the model is built withobject.__new__and given only what the seek loop reads, withencode/get_prompt/generate_with_fallbackstubbed. Clip boundaries sit deliberately off the 10 ms grid, so a library that truncated where it now rounds would start a clip's first window one frame early and the tiling would not close.pyproject.tomlpinsfaster-whisper>=1.1with no ceiling and Renovate auto-merges on green, so without this a refactor upstream would produce silently wrong timestamps. This makes it go red instead. No download, no network, notslow.Verification
648 tests, mypy and ruff clean. 16 mutants, all killed — including
round→intin the frame grid, five wrong clip-index rules, four clamp variants, and the library test's own falsifier. Two survivors were found mid-way and each got a test.Worth second-guessing
_on_the_frame_gridreproducesround(ts * frames_per_second). No oracle was found that determines a window's clip without it; the mitigation is that the library test cross-checks our frames against the real loop's window starts.AttributeError, not a behaviour message. A loud false alarm was judged better than silence.segment.seekis accessed unguarded: if a release drops the field the worker raises mid-job rather than falling back. Deliberate — a silent fallback is the failure mode being removed — but it is a production crash.