turn_latency never fires on the native realtime front (turn-latency decomposition covers only the cascade path)

[octalpixel]

Problem

The session emits a turn_latency event carrying the per-turn latency decomposition
(ttfaMs plus eouDelayMs / llmTtftMs / ttsTtfbMs). It is the only per-stage latency
instrument in the product.

Actual: on the native realtime front the event never fires at all. Not partial fields —
the entire event is absent for every turn. Any latency dashboard, gate, or regression check
built on it silently reads zero for native while working normally for cascade.

Expected: turn_latency fires once per voice turn on every front, and the meaning of
ttfaMs is unambiguous.

Repro: drive one turn through a native realtime session (realtime adapter + bridge) with a
tool-calling reasoner, and subscribe to turn_latency. Nothing is emitted. The same fixture
through the cascade session emits it normally.

Measured on a live run: assistant first audio landed ~1.6s before the session's own
end-of-speech event for the same turn.

Root Cause Analysis

Three independent defects compound:

1. The instrument encodes a cascade-shaped ordering assumption. The turn-timing record for
a turn is first created when the session handles end-of-speech. The latency event is emitted
from the first-assistant-audio handler, which bails when no timing record exists yet. On
cascade that ordering always holds (endpoint precedes generation precedes audio). Native S2S
inverts it: the provider begins speaking before Syrinx's own endpointer concludes, so at
first-audio time no record exists and the turn is dropped silently.

2. The realtime bridge never contributes turn timings. It surfaces transcripts and
end-of-speech but never records speech-end, first-LLM-delta, or first-TTS-text for the turn.
So even with the ordering fixed, native would yield a total with no stage breakdown.

3. The adapter event surface drops the provider's end-of-user-speech signal. The realtime
event union models speech start but has no speech stop variant. The OpenAI-compatible
adapter receives the provider's speech-stopped event and discards it, so the bridge has no
end-of-speech signal to publish and the session's speech-end anchor is never set.

This is the same lossy-adapter-surface pattern as #28/#32 (Gemini transcription received but
not surfaced): the provider sends a signal, the adapter drops it, a downstream consumer
silently degrades.

Contributing factor — a silent anchor fallback. ttfaMs is anchored on speech-end when
available and falls back to the endpoint event otherwise, with nothing in the payload
recording which was used. So ttfaMs can silently change meaning between turns and between
fronts while keeping the same name. Two different metrics wear one label.

TDD Fix Plan

1. RED: A turn whose assistant audio arrives before the end-of-speech event still emits
   exactly one turn_latency.
   GREEN: Create the turn-timing record on demand from the first-audio path instead of
   bailing when absent.

2. RED: The turn_latency payload states which anchor ttfaMs was measured from, and a
   turn with no speech-end anchor reports the endpoint anchor rather than an unlabelled number.
   GREEN: Add an explicit anchor discriminator to the payload and populate it at emit time.

3. RED: A realtime adapter receiving the provider's end-of-user-speech signal surfaces a
   corresponding speech-stopped event to its consumer.
   GREEN: Add a speech-stopped variant to the realtime event contract and emit it from the
   OpenAI-compatible adapter.

4. RED: A realtime bridge observing speech-stopped publishes an end-of-speech signal that
   the session records as the turn's speech-end anchor.
   GREEN: Translate the adapter event into the session-level end-of-speech packet.

5. RED: One native realtime turn emits turn_latency with a speech-end anchor and a
   non-empty stage breakdown.
   GREEN: Populate first-LLM-delta and first-TTS-text timings from the bridge's generation
   path.

6. RED: A text-injected (non-voice) turn still emits no turn_latency, and a barge-in
   turn is not double-counted.
   GREEN: Preserve the existing guards while relaxing only the ordering assumption.

REFACTOR: Extract the stage-attribution arithmetic so cascade and native produce the
payload through one path, and the ordering assumption cannot be reintroduced in one front only.

Acceptance Criteria

• turn_latency fires exactly once per voice turn on both the cascade and native realtime fronts
• The payload states which anchor ttfaMs was measured from; no silent fallback
• The realtime event contract models end-of-user-speech, and the OpenAI-compatible adapter emits it
• A native turn reports a non-empty stage breakdown, not just a total
• Non-voice turns still emit nothing; barge-in turns are not double-counted
• All new tests pass
• Existing tests still pass

[octalpixel]

Partial fix landed; the native arm still does not emit. Live trace of a native turn (OpenAI Realtime + delegated reasoner), ordered, with contextIds:

[+15941ms] llm.delta          ctx=idle-1784472678604
[+15958ms] tts.text           ctx=idle-1784472678604
[+21770ms] turn.change        ctx=ebcd76e5-...
[+22756ms] tts.audio          ctx=ebcd76e5-...
[+24548ms] eos.turn_complete  ctx=ebcd76e5-...
[+24551ms] tts.end            ctx=ebcd76e5-...

Three distinct problems, only the first of which was in the original diagnosis:

1. No user-side speech-end signal reaches the session on native at all. Neither vad.speech_started nor vad.speech_ended appears. The bridge's speech_started handler pushes interrupt.detected, not a VAD packet, and is gated on caps.emitsServerSpeechStarted. The speech_stopped -> vad.speech_ended wiring added for this issue does not produce a packet in practice — still to determine whether input_audio_buffer.speech_stopped is not arriving from the provider, or the handler's contextId guard rejects it.

2. eos.turn_complete arrives AFTER first audio (24548ms vs 22756ms), so it cannot serve as a fallback anchor at emit time. The ordering fix alone is insufficient — there is genuinely no anchor available when emitTurnLatency runs.

3. contextId changes twice, not once. llm.delta/tts.text land on an idle-* context; turn.change then rotates to a UUID that carries tts.audio/eos. A turn.change carry-forward has been added so timings survive the rotation, but it does not help while there is no anchor to carry.

Note on test coverage: all turn_latency unit tests use a single hardcoded contextId, so none of them can exercise identity rotation — the suite was green throughout while the feature had never worked on this path. Turn-identity work on this instrument needs a live proof, not a suite.

Cascade remains fully working and now reports the added fields (anchor, textAggregationMs, unattributedMs, llmCallCount, llmPassTtftMs) — measured on a live cascade turn: ttfaMs 4114ms = llmTtft 3539 + ttsTtfb 242 + unattributed 333.

[octalpixel]

Native now emits. Root cause was none of the earlier guesses: speech_stopped arrives before response_started, when the bridge's contextId is still empty, so the if (!this.contextId) return guard dropped it. Found by adapter-level tracing after two patches from plausible-but-wrong diagnoses both passed the suite and failed live. Fix buffers the pre-response speech-end and binds it on response_started.

Live proof — native:

[+22795ms] vad.speech_ended   ctx=e7eedb27-...     <- was absent entirely before
[+23581ms] tts.audio          ctx=e7eedb27-...
  ttfaMs         798ms   anchor=speech_end
  llmTtftMs      523ms
  unattributedMs 275ms

Live proof — cascade, fully attributed:

  ttfaMs            1685ms   anchor=eos
  llmTtftMs         1241ms
  textAggregationMs  233ms
  ttsTtfbMs          211ms
  unattributedMs       0ms      (1241 + 233 + 211 = 1685)
  llmCallCount         1  passTtft=[1238]

unattributedMs reaching exactly 0 on cascade is the strongest available evidence the stage model is correct — and on native it correctly reports 275ms unexplained rather than implying full attribution. That field was the one part of this design with no prior art in LiveKit, Pipecat or the OTel GenAI conventions, and it has now earned its place twice: it caught the sentence-aggregation stage originally, and it is what makes the native gap legible instead of invisible.

Remaining (tracked separately): the native breakdown is incomplete. Four fields are n/a there, each with a distinct cause — eouDelayMs (eos arrives after first audio, so eosMs is unset at emit time), textAggregationMs and ttsTtfbMs (llm.delta/tts.text land on the idle-* context and the carry-forward did not bring firstTtsTextMs across), and llmCallCount (aisdk per-pass metrics not wired on the delegate path).

One thing worth a second look: cascade reports llmCallCount 1 on a turn that called a tool, which should imply at least two passes. Possible under-count in the metric wiring.

Process note. All turn_latency unit tests bar one still hardcode a single contextId (~203 literals), so the suite remains structurally incapable of catching identity bugs of this class. Three fix attempts here were green throughout. Turn-identity work on this instrument should be gated on the live harness (SYRINX_SPIKE_TRACE=1 SYRINX_SPIKE_ARM=native), not on tests.

[octalpixel]

Complete. turn_latency fires on both fronts with a full stage breakdown, is exported as histograms, and has a live release gate.

Final live state (pnpm smoke:turn-latency):

=== cascade ===  fired=true  anchor=eos          ttfaMs=1791  stages=3/4
=== native  ===  fired=true  anchor=speech_end   ttfaMs=482   stages=1/4
TURN-LATENCY SMOKE PASSED (cascade, native)

Cascade attributes exactly — unattributedMs 0 on a clean turn. Native reports three n/a by documented design, not omission: its endpointing is provider-owned and eos.turn_complete arrives after first audio, so there is no Syrinx endpoint-delay stage; and the llm.delta/tts.text on the idle-* context belong to the prior turn, so reporting them as this turn's aggregation would be a fabrication. An honest n/a beat a wrong number.

Also fixed along the way:

• llmCallCount returned 1 on a tool-calling turn, which is impossible — a grounded answer needs at least two round-trips. Passes are now bounded at tool-call/tool-result, with emission deferred to tts.end so post-tool passes are counted. ttfaMs still measures to first audio; only the emit moved.
• That deferral then made barged turns emit nothing at all. Barge-in correlates with slow turns, so dropping them biased the sample toward fast ones — the worst turns would have vanished from exactly the metric meant to surface them. interrupt.detected now flushes the pending event.
• ObservabilityObserver was tagging v2v_ms/thinking_ms/agent_speech_ms with sessionId and speechId — unbounded cardinality on the only histograms the product exported. Removed from the metric dimensions; they stay on the obs.turn_boundary event.

Process note worth keeping. Three consecutive fix attempts on the native bug passed the unit suite (294, then 295 tests) and failed live. voice-agent-session.test.ts has ~203 hardcoded contextId literals against one test that rotates — the bugs in this area are all about identity changing mid-turn, so the suite is structurally blind to the class. smoke:turn-latency is the mitigation: it fails if the event does not fire, fires without an anchor, or reports a total with zero stages (the "instrument on but blind" state, which looks healthy on a dashboard). The 203 literals remain; a rotation-by-default test helper is the structural fix and is not built.

Commits: 916ebfb, 0a57a6c, 4bda69d, 372dadc.