fix(swift): anchor realtime answer-generation span to response.created

swift/SKILL.md

@@ -125,7 +125,11 @@ signatures live in `Sources/AgentSquad/`.
 - **Storage**: `FileChatStorage` (JSON, iOS 16+, scopes per-call by `userId`/`sessionId`/`agentId` — e.g. `sessionId` to isolate per match) or `DeviceChatStorage` (SwiftData, iOS 17+, bound to one `userId`). Both default to Library/Caches (disposable). `InMemoryChatStorage` (iOS 16+) is non-persistent and holds one conversation — construct it empty or seeded with a prior conversation to load one into a session. Wrap any store in `TransformingChatStorage` to scrub/redact before persistence; prefer redacting over returning `nil` (dropping one side of an exchange can make the store skip its counterpart via the consecutive-same-role guard).
 - **Tracing lifecycle**: nothing drains the tracer for you — flush on background, shut down on
   termination. `OSLogTracer` logs no payloads. `Redaction` hashes ids + clips strings but does **not**
-  pattern-scrub PII — supply a custom `Redactor` for that.
+  pattern-scrub PII — supply a custom `Redactor` for that. A realtime answer generation
+  (`response`/`presenter`) is backdated to its `response.created` receive-time via
+  `SpanHandle.generation(…, startedAt:)`, so the exported span carries the real call latency instead
+  of a ~0 duration (the Realtime API sends no server-side timing). The overload defaults to stamping
+  now, so custom `SpanHandle`s need not implement it.
 - **Realtime** is a peer runtime, not an agent; its `events` stream is non-throwing; needs
   `NSMicrophoneUsageDescription`; always `stop()`. In-band failures arrive as
   `.error(code:message:)` — `code` is the API's machine code (e.g. `rate_limit_exceeded`),

swift/Sources/AgentSquad/Core/Tracing/ProcessingTracer.swift

@@ -53,6 +53,10 @@ struct ProcessedSpan: GenerationHandle {
         child(kind: .generation, name: name, input: input, model: model)
     }
 
+    func generation(_ name: String, model: String, input: JSONValue?, startedAt: Date) -> any GenerationHandle {
+        child(kind: .generation, name: name, input: input, model: model, startedAt: startedAt)
+    }
+
     func usage(promptTokens: Int?, completionTokens: Int?) {
         processor.onUsage(id: id, promptTokens: promptTokens, completionTokens: completionTokens)
     }
@@ -70,8 +74,8 @@ struct ProcessedSpan: GenerationHandle {
         processor.onEnd(id: id, endedAt: Date(), output: output, error: error.map { String(reflecting: $0) })
     }
 
-    private func child(kind: TraceEvent.Kind, name: String, input: JSONValue?, model: String?) -> ProcessedSpan {
-        let child = ProcessedSpan(traceId: traceId, id: UUID().uuidString, parentId: id, startedAt: Date(), userId: userId, sessionId: sessionId, processor: processor)
+    private func child(kind: TraceEvent.Kind, name: String, input: JSONValue?, model: String?, startedAt: Date = Date()) -> ProcessedSpan {
+        let child = ProcessedSpan(traceId: traceId, id: UUID().uuidString, parentId: id, startedAt: startedAt, userId: userId, sessionId: sessionId, processor: processor)
         processor.onOpen(SpanData(
             id: child.id, traceId: traceId, parentId: child.parentId, kind: kind, name: name,
             startedAt: child.startedAt, input: input, model: model, userId: userId, sessionId: sessionId

swift/Sources/AgentSquad/Core/Tracing/Tracing.swift

@@ -34,6 +34,11 @@ public protocol SpanHandle: Sendable {
     func span(_ name: String, input: JSONValue?) -> any SpanHandle
     /// Open a child generation — an LLM call (records model + token usage).
     func generation(_ name: String, model: String, input: JSONValue?) -> any GenerationHandle
+    /// Open a child generation whose start is backdated to `startedAt` — for a call whose real start
+    /// (e.g. a realtime `response.created`) precedes the moment we can materialize the span. Lets the
+    /// exported span carry the true call latency instead of a ~0 duration. Defaults to ignoring
+    /// `startedAt` (stamping now), so a stateless tracer need not implement it.
+    func generation(_ name: String, model: String, input: JSONValue?, startedAt: Date) -> any GenerationHandle
     /// Set the input once it's known later than open (e.g. a transcript arriving after the turn span).
     func setInput(_ input: JSONValue)
     /// Attach metadata — a `.object` whose top-level keys ride to the backend as span attributes
@@ -47,6 +52,11 @@ public protocol SpanHandle: Sendable {
 extension SpanHandle {
     public func setInput(_ input: JSONValue) {}
     public func setMetadata(_ metadata: JSONValue) {}
+    /// Default: ignore the backdate and stamp the start now — implementers that don't track a
+    /// separate start time keep working unchanged.
+    public func generation(_ name: String, model: String, input: JSONValue?, startedAt: Date) -> any GenerationHandle {
+        generation(name, model: model, input: input)
+    }
 }
 
 /// A span for an LLM call; adds token accounting.

swift/Sources/AgentSquad/Runtimes/Realtime/OpenAIGroundedVoiceAssistant.swift

@@ -47,6 +47,9 @@ public actor OpenAIGroundedVoiceAssistant: OpenAIRealtimeSession, VoiceAssistant
     private var presenterId: String?
     private var presenterResponses: Set<String> = []
     private var presenterActive = false
+    // When the spoken (presenter/direct) response was created on the wire, so its `presenter`
+    // generation span can be backdated to it for a real latency (the API sends no timing).
+    private var presenterStartedAt: Date?
     // Barge-in truncation: which audio item is playing + how much was sent, vs. the runtime's
     // played-ms clock. NOT cleared by `resetTurn` — `interrupt()` reads it after resetting the turn.
     // Only the in-band `direct` reply is truncatable: the presenter is out-of-band
@@ -223,6 +226,7 @@ public actor OpenAIGroundedVoiceAssistant: OpenAIRealtimeSession, VoiceAssistant
             if (role == "presenter" || role == "direct"), !id.isEmpty {
                 presenterResponses.insert(id)
                 presenterId = id
+                presenterStartedAt = Date()   // anchor the presenter generation's latency to now (created)
                 spokenResponseIsInBand = role == "direct"
             }
         case .responseDone(let id, let usage, let status):
@@ -262,7 +266,10 @@ public actor OpenAIGroundedVoiceAssistant: OpenAIRealtimeSession, VoiceAssistant
                 // `tool.*` child spans, but its token usage is dropped this pass — so this count is the
                 // presenter's, not the turn total.
                 if let turn = turnSpan {
-                    let presenter = turn.generation("presenter", model: model, input: transcript(user))
+                    // Backdate the generation to the presenter/direct response's `created` receive-time
+                    // so it carries the real LLM latency, not a ~0-duration span (the API sends no timing).
+                    let presenter = turn.generation("presenter", model: model, input: transcript(user),
+                                                     startedAt: presenterStartedAt ?? Date())
                     presenter.usage(promptTokens: usage?.inputTokens, completionTokens: usage?.outputTokens)
                     if let breakdown = usage?.breakdownMetadata { presenter.setMetadata(breakdown) }
                     presenter.end(output: transcript(reply), error: nil)
@@ -275,6 +282,11 @@ public actor OpenAIGroundedVoiceAssistant: OpenAIRealtimeSession, VoiceAssistant
                 emit(.state(.listening))
                 pendingUserText = ""
                 replyText = ""
+                // Clear synchronously BEFORE the await: `persist` suspends the actor, and a reentrant
+                // next turn can set `presenterStartedAt` from its own response.created during that
+                // suspension — a `defer` after the await would wipe the new turn's timestamp and its
+                // presenter generation would fall back to Date() (~0 latency again).
+                presenterStartedAt = nil
                 await persist(user: user, reply: reply)
             }
             // else: a response we cancelled on barge-in (`presenterId` already cleared). The server still
@@ -334,6 +346,7 @@ public actor OpenAIGroundedVoiceAssistant: OpenAIRealtimeSession, VoiceAssistant
         presenterResponses.remove(id)
         if id == presenterId { presenterId = nil }
         presenterActive = false
+        presenterStartedAt = nil
         callsPerResponse[id] = nil
         truncation.reset()
         endTurn(error: RealtimeSessionError.responseFailed(detail: detail))

swift/Sources/AgentSquad/Runtimes/Realtime/OpenAIVoiceAssistant.swift

@@ -54,6 +54,10 @@ public actor OpenAIVoiceAssistant: OpenAIRealtimeSession, VoiceAssistant {
     private var liveResponses: Set<String> = []
     private var currentResponseId: String?
     private var isSpeaking = false
+    // When each response was created on the wire (client receive-time of `response.created`), so the
+    // answer generation span can be backdated to it — the OpenAI Realtime API sends no timing, and
+    // materializing the span at `response.done` alone would give it ~0 latency.
+    private var responseStartedAt: [String: Date] = [:]
     // Barge-in truncation: which audio item is playing + how much was sent, vs. the runtime's
     // played-ms clock. NOT cleared by `resetTurn` — `interrupt()` reads it after resetting the turn.
     private var truncation = AudioTruncationState()
@@ -226,6 +230,7 @@ public actor OpenAIVoiceAssistant: OpenAIRealtimeSession, VoiceAssistant {
             liveResponses.insert(id)
             currentResponseId = id
             isSpeaking = true
+            responseStartedAt[id] = Date()   // anchor the answer generation's latency to now (created)
         case .responseDone(let id, let usage, let status):
             await responseDone(id, usage: usage, status: status)
         case .error(let code, let message):
@@ -272,7 +277,10 @@ public actor OpenAIVoiceAssistant: OpenAIRealtimeSession, VoiceAssistant {
         // Record the spoken exchange (transcript in/out + usage) as a generation under the turn, then
         // close the turn with the reply — so the trace shows what was said, not an empty span.
         if let turn = turnSpan {
-            let exchange = turn.generation("response", model: model, input: transcript(user))
+            // Backdate the generation to the response's `created` receive-time so it carries the real
+            // LLM latency (the API sends no timing; stamping it now would give a ~0-duration span).
+            let exchange = turn.generation("response", model: model, input: transcript(user),
+                                           startedAt: responseStartedAt[id] ?? Date())
             exchange.usage(promptTokens: usage?.inputTokens, completionTokens: usage?.outputTokens)
             if let breakdown = usage?.breakdownMetadata { exchange.setMetadata(breakdown) }
             exchange.end(output: transcript(reply), error: nil)
@@ -316,6 +324,7 @@ public actor OpenAIVoiceAssistant: OpenAIRealtimeSession, VoiceAssistant {
         userText = ""
         replyText = ""
         callsPerResponse.removeAll()
+        responseStartedAt.removeAll()
         fnNames.removeAll()
         currentTurnIsTextOnly = false   // next turn defaults to the session modality unless `sendText` opts in
         turnReasoningEffort = nil       // reasoning escalation is per turn

swift/Tests/AgentSquadTests/OpenAIGroundedVoiceAssistantTests.swift

@@ -357,6 +357,50 @@ import Testing
         #expect(tracer.recorder.output("voice.turn") == .string("PSG is favourite at 2.5"))
     }
 
+    @Test func presenterGenerationSpanMeasuresRealLatencyFromResponseCreated() async throws {
+        let transport = MockRealtimeTransport()
+        let tracer = RecordingTracer()
+        let log = EventLog()
+        let session = session(transport, tools: oddsTools(), tracer: tracer)
+        log.start(session)
+        try await session.start()
+
+        transport.push(responseCreated("r1"))
+        transport.push(funcArgs("r1", "c1", "odds"))
+        transport.push(responseDone("r1"))                          // tools → continue
+        transport.push(responseDone("r2"))                          // settled → present()
+        await eventually { log.states.contains(.presenting) }       // gatherer drained, pump idle
+        transport.push(responseCreated("p1", role: "presenter"))    // presenter starts (span start anchor)
+        try await Task.sleep(for: .milliseconds(50))                // …presenter "generates"…
+        transport.push(responseDone("p1"))                          // presenter finishes (span end anchor)
+
+        await eventually { tracer.recorder.ended.contains("presenter") }
+        // Backdated to the presenter response.created, so the generation carries the real latency
+        // instead of the ~0s it showed when created-and-ended at response.done.
+        let latency = try #require(tracer.recorder.duration("presenter"))
+        #expect(latency >= 0.02)
+    }
+
+    @Test func directGenerationSpanMeasuresRealLatencyFromResponseCreated() async throws {
+        let transport = MockRealtimeTransport()
+        let tracer = RecordingTracer()
+        let log = EventLog()
+        let session = session(transport, tools: oddsTools(), tracer: tracer)
+        log.start(session)
+        try await session.start()
+
+        transport.push(#"{"type":"response.output_text.delta","response_id":"agent","delta":"hi"}"#)
+        transport.push(responseDone("agent"))                       // no tools, has text → speakDirectly()
+        await eventually { log.states.contains(.speaking) }         // speakDirectly ran, pump idle
+        transport.push(responseCreated("d1", role: "direct"))       // direct reply starts (span start anchor)
+        try await Task.sleep(for: .milliseconds(50))                // …direct reply "generates"…
+        transport.push(responseDone("d1"))                          // direct reply finishes (span end anchor)
+
+        await eventually { tracer.recorder.ended.contains("presenter") }   // the direct answer is the `presenter` generation
+        let latency = try #require(tracer.recorder.duration("presenter"))
+        #expect(latency >= 0.02)
+    }
+
     @Test func attachesAudioTokenBreakdownToThePresenterGeneration() async throws {
         let transport = MockRealtimeTransport()
         let tracer = RecordingTracer()

swift/Tests/AgentSquadTests/OpenAIVoiceAssistantTests.swift

@@ -250,6 +250,26 @@ import Testing
         #expect(tracer.recorder.output("voice.turn") == .string("PSG is favourite at 2.5"))
     }
 
+    @Test func responseGenerationSpanMeasuresRealLatencyFromResponseCreated() async throws {
+        let transport = MockRealtimeTransport()
+        let tracer = RecordingTracer()
+        let log = EventLog()
+        let session = session(transport, tracer: tracer)
+        log.start(session)
+        try await session.start()
+
+        transport.push(responseCreated("r1"))                 // the answer starts here (span start anchor)
+        await eventually { log.states.contains(.speaking) }   // …created processed, startedAt stamped…
+        try await Task.sleep(for: .milliseconds(50))          // …the model "generates" for a bit…
+        transport.push(responseDone("r1"))                    // …and finishes here (span end anchor)
+
+        await eventually { tracer.recorder.ended.contains("response") }
+        // The `response` generation is backdated to response.created, so its duration reflects the real
+        // LLM latency (previously it was created-and-ended at response.done → ~0s, the LangSmith bug).
+        let latency = try #require(tracer.recorder.duration("response"))
+        #expect(latency >= 0.02)
+    }
+
     @Test func traceTranscriptsOffOmitsSpokenTextButKeepsStructureAndUsage() async throws {
         let transport = MockRealtimeTransport()
         let tracer = RecordingTracer()

swift/Tests/AgentSquadTests/ProcessingTracerTests.swift

@@ -107,6 +107,25 @@ import Testing
         #expect(genEvent.completionTokens == 5)
     }
 
+    @Test func generationBackdatesStartedAtToTheGivenTime() async throws {
+        let exporter = RecordingExporter()
+        let tracer = ProcessingTracer(exporter: exporter, batchSize: 100)
+
+        // A realtime answer whose call started well before we could materialize the span: backdating
+        // `startedAt` makes the exported span carry the real latency instead of a ~0 duration.
+        let start = Date(timeIntervalSince1970: 1_000)
+        let root = tracer.startTrace(name: "turn", userId: nil, sessionId: nil, metadata: nil)
+        let gen = root.generation("response", model: "gpt", input: nil, startedAt: start)
+        gen.end(output: nil, error: nil)
+        root.end(output: nil, error: nil)
+        try await tracer.flush()
+
+        let genEvent = try #require(await exporter.events.first { $0.kind == .generation })
+        #expect(genEvent.startedAt == start)                        // the backdate survives finalize
+        let ended = try #require(genEvent.endedAt)
+        #expect(ended.timeIntervalSince(start) > 0)                 // and yields a non-zero latency
+    }
+
     @Test func setInputAfterOpenIsAppliedToTheExportedSpan() async throws {
         let exporter = RecordingExporter()
         let tracer = ProcessingTracer(exporter: exporter, batchSize: 100)

swift/Tests/AgentSquadTests/RealtimeTestSupport.swift

@@ -75,12 +75,15 @@ final class RecordingTracer: Tracer, @unchecked Sendable {
         private var _usage: [String: (Int?, Int?)] = [:]
         private var _metadata: [String: JSONValue] = [:]
         private var _errors: [String: String] = [:]
-        func open(_ n: String, input: JSONValue? = nil) { lock.withLock { _opened.append(n); if let input { _input[n] = input } } }
+        private var _startedAt: [String: Date] = [:]
+        private var _endedAt: [String: Date] = [:]
+        func open(_ n: String, input: JSONValue? = nil, startedAt: Date = Date()) { lock.withLock { _opened.append(n); _startedAt[n] = startedAt; if let input { _input[n] = input } } }
         func setInput(_ n: String, _ input: JSONValue) { lock.withLock { _input[n] = input } }
         func setMetadata(_ n: String, _ metadata: JSONValue) { lock.withLock { _metadata[n] = metadata } }
         func close(_ n: String, output: JSONValue?, error: (any Error)? = nil) {
             lock.withLock {
                 _ended.append(n)
+                _endedAt[n] = Date()
                 if let output { _output[n] = output }
                 if let error { _errors[n] = String(reflecting: error) }   // same projection the processors use
             }
@@ -93,13 +96,17 @@ final class RecordingTracer: Tracer, @unchecked Sendable {
         func usage(_ n: String) -> (Int?, Int?)? { lock.withLock { _usage[n] } }
         func metadata(_ n: String) -> JSONValue? { lock.withLock { _metadata[n] } }
         func error(_ n: String) -> String? { lock.withLock { _errors[n] } }
+        /// The span's recorded latency (end − start). `startedAt` is the backdated value when the span
+        /// was opened via `generation(…startedAt:)`, so this asserts the real duration, not ~0.
+        func duration(_ n: String) -> TimeInterval? { lock.withLock { guard let s = _startedAt[n], let e = _endedAt[n] else { return nil }; return e.timeIntervalSince(s) } }
     }
     final class Span: GenerationHandle, @unchecked Sendable {
         let id: String
         let recorder: Recorder
         init(id: String, recorder: Recorder) { self.id = id; self.recorder = recorder }
         func span(_ name: String, input: JSONValue?) -> any SpanHandle { recorder.open(name, input: input); return Span(id: name, recorder: recorder) }
         func generation(_ name: String, model: String, input: JSONValue?) -> any GenerationHandle { recorder.open(name, input: input); return Span(id: name, recorder: recorder) }
+        func generation(_ name: String, model: String, input: JSONValue?, startedAt: Date) -> any GenerationHandle { recorder.open(name, input: input, startedAt: startedAt); return Span(id: name, recorder: recorder) }
         func setInput(_ input: JSONValue) { recorder.setInput(id, input) }
         func setMetadata(_ metadata: JSONValue) { recorder.setMetadata(id, metadata) }
         func end(output: JSONValue?, error: (any Error)?) { recorder.close(id, output: output, error: error) }