feat(telemetry): trace dispatch, startup, and shutdown

[davidzhao]

What

Before the first turn and after the last one the trace had a single span, job_entrypoint, so "the agent took 4 s to say hello" and "the job hung on shutdown" could not be split into their steps. This adds the dispatch timeline, the startup spans, the shutdown spans, and the join keys for lining the agent trace up with server, SIP, and client events later.

Dispatch timeline

• The worker stamps received_at, accepted_at, assigned_at on RunningJobInfo; the process pool stamps launched_at. StartJobRequest carries the four as 64-bit doubles (a 32-bit float only resolves ~128 s at unix-epoch magnitude, which made every latency read 0).
• job_entrypoint is back-dated to received_at and gets one timestamped event per stage (job_received, job_accepted, job_assigned, process_assigned, entrypoint_started, job_started_on_server from JobState.started_at). The attributes are the seconds between adjacent stages, so the chain reads off the span without timestamp arithmetic: lk.job.accept_latency (request → accept), assignment_latency (accept → server assignment), launch_latency (assignment → a pool process takes the job), entrypoint_latency (process takes the job → user entrypoint runs), and their sum dispatch_latency. Raw *_at unix timestamps are not set as attributes. Unknown stages (simulation, console, resumed jobs) are skipped, not guessed.
• agent_session is a child of job_entrypoint, so the job's trace tells the whole story from dispatch to teardown: job_entrypoint → (room_connect, agent_session, …, job_shutdown). Nothing is replayed or re-parented for the session's benefit; a viewer keyed to agent_session zooms out to the job for the rest.
• The trace pipeline is up before the job's first span. Until now the cloud tracer provider was created on the first init_recording (inside session.start()), so in a process's first job every earlier span was a non-recording stub: job_entrypoint and room_connect were lost, and agent_session had no valid parent and started its own trace (that is why it rendered as a root). JobContext._prepare_telemetry now creates the provider and the gated exporter when the job starts, registering nothing; the gate holds the job's spans (oldest first, bounded) until init_recording decides, then uploads or drops them, and drops them at cleanup if the job never registers.
• job_entrypoint spans the whole job. It is created before the user entrypoint runs and ended after job_shutdown, just before the telemetry release flushes, so the root covers dispatch, session and teardown. The user function returning is an entrypoint_returned event on it (most entrypoints return right after session.start()); a raising entrypoint is recorded redaction-aware, a cancelled one as entrypoint_cancelled.
• Join keys on job_entrypoint and agent_session: lk.room_sid, lk.dispatch_id, lk.job.worker_id, lk.job.agent_id. A linked SIP participant's sip.* attributes are copied onto agent_session under lk.sip.* (call id, trunk id and number, rule id, status, headers); only the end user's sip.phoneNumber is PII and lands as lk.pii.sip.phoneNumber.

Startup

• room_connect around JobContext.connect: room ids, auto_subscribe, e2ee, local participant, remote participant count; error status on failure. Called before session.start() it lands under job_entrypoint; called while the session is starting it nests under session_start.
• session_start groups AgentSession.start(): start_agent_activity, setup_toolsets, RoomIO's wait_for_participant, publish_audio_output, and the room connect. Only startup work is parented there via explicit contexts; user_turn / agent_turn stay directly under agent_session (tested).
• wait_for_audio_track on the RoomIO audio input: linked participant → first frame, with track_subscribed, pre_connect_audio, and first_frame events and lk.first_frame_delay.
• Events on agent_session: participant_linked, participant_disconnected (reason), connection_state_changed, agent_state_changed, user_state_changed.

Shutdown

• session_close wraps the AgentSession close with lk.close_reason (enum) and lk.close.drain; drain_agent_activity and on_exit nest inside it.
• job_shutdown wraps the job's shutdown sequence with lk.shutdown.reason and children on_session_end, session_end_upload, room_disconnect, and one shutdown_callback per user callback named by lk.callback.name (the session's own close hook runs without a span: it is already session_close). It is a child of job_entrypoint, like the session.
• user_turn is pinned to the session root explicitly. It can be created from any task (a late STT final arriving during session_close, for one) and used to nest under whatever was current there.
• Startup spans are never current. session_start, room_connect, wait_for_participant, publish_audio_output and setup_toolsets wrap code that spawns the tasks living for the whole session (the room's event tasks, the published track, MCP servers). A current span there is inherited by those tasks and becomes the accidental parent of unrelated spans they emit later: in a real run user_speaking from the room's active-speaker callback landed under room_connect. They are now created with tracer.detached_span(name, context=...): parented explicitly (under session_start while it runs), never attached to the context.
• Process warm-up (_preload_for_jobs, before the user prewarm function) does the framework's own lazy one-time work: it loads the livekit-rtc native library (otherwise the first FFI call, the AudioProcessingModule at session start, took 100–350 ms) imports the openai SDK's resources tree (otherwise the inference LLM prewarm's first client attribute access took ~300 ms), and builds one httpx client so the process's SSL context exists (otherwise the first inference client construction took ~50 ms of GIL-held CPU at session start). Both showed up as event_loop_blocked at session start that no user code caused.
• Job cleanup (tempdir removal, the per-job telemetry release that joins exporter flush threads) moved off the event loop into asyncio.to_thread, so shutdown no longer stalls the loop the monitor watches, and THREAD-executor jobs sharing the process are not held up.

job_entrypoint  (back-dated to job_received; events per stage)
├─ agent_session
│  ├─ session_start
│  │  ├─ room_connect
│  │  ├─ wait_for_participant
│  │  ├─ wait_for_audio_track
│  │  ├─ publish_audio_output
│  │  └─ start_agent_activity
│  │     ├─ setup_toolsets
│  │     └─ on_enter
│  ├─ user_turn / agent_turn ...
│  └─ session_close
│     ├─ drain_agent_activity
│     └─ on_exit
└─ job_shutdown
   ├─ on_session_end
   ├─ session_end_upload
   ├─ room_disconnect
   └─ shutdown_callback (×N)

Tests

tests/test_startup_spans.py: StartJobRequest round trip, dispatch events and latencies, server timestamp units, room_connect under the job span, success and failure, shutdown callback naming, and a full fake session asserting the session_start / session_close nesting, that turns are not re-parented, and the state events. tests/test_recording.py: the gate holds, flushes and drops spans of undecided jobs; the prepared pipeline holds early spans until the job registers.

Not covered by unit tests (needs a real room): wait_for_audio_track and publish_audio_output.

Stacked on #7130.

🤖 Generated with Claude Code