diff --git a/Packages/Shared/CMUXMobileCore/Sources/CMUXMobileCore/DiagnosticTerminalTrace.swift b/Packages/Shared/CMUXMobileCore/Sources/CMUXMobileCore/DiagnosticTerminalTrace.swift index 3bb85bfc2063..d00465a60ef1 100644 --- a/Packages/Shared/CMUXMobileCore/Sources/CMUXMobileCore/DiagnosticTerminalTrace.swift +++ b/Packages/Shared/CMUXMobileCore/Sources/CMUXMobileCore/DiagnosticTerminalTrace.swift @@ -18,6 +18,13 @@ public enum DiagnosticTerminalTracePhase: Int, Sendable, Codable, CaseIterable { case applied = 7 case failed = 8 case discarded = 9 + /// The operation is still in flight past a stall threshold. + /// + /// Unlike every other phase this is not terminal: it is emitted by a + /// probe while the request is outstanding, so an operation that never + /// settles still produces evidence. A settled operation emits its real + /// terminal phase afterwards. + case stalled = 10 } /// A short opaque ID that can safely cross the mobile RPC boundary. diff --git a/Packages/Shared/CMUXMobileCore/Sources/CMUXMobileCore/MobileTerminalReplayTrace.swift b/Packages/Shared/CMUXMobileCore/Sources/CMUXMobileCore/MobileTerminalReplayTrace.swift new file mode 100644 index 000000000000..0df7112bf62b --- /dev/null +++ b/Packages/Shared/CMUXMobileCore/Sources/CMUXMobileCore/MobileTerminalReplayTrace.swift @@ -0,0 +1,102 @@ +import Foundation + +/// Why a terminal replay was requested. +/// +/// A replay is the only path that repaints a surface the phone has just +/// rebuilt blank, so the trigger is the difference between "the user is +/// looking at a blank terminal" and "the user is looking at slightly stale +/// text". Values are stable on the wire: they are packed into the terminal +/// trace's payload slot and read back in the analytics pipeline. +/// Raw values are never reused: a removed case leaves its number retired so a +/// newer producer cannot be misread as an older codepath. +public enum MobileTerminalReplayTrigger: Int, Sendable, Codable, CaseIterable { + /// No reason was recorded. Nothing produces this today; it is the + /// well-defined zero so an empty payload slot decodes without inventing a + /// codepath. + case unknown = 0 + /// The output stream reset; the surface was rebuilt blank. + case outputReset = 1 + /// The render pipeline reset; the surface was rebuilt blank. + case renderPipelineReset = 2 + /// A viewport transition armed a barrier and re-requested state. + case viewportTransition = 3 + /// A render-grid delta did not chain onto the delivered revision. + case revisionChainBreak = 4 + /// A render-grid delta did not chain onto the delivered history rows. + case historyChainBreak = 5 + /// First attach to a surface with no delivered baseline. + case coldAttach = 6 + /// A previous replay attempt failed or came back unusable. + case failureRetry = 7 + /// The phone dropped a delivered frame before it reached the grid. + case droppedFrame = 8 + /// The grid apply contract rejected a frame at paint time. + case applyFenceFailure = 9 + /// Pending input never echoed, so the mirror is presumed diverged. + case pendingInputDrop = 10 + /// The event subscription was re-established. + case resubscribe = 11 + /// The Mac left the alternate screen, so the primary baseline is unknown. + case screenTransition = 14 + /// A render-grid delta arrived with no delivered baseline to patch. + case missingBaseline = 15 + /// A gap in the byte stream needs an authoritative screen to verify it. + case byteGap = 16 +} + +/// Categorical context recorded alongside one replay trace. +/// +/// The terminal trace event carries a single integer payload slot, so this +/// packs the fields that decide whether a slow replay is user-visible. The +/// encoding is stable on the wire and round-trips through ``encoded``. +public struct MobileTerminalReplayTraceContext: Equatable, Sendable { + /// Highest retry attempt the encoding can represent. + public static let maxAttempt = 15 + + /// Why this replay was requested. + public let trigger: MobileTerminalReplayTrigger + /// Whether the surface had been rebuilt blank when the replay was + /// requested. A slow replay on a blank surface is the blank-screen stall; + /// a slow replay on a painted surface only holds back fresh output. + public let surfaceIsBlank: Bool + /// Whether a replay barrier is suppressing live output for this surface. + public let barrierActive: Bool + /// Zero-based retry index within the current replay episode. + public let attempt: Int + + public init( + trigger: MobileTerminalReplayTrigger, + surfaceIsBlank: Bool, + barrierActive: Bool, + attempt: Int + ) { + self.trigger = trigger + self.surfaceIsBlank = surfaceIsBlank + self.barrierActive = barrierActive + self.attempt = min(max(0, attempt), Self.maxAttempt) + } + + /// Packs the context into one non-negative integer payload slot. + public var encoded: Int { + var value = trigger.rawValue & 0xFF + if surfaceIsBlank { value |= 1 << 8 } + if barrierActive { value |= 1 << 9 } + value |= (attempt & 0xF) << 10 + return value + } + + /// Unpacks a context previously produced by ``encoded``. + /// + /// Returns `nil` for a negative value or an unknown trigger so a future + /// producer cannot be silently misread as `unknown` by an older consumer. + public init?(encoded: Int) { + guard encoded >= 0, + let trigger = MobileTerminalReplayTrigger(rawValue: encoded & 0xFF) else { + return nil + } + self.trigger = trigger + self.surfaceIsBlank = (encoded & (1 << 8)) != 0 + self.barrierActive = (encoded & (1 << 9)) != 0 + self.attempt = (encoded >> 10) & 0xF + } +} diff --git a/Packages/Shared/CMUXMobileCore/Tests/CMUXMobileCoreTests/MobileTerminalReplayTraceContextTests.swift b/Packages/Shared/CMUXMobileCore/Tests/CMUXMobileCoreTests/MobileTerminalReplayTraceContextTests.swift new file mode 100644 index 000000000000..11b63402089a --- /dev/null +++ b/Packages/Shared/CMUXMobileCore/Tests/CMUXMobileCoreTests/MobileTerminalReplayTraceContextTests.swift @@ -0,0 +1,65 @@ +import Testing + +@testable import CMUXMobileCore + +@Suite("Replay trace context encoding") +struct MobileTerminalReplayTraceContextTests { + @Test func everyTriggerRoundTripsWithBothFlags() { + for trigger in MobileTerminalReplayTrigger.allCases { + for blank in [true, false] { + for barrier in [true, false] { + let context = MobileTerminalReplayTraceContext( + trigger: trigger, + surfaceIsBlank: blank, + barrierActive: barrier, + attempt: 3 + ) + #expect(MobileTerminalReplayTraceContext(encoded: context.encoded) == context) + } + } + } + } + + @Test func attemptClampsToTheEncodableRange() { + let context = MobileTerminalReplayTraceContext( + trigger: .failureRetry, + surfaceIsBlank: true, + barrierActive: true, + attempt: 99 + ) + #expect(context.attempt == MobileTerminalReplayTraceContext.maxAttempt) + #expect(MobileTerminalReplayTraceContext(encoded: context.encoded) == context) + } + + @Test func negativeAttemptClampsToZero() { + let context = MobileTerminalReplayTraceContext( + trigger: .coldAttach, + surfaceIsBlank: false, + barrierActive: false, + attempt: -4 + ) + #expect(context.attempt == 0) + #expect(context.encoded == MobileTerminalReplayTrigger.coldAttach.rawValue) + } + + /// An older consumer must not read a future trigger as `unknown`: that + /// would silently attribute a new codepath's stalls to the wrong bucket. + @Test func unknownTriggerDecodesToNilRatherThanUnknown() { + let futureTrigger = 0xFE + #expect(MobileTerminalReplayTraceContext(encoded: futureTrigger) == nil) + #expect(MobileTerminalReplayTraceContext(encoded: -1) == nil) + } + + @Test func flagsAreIndependentOfTheTriggerBits() { + let blankOnly = MobileTerminalReplayTraceContext( + trigger: .outputReset, surfaceIsBlank: true, barrierActive: false, attempt: 0 + ) + let barrierOnly = MobileTerminalReplayTraceContext( + trigger: .outputReset, surfaceIsBlank: false, barrierActive: true, attempt: 0 + ) + #expect(blankOnly.encoded != barrierOnly.encoded) + #expect(MobileTerminalReplayTraceContext(encoded: blankOnly.encoded)?.surfaceIsBlank == true) + #expect(MobileTerminalReplayTraceContext(encoded: barrierOnly.encoded)?.surfaceIsBlank == false) + #expect(MobileTerminalReplayTraceContext(encoded: barrierOnly.encoded)?.barrierActive == true) + } +} diff --git a/Packages/iOS/CmuxMobileAnalytics/Sources/CmuxMobileAnalytics/MobileTerminalTraceReporter.swift b/Packages/iOS/CmuxMobileAnalytics/Sources/CmuxMobileAnalytics/MobileTerminalTraceReporter.swift index c57e7e65625b..b93675c51d88 100644 --- a/Packages/iOS/CmuxMobileAnalytics/Sources/CmuxMobileAnalytics/MobileTerminalTraceReporter.swift +++ b/Packages/iOS/CmuxMobileAnalytics/Sources/CmuxMobileAnalytics/MobileTerminalTraceReporter.swift @@ -17,12 +17,31 @@ public final class MobileTerminalTraceReporter: Sendable { private struct Start: Sendable { let operation: DiagnosticTerminalTraceOperation let tNanos: UInt64 + let replayContext: MobileTerminalReplayTraceContext? + /// Background-transition count when this operation began. + let backgroundEpoch: UInt64 } private struct State: Sendable { var starts: [UInt64: Start] = [:] var windowStart: UInt64 = 0 var emittedInWindow = 0 + /// Counts transitions out of the foreground. + /// + /// Comparing this against the value recorded at `started` answers the + /// question the flag below cannot: an operation that began on screen, + /// spent an hour suspended and settled after reactivation is in the + /// foreground when it reports, but its elapsed time is not screen + /// time. Only an unchanged count means the whole trace was on screen. + var backgroundEpoch: UInt64 = 0 + /// Whether the app was in the foreground when the phase was recorded. + /// + /// A suspended app runs no code, so an operation that spans + /// suspension accrues wall-clock time it never spent waiting on + /// screen. Without this flag a stall of a few foreground seconds and + /// one that sat in a pocket for an hour are indistinguishable in + /// Axiom, and any percentile over the mix is meaningless. + var isForeground = true } private final class StateStore: @unchecked Sendable { @@ -46,6 +65,13 @@ public final class MobileTerminalTraceReporter: Sendable { } } + func setForeground(_ active: Bool) { + queue.async { [self] in + if !active, state.isForeground { state.backgroundEpoch &+= 1 } + state.isForeground = active + } + } + func drain() async { await withCheckedContinuation { continuation in queue.async { continuation.resume() } @@ -59,6 +85,8 @@ public final class MobileTerminalTraceReporter: Sendable { let terminalPhase: DiagnosticTerminalTracePhase let durationMilliseconds: UInt32 let outcome: String + let replayContext: MobileTerminalReplayTraceContext? + let isForeground: Bool } private let emitter: any AnalyticsEmitting @@ -79,6 +107,12 @@ public final class MobileTerminalTraceReporter: Sendable { } } + /// Records the app lifecycle edge so each emitted row says whether its + /// elapsed time was spent on screen. + public func setForeground(_ active: Bool) { + state.setForeground(active) + } + public func flush() async { await state.drain() await emitter.flush() @@ -103,9 +137,33 @@ public final class MobileTerminalTraceReporter: Sendable { let oldest = state.starts.min(by: { $0.value.tNanos < $1.value.tNanos })?.key { state.starts.removeValue(forKey: oldest) } - state.starts[traceID.rawValue] = Start(operation: operation, tNanos: event.tNanos) + state.starts[traceID.rawValue] = Start( + operation: operation, + tNanos: event.tNanos, + replayContext: event.c.flatMap(MobileTerminalReplayTraceContext.init(encoded:)), + backgroundEpoch: state.backgroundEpoch + ) return nil } + // A stall report is the only non-terminal emission: the operation is + // still outstanding, so the pending start must survive for the phase + // that eventually settles it. Without this an operation that never + // settles produced no row at all. + if phase == .stalled { + guard let duration = event.ms else { return nil } + guard admitEmission(at: event.tNanos, state: &state) else { return nil } + let start = state.starts[traceID.rawValue] + return Observation( + traceID: traceID, + operation: start?.operation ?? operation, + terminalPhase: phase, + durationMilliseconds: duration, + outcome: "stalled", + replayContext: event.c.flatMap(MobileTerminalReplayTraceContext.init(encoded:)) + ?? start?.replayContext, + isForeground: stayedForeground(start, state: state) + ) + } guard phase == .applied || phase == .failed || phase == .discarded else { return nil } let start = state.starts.removeValue(forKey: traceID.rawValue) // Prefer the monotonic diagnostic timestamps whenever the start phase @@ -124,10 +182,22 @@ public final class MobileTerminalTraceReporter: Sendable { operation: start?.operation ?? operation, terminalPhase: phase, durationMilliseconds: duration, - outcome: outcome + outcome: outcome, + replayContext: start?.replayContext, + isForeground: stayedForeground(start, state: state) ) } + /// Whether the whole operation stayed on screen. + /// + /// Conservative when the start was dropped under admission pressure: an + /// operation whose beginning is unknown cannot claim its elapsed time was + /// screen time. + private static func stayedForeground(_ start: Start?, state: State) -> Bool { + guard let start else { return false } + return state.isForeground && start.backgroundEpoch == state.backgroundEpoch + } + private static func admitEmission(at now: UInt64, state: inout State) -> Bool { if state.windowStart == 0 || now < state.windowStart || now - state.windowStart >= 60 * 1_000_000_000 { @@ -140,7 +210,7 @@ public final class MobileTerminalTraceReporter: Sendable { } private static func properties(for observation: Observation) -> [String: AnalyticsValue] { - [ + var properties: [String: AnalyticsValue] = [ "phase": .string(tracePhase), "outcome": .string(observation.outcome), "duration_ms": .int(Int(observation.durationMilliseconds)), @@ -148,6 +218,15 @@ public final class MobileTerminalTraceReporter: Sendable { "trace_id": .string(observation.traceID.stringValue), "operation": .string(String(describing: observation.operation)), "terminal_phase": .string(String(describing: observation.terminalPhase)), + "app_foreground": .bool(observation.isForeground), ] + if let context = observation.replayContext { + properties["replay_trigger"] = .string(String(describing: context.trigger)) + // The field that separates a blank terminal from a stale one. + properties["surface_blank"] = .bool(context.surfaceIsBlank) + properties["barrier_active"] = .bool(context.barrierActive) + properties["replay_attempt"] = .int(context.attempt) + } + return properties } } diff --git a/Packages/iOS/CmuxMobileAnalytics/Tests/CmuxMobileAnalyticsTests/MobileTerminalTraceStallTests.swift b/Packages/iOS/CmuxMobileAnalytics/Tests/CmuxMobileAnalyticsTests/MobileTerminalTraceStallTests.swift new file mode 100644 index 000000000000..0a0489d09462 --- /dev/null +++ b/Packages/iOS/CmuxMobileAnalytics/Tests/CmuxMobileAnalyticsTests/MobileTerminalTraceStallTests.swift @@ -0,0 +1,158 @@ +import CMUXMobileCore +import Testing + +@testable import CmuxMobileAnalytics + +private struct StallTestConsent: AnalyticsConsentProviding { + let isTelemetryEnabled: Bool +} + +/// A replay that never settles is the blank-terminal stall. These cover the +/// emission path that makes it visible at all. +@Suite("Terminal replay stall reporting") +struct MobileTerminalTraceStallTests { + private func makeReporter() -> (MobileTerminalTraceReporter, RecordingAnalyticsUploader) { + let uploader = RecordingAnalyticsUploader() + let emitter = AnalyticsEmitter( + uploader: uploader, + consent: StallTestConsent(isTelemetryEnabled: true), + anonymousID: "local-install" + ) + return (MobileTerminalTraceReporter(emitter: emitter), uploader) + } + + private func event( + _ phase: DiagnosticTerminalTracePhase, + at tNanos: UInt64, + trace: DiagnosticTerminalTraceID, + ms: UInt32? = nil, + c: Int? = nil + ) -> DiagnosticEvent { + DiagnosticEvent( + code: .terminalTrace, + tNanos: tNanos, + ms: ms, + a: DiagnosticTerminalTraceOperation.replay.rawValue, + b: phase.rawValue, + c: c, + traceID: trace.rawValue + ) + } + + @Test func aReplayThatNeverSettlesStillReportsToAxiom() async { + let (reporter, uploader) = makeReporter() + let trace = DiagnosticTerminalTraceID(rawValue: 0xB1A4)! + let context = MobileTerminalReplayTraceContext( + trigger: .outputReset, surfaceIsBlank: true, barrierActive: true, attempt: 0 + ) + reporter.ingest(event(.started, at: 1_000_000_000, trace: trace, c: context.encoded)) + reporter.ingest(event(.stalled, at: 3_000_000_000, trace: trace, ms: 2_000, c: context.encoded)) + reporter.ingest(event(.stalled, at: 31_000_000_000, trace: trace, ms: 30_000, c: context.encoded)) + await reporter.flush() + + let values = await uploader.uploadedEvents + #expect(values.count == 2) + #expect(values.allSatisfy { $0.properties["outcome"] == .string("stalled") }) + #expect(values.allSatisfy { $0.properties["terminal_phase"] == .string("stalled") }) + #expect(values.first?.properties["duration_ms"] == .int(2_000)) + #expect(values.last?.properties["duration_ms"] == .int(30_000)) + // The fields that separate a blank terminal from merely stale text. + #expect(values.first?.properties["surface_blank"] == .bool(true)) + #expect(values.first?.properties["barrier_active"] == .bool(true)) + #expect(values.first?.properties["replay_trigger"] == .string("outputReset")) + #expect(values.first?.properties["replay_attempt"] == .int(0)) + } + + /// A stall report must not consume the pending start: the settled phase + /// still has to report, and its duration must still span from `started`. + @Test func stallReportDoesNotSwallowTheSettledPhase() async { + let (reporter, uploader) = makeReporter() + let trace = DiagnosticTerminalTraceID(rawValue: 0xB1A5)! + let context = MobileTerminalReplayTraceContext( + trigger: .coldAttach, surfaceIsBlank: true, barrierActive: false, attempt: 2 + ) + reporter.ingest(event(.started, at: 1_000_000_000, trace: trace, c: context.encoded)) + reporter.ingest(event(.stalled, at: 3_000_000_000, trace: trace, ms: 2_000, c: context.encoded)) + reporter.ingest(event(.failed, at: 31_000_000_000, trace: trace)) + await reporter.flush() + + let values = await uploader.uploadedEvents + #expect(values.count == 2) + #expect(values.last?.properties["outcome"] == .string("failure")) + #expect(values.last?.properties["duration_ms"] == .int(30_000)) + // The context recorded at `started` survives onto the settled row. + #expect(values.last?.properties["replay_trigger"] == .string("coldAttach")) + #expect(values.last?.properties["surface_blank"] == .bool(true)) + #expect(values.last?.properties["replay_attempt"] == .int(2)) + } + + /// A fast successful replay stays below the slow threshold and must not + /// gain a row just because the context fields now exist. + @Test func fastSuccessfulReplayStillEmitsNothing() async { + let (reporter, uploader) = makeReporter() + let trace = DiagnosticTerminalTraceID(rawValue: 0xB1A6)! + let context = MobileTerminalReplayTraceContext( + trigger: .viewportTransition, surfaceIsBlank: false, barrierActive: true, attempt: 0 + ) + reporter.ingest(event(.started, at: 1_000_000_000, trace: trace, c: context.encoded)) + reporter.ingest(event(.applied, at: 1_300_000_000, trace: trace)) + await reporter.flush() + + #expect((await uploader.uploadedEvents).isEmpty) + } + + /// A stall that accrued its time while the app was suspended is not a + /// blank screen anyone saw. Mixing the two makes every percentile in + /// Axiom meaningless, so each row has to say which it was. + @Test func stallRowsRecordWhetherTheAppWasOnScreen() async { + let (reporter, uploader) = makeReporter() + let context = MobileTerminalReplayTraceContext( + trigger: .outputReset, surfaceIsBlank: true, barrierActive: true, attempt: 0 + ) + let onScreen = DiagnosticTerminalTraceID(rawValue: 0xB1B0)! + reporter.ingest(event(.started, at: 1_000_000_000, trace: onScreen, c: context.encoded)) + reporter.ingest(event(.stalled, at: 6_000_000_000, trace: onScreen, ms: 5_000, c: context.encoded)) + await reporter.flush() + #expect((await uploader.uploadedEvents).last?.properties["app_foreground"] == .bool(true)) + + reporter.setForeground(false) + let suspended = DiagnosticTerminalTraceID(rawValue: 0xB1B1)! + reporter.ingest(event(.started, at: 7_000_000_000, trace: suspended, c: context.encoded)) + reporter.ingest(event(.stalled, at: 67_000_000_000, trace: suspended, ms: 60_000, c: context.encoded)) + await reporter.flush() + let values = await uploader.uploadedEvents + #expect(values.count == 2) + #expect(values.last?.properties["app_foreground"] == .bool(false)) + #expect(values.last?.properties["duration_ms"] == .int(60_000)) + } + + /// The case that makes the flag trustworthy: a replay that begins on + /// screen, spans suspension, and settles after reactivation is in the + /// foreground when it reports, but its elapsed time is not screen time. + @Test func aTraceThatSpannedSuspensionIsNotReportedAsOnScreen() async { + let (reporter, uploader) = makeReporter() + let trace = DiagnosticTerminalTraceID(rawValue: 0xB1B2)! + let context = MobileTerminalReplayTraceContext( + trigger: .outputReset, surfaceIsBlank: true, barrierActive: true, attempt: 0 + ) + reporter.ingest(event(.started, at: 1_000_000_000, trace: trace, c: context.encoded)) + reporter.setForeground(false) + reporter.setForeground(true) + reporter.ingest(event(.failed, at: 160_000_000_000, trace: trace)) + await reporter.flush() + + let values = await uploader.uploadedEvents + #expect(values.count == 1) + #expect(values.last?.properties["app_foreground"] == .bool(false)) + } + + @Test func stallWithoutAnElapsedMagnitudeIsDropped() async { + let (reporter, uploader) = makeReporter() + let trace = DiagnosticTerminalTraceID(rawValue: 0xB1A7)! + reporter.ingest(event(.started, at: 1_000_000_000, trace: trace)) + reporter.ingest(event(.stalled, at: 3_000_000_000, trace: trace)) + await reporter.flush() + + #expect((await uploader.uploadedEvents).isEmpty) + } +} diff --git a/Packages/iOS/CmuxMobileRPC/Sources/CmuxMobileRPC/MobileCoreRPCSession.swift b/Packages/iOS/CmuxMobileRPC/Sources/CmuxMobileRPC/MobileCoreRPCSession.swift index 87dafa941568..1e2622c2f090 100644 --- a/Packages/iOS/CmuxMobileRPC/Sources/CmuxMobileRPC/MobileCoreRPCSession.swift +++ b/Packages/iOS/CmuxMobileRPC/Sources/CmuxMobileRPC/MobileCoreRPCSession.swift @@ -92,6 +92,33 @@ actor MobileCoreRPCSession { private var connectionTask: ConnectingTask? private var recordedConnectCancellationAttemptIDs: Set = [] private var installedConnectionID: UUID? + /// Counts inbound deliveries on the installed transport. + /// + /// A QUIC path can stop carrying traffic without closing: `receive()` + /// never returns and never throws, so `readLoop` cannot tear the + /// connection down and every request rides it until its own deadline. + /// Comparing this counter across a request's lifetime answers the one + /// question that separates "this request is slow" from "this transport is + /// dead": did anything at all arrive while it was outstanding. + private var inboundDeliveryCount: UInt64 = 0 + /// Consecutive response timeouts that saw no inbound delivery at all. + /// + /// One unanswered request is genuinely ambiguous: a host can be slow or + /// silent on a single method while its connection is perfectly healthy, + /// and `responseTimeoutDoesNotCloseMultiplexedSession` pins that. Two in a + /// row without a single byte arriving in between is not ambiguous. Any + /// inbound delivery resets this, so the streak only survives a lane that + /// has gone completely quiet. + private var silentTimeoutStreak = 0 + /// Increments once per counted silent timeout. + /// + /// Requests armed before the previous silent timeout belong to the same + /// silence window. Six replays fired together and answered by one quiet + /// period is one piece of evidence, not six, so only a request armed + /// after the last counted timeout may advance the streak. + private var silentTimeoutEpoch: UInt64 = 0 + /// Silent timeouts required before the installed transport is condemned. + static let minimumSilentTimeoutsBeforeCondemning = 2 private var readerTask: Task? /// Watches the complete native connection, separately from the control /// lane reader. IROH can close the shared QUIC session without making a @@ -380,6 +407,10 @@ actor MobileCoreRPCSession { return } isTearingDown = true + // Evidence is per connection. A replacement transport must not + // inherit a streak accumulated against the one it replaces, or its + // first silent timeout condemns it on a single piece of evidence. + silentTimeoutStreak = 0 defer { isTearingDown = false let waiters = tearDownWaiters @@ -1038,6 +1069,9 @@ actor MobileCoreRPCSession { } // Enforce size per decoded frame. A chunk can finish one valid // maximum-size frame and also contain bytes from the next frame. + inboundDeliveryCount &+= 1 + // The lane just proved it still carries bytes. + silentTimeoutStreak = 0 buffer.append(chunk) do { while !Task.isCancelled, installedConnectionID == connectionID { @@ -1085,7 +1119,12 @@ actor MobileCoreRPCSession { pipelinedContinuation?.resume(returning: .cancelled) } - private func timeoutPendingRequest(requestID: String) async { + private func timeoutPendingRequest( + requestID: String, + armedConnectionID: UUID? = nil, + armedInboundCount: UInt64 = 0, + armedSilentEpoch: UInt64 = 0 + ) async { let legacyContinuation = pending.removeValue(forKey: requestID) let pipelinedSettlement = pipelinedPending.removeValue( forKey: requestID @@ -1094,6 +1133,11 @@ actor MobileCoreRPCSession { return } requestTimeoutTasks.removeValue(forKey: requestID)?.cancel() + // A request still sitting in the write queue never reached the wire, + // so its expiry says nothing about whether the transport can deliver. + // It means the queue is backed up, which the head-of-line handling + // below already owns. + let reachedTheWire = queuedWriteIDs[requestID] == nil var condemnedWriteRequestID = requestID if let queuedWriteID = queuedWriteIDs.removeValue(forKey: requestID) { cancelledQueuedWriteIDs.insert(queuedWriteID) @@ -1107,13 +1151,38 @@ actor MobileCoreRPCSession { condemnedWriteRequestID = write.requestID } } - let error: MobileShellConnectionError = if await recycleTransportIfActiveWrite( + var error: MobileShellConnectionError = if await recycleTransportIfActiveWrite( requestID: condemnedWriteRequestID ) { .transportWriteTimedOut } else { .requestTimedOut } + // `recycleTransportIfActiveWrite` only condemns a transport whose + // *write* is stuck and that already reports itself closed. A path that + // black-holes after the write succeeded satisfies neither, so without + // this the dead transport stays installed and `ensureConnected` hands + // it to the retry, which burns another full deadline. Two of those is + // a minute of blank terminal. + if case .requestTimedOut = error, reachedTheWire { + if transportDeliveredNothing( + armedConnectionID: armedConnectionID, + armedInboundCount: armedInboundCount + ) { + // Requests armed before the last counted timeout share its + // silence window; they are already represented by it. + if armedSilentEpoch == silentTimeoutEpoch { + silentTimeoutEpoch &+= 1 + silentTimeoutStreak += 1 + if silentTimeoutStreak >= Self.minimumSilentTimeoutsBeforeCondemning { + error = .connectionClosed + await tearDown(error: .connectionClosed) + } + } + } else { + silentTimeoutStreak = 0 + } + } let settlement = PendingRequestSettlement.response(.failure(error)) legacyContinuation?.resume(returning: settlement) switch pipelinedSettlement { @@ -1150,6 +1219,9 @@ actor MobileCoreRPCSession { timeoutNanoseconds: UInt64 ) { requestTimeoutTasks[requestID]?.cancel() + let armedConnectionID = installedConnectionID + let armedInboundCount = inboundDeliveryCount + let armedSilentEpoch = silentTimeoutEpoch requestTimeoutTasks[requestID] = Task { [weak self, taskTimeout] in do { try await taskTimeout.sleep(nanoseconds: timeoutNanoseconds) @@ -1157,10 +1229,32 @@ actor MobileCoreRPCSession { return } guard let self else { return } - await self.timeoutPendingRequest(requestID: requestID) + await self.timeoutPendingRequest( + requestID: requestID, + armedConnectionID: armedConnectionID, + armedInboundCount: armedInboundCount, + armedSilentEpoch: armedSilentEpoch + ) } } + /// Whether a timed-out request proves its transport can no longer deliver. + /// + /// Only a transport that delivered *nothing* for the whole life of the + /// request is condemned. If anything arrived (another response, an event + /// frame, a terminal delta) the lane is demonstrably alive and this one + /// request was merely slow, so the request fails alone. Requires the same + /// installed connection throughout: a timeout belonging to a connection + /// that has already been replaced says nothing about the current one. + private func transportDeliveredNothing( + armedConnectionID: UUID?, + armedInboundCount: UInt64 + ) -> Bool { + guard let armedConnectionID, + installedConnectionID == armedConnectionID else { return false } + return inboundDeliveryCount == armedInboundCount + } + func settlePendingRequest( requestID: String, settlement: PendingRequestSettlement diff --git a/Packages/iOS/CmuxMobileRPC/Sources/CmuxMobileRPC/MobileTerminalReplayResponse.swift b/Packages/iOS/CmuxMobileRPC/Sources/CmuxMobileRPC/MobileTerminalReplayResponse.swift index 43422e2ff1de..2414d10e2d6b 100644 --- a/Packages/iOS/CmuxMobileRPC/Sources/CmuxMobileRPC/MobileTerminalReplayResponse.swift +++ b/Packages/iOS/CmuxMobileRPC/Sources/CmuxMobileRPC/MobileTerminalReplayResponse.swift @@ -21,6 +21,13 @@ public struct MobileTerminalReplayResponse: Decodable, Sendable { public let columns: Int? /// The host grid row count (debug diagnostics only). public let rows: Int? + /// Milliseconds the host spent between receiving this replay request and + /// finishing the capture it answers with. + /// + /// Subtracting this from the phone's own request round trip separates a + /// slow host capture from a slow or stalled transport. Absent on hosts + /// that predate the field. + public let hostElapsedMilliseconds: UInt32? private enum CodingKeys: String, CodingKey { case dataBase64 = "data_b64" @@ -29,6 +36,7 @@ public struct MobileTerminalReplayResponse: Decodable, Sendable { case sequence = "seq" case columns case rows + case hostElapsedMilliseconds = "host_elapsed_ms" } public init(from decoder: any Decoder) throws { @@ -41,6 +49,10 @@ public struct MobileTerminalReplayResponse: Decodable, Sendable { sequence = try container.decodeIfPresent(UInt64.self, forKey: .sequence) columns = try container.decodeIfPresent(Int.self, forKey: .columns) rows = try container.decodeIfPresent(Int.self, forKey: .rows) + hostElapsedMilliseconds = try? container.decodeIfPresent( + UInt32.self, + forKey: .hostElapsedMilliseconds + ) } /// Decode a replay response from raw JSON data. diff --git a/Packages/iOS/CmuxMobileRPC/Tests/CmuxMobileRPCTests/MobileCoreRPCSilentTransportTests.swift b/Packages/iOS/CmuxMobileRPC/Tests/CmuxMobileRPCTests/MobileCoreRPCSilentTransportTests.swift new file mode 100644 index 000000000000..57d569ae0ff1 --- /dev/null +++ b/Packages/iOS/CmuxMobileRPC/Tests/CmuxMobileRPCTests/MobileCoreRPCSilentTransportTests.swift @@ -0,0 +1,112 @@ +import CMUXMobileCore +import Foundation +import Testing +@testable import CmuxMobileRPC + +/// A QUIC path can stop carrying traffic without closing: `receive()` never +/// returns and never throws, so the read loop cannot tear the connection down. +/// Every request then rides that corpse until its own deadline, and because +/// the deadline failed only the request, the retry rode it again. Two of those +/// is a minute of blank terminal on the phone. +@Suite struct MobileCoreRPCSilentTransportTests { + private func makeClient( + transport: any CmxByteTransport, + port: Int, + timeoutNanoseconds: UInt64 = 200_000_000 + ) throws -> MobileCoreRPCClient { + let route = try hostPortRoute(kind: .debugLoopback, host: "127.0.0.1", port: port) + let runtime = TestMobileSyncRuntime( + transportFactory: FixedTransportFactory(transport: transport), + rpcRequestTimeoutNanoseconds: timeoutNanoseconds + ) + let ticket = try CmxAttachTicket( + workspaceID: "workspace-main", + terminalID: "terminal-main", + macDeviceID: "test-mac", + macDisplayName: "Test Mac", + routes: [route], + expiresAt: Date().addingTimeInterval(60), + authToken: "ticket-secret" + ) + return MobileCoreRPCClient( + runtime: runtime, + route: route, + ticket: ticket, + allowsStackAuthFallback: true + ) + } + + private func replayRequest(id: String) throws -> Data { + try MobileCoreRPCClient.requestData( + method: "mobile.terminal.replay", + params: ["workspace_id": "workspace-main", "surface_id": "surface-main"], + id: id + ) + } + + @Test func aTransportThatDeliversNothingIsCondemnedOnTheSecondTimeout() async throws { + let transport = ControllableResponseTransport(closeEndsReceive: true) + let client = try makeClient(transport: transport, port: 59310) + + do { + _ = try await client.sendRequest(try replayRequest(id: "replay-1")) + Issue.record("Expected the first replay to fail") + } catch {} + // One unanswered request is ambiguous; the connection survives it. + #expect(await transport.closed() == false) + + do { + _ = try await client.sendRequest(try replayRequest(id: "replay-2")) + Issue.record("Expected the retry to fail") + } catch {} + + // Both writes succeeded and the transport never reported itself + // closed, so nothing else in the session could condemn it. Two + // written requests answered by total silence is the evidence. + #expect(await transport.closed()) + } + + /// Six replays fired together and answered by one quiet period is one + /// piece of evidence, not six. Without a silence-window guard a single + /// quiet moment condemns the transport on concurrent requests alone. + @Test func concurrentTimeoutsInOneSilenceWindowAreOnePieceOfEvidence() async throws { + let transport = ControllableResponseTransport(closeEndsReceive: true) + let client = try makeClient(transport: transport, port: 59312) + + await withTaskGroup(of: Void.self) { group in + for index in 0..<4 { + group.addTask { + _ = try? await client.sendRequest( + try self.replayRequest(id: "concurrent-\(index)") + ) + } + } + await group.waitForAll() + } + + #expect(await transport.closed() == false) + } + + /// The guard that keeps this from punishing a healthy connection: if + /// anything at all arrived while the request was outstanding, the lane is + /// demonstrably alive and only the request failed. + @Test func aTransportStillDeliveringIsKeptWhenOneRequestTimesOut() async throws { + let transport = ControllableResponseTransport(closeEndsReceive: true) + let client = try makeClient(transport: transport, port: 59311) + + async let outcome: Void = { + do { + _ = try await client.sendRequest(try replayRequest(id: "replay-2")) + Issue.record("Expected the replay to fail") + } catch {} + }() + + await transport.waitUntilSent(count: 1) + // Unrelated inbound traffic: proves the lane still carries bytes even + // though this request is never answered. + try await transport.deliverResponse(id: "someone-else", status: "ok") + await outcome + + #expect(await transport.closed() == false) + } +} diff --git a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+AppDiagnostics.swift b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+AppDiagnostics.swift index b0e98b058685..9e8559ee44e4 100644 --- a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+AppDiagnostics.swift +++ b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+AppDiagnostics.swift @@ -24,6 +24,32 @@ extension MobileShellComposite { ) } + /// Adds one bounded terminal trace phase to the diagnostic spine, carrying + /// the categorical context that decides whether a slow replay is a blank + /// screen or merely stale text. + /// + /// The trace event has one integer payload slot, and this overload spends + /// it on ``MobileTerminalReplayTraceContext``. Use it for the phases that + /// have no byte count to report (`started` and `stalled`); the phases that + /// carry a payload size keep using `detail`. + public func recordTerminalTrace( + operation: DiagnosticTerminalTraceOperation, + phase: DiagnosticTerminalTracePhase, + traceID: DiagnosticTerminalTraceID, + surfaceID: String? = nil, + startedAt: Date? = nil, + replayContext: MobileTerminalReplayTraceContext + ) { + recordTerminalTrace( + operation: operation, + phase: phase, + traceID: traceID, + surfaceID: surfaceID, + startedAt: startedAt, + detail: replayContext.encoded + ) + } + /// Adds one bounded terminal trace phase to the diagnostic spine. public func recordTerminalTrace( operation: DiagnosticTerminalTraceOperation, diff --git a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalLane.swift b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalLane.swift index 58dddb01d7f1..d545cc423c59 100644 --- a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalLane.swift +++ b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalLane.swift @@ -157,6 +157,7 @@ extension MobileShellComposite { guard frame.sequence <= deliveredSequence else { requestAuthoritativeTerminalResync( surfaceID: surfaceID, + trigger: .byteGap, reason: "iroh_terminal_lane_gap" ) return .suspendUntilAuthoritativeOutput @@ -182,6 +183,7 @@ extension MobileShellComposite { guard frame.kind == .replay else { requestAuthoritativeTerminalResync( surfaceID: surfaceID, + trigger: .missingBaseline, reason: "iroh_terminal_lane_missing_baseline" ) return .suspendUntilAuthoritativeOutput diff --git a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalOutputDelivery.swift b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalOutputDelivery.swift index 4493e2e735a9..015d87c895b8 100644 --- a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalOutputDelivery.swift +++ b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalOutputDelivery.swift @@ -212,7 +212,7 @@ extension MobileShellComposite { "sync.render_grid_advisory source=\(source) surface=\(renderGrid.surfaceID) screen=\(renderGrid.activeScreen.rawValue) seq=\(renderGrid.stateSeq) requestReplay=\(deliveryDecision.requestReplay) updateTrackedScreen=\(deliveryDecision.updateTrackedScreen) deliverViewportPolicy=\(deliveryDecision.deliverViewportPolicy)" ) if deliveryDecision.requestReplay { - requestTerminalReplay(surfaceID: renderGrid.surfaceID) + requestTerminalReplay(surfaceID: renderGrid.surfaceID, trigger: .screenTransition) } #if DEBUG MobileLatencyTrace.stamp( @@ -272,7 +272,10 @@ extension MobileShellComposite { "base=\(deltaBase.map(String.init) ?? "nil") " + "delivered=\(delivered.map(String.init) ?? "nil") seq=\(renderGrid.stateSeq)" ) - terminalOutputNeedsReplay(surfaceID: renderGrid.surfaceID) + terminalOutputNeedsReplay( + surfaceID: renderGrid.surfaceID, + trigger: .historyChainBreak + ) #if DEBUG MobileLatencyTrace.stamp( "gate", @@ -299,7 +302,10 @@ extension MobileShellComposite { guard let deliveredRevisionContinuity, let deliveredColumns = deliveredRevisionContinuity.columns, let deliveredRows = deliveredRevisionContinuity.rows else { - terminalOutputNeedsReplay(surfaceID: renderGrid.surfaceID) + terminalOutputNeedsReplay( + surfaceID: renderGrid.surfaceID, + trigger: .applyFenceFailure + ) return } replaceablePatchShapeMatches = deliveredColumns == renderGrid.columns @@ -327,7 +333,10 @@ extension MobileShellComposite { "base=\(baseText) epoch=\(renderGrid.renderEpoch.prefix(8)) " + "delivered=\(deliveredText) seq=\(renderGrid.stateSeq)" ) - terminalOutputNeedsReplay(surfaceID: renderGrid.surfaceID) + terminalOutputNeedsReplay( + surfaceID: renderGrid.surfaceID, + trigger: .revisionChainBreak + ) #if DEBUG MobileLatencyTrace.stamp( "gate", @@ -523,6 +532,7 @@ extension MobileShellComposite { MobileDebugLog.anchormux("terminal.output.replay_retry_after_drop surface=\(surfaceID)") requestTerminalReplay( surfaceID: surfaceID, + trigger: .droppedFrame, replayBarrierToken: replayBarrierToken, coveredReplayBarrierDroppedOutputCount: droppedOutputCount ) @@ -538,7 +548,7 @@ extension MobileShellComposite { MobileDebugLog.anchormux( "terminal.output.pending_overflow surface=\(surfaceID) cap=\(TerminalOutputDeliveryQueue.maxPendingDeliveries)" ) - terminalOutputNeedsReplay(surfaceID: surfaceID) + terminalOutputNeedsReplay(surfaceID: surfaceID, trigger: .droppedFrame) return false } if bypassReplayBarrier, @@ -665,7 +675,11 @@ extension MobileShellComposite { terminalRenderGridBaselineReplayBarrierTokensBySurfaceID[surfaceID] = replayBarrierToken } MobileDebugLog.anchormux("terminal.output.replay_followup surface=\(surfaceID)") - requestTerminalReplay(surfaceID: surfaceID, replayBarrierToken: replayBarrierToken) + requestTerminalReplay( + surfaceID: surfaceID, + trigger: .coldAttach, + replayBarrierToken: replayBarrierToken + ) return } _ = failOpenTerminalReplayBarrier( @@ -754,7 +768,11 @@ extension MobileShellComposite { terminalAlternateRenderGridBaselineSurfaceIDs.remove(surfaceID) terminalMirrorHydrationNeededSurfaceIDs.insert(surfaceID) MobileDebugLog.anchormux("terminal.output.reset surface=\(surfaceID)") - requestTerminalReplay(surfaceID: surfaceID, replayBarrierToken: replayBarrierToken) + requestTerminalReplay( + surfaceID: surfaceID, + trigger: .outputReset, + replayBarrierToken: replayBarrierToken + ) } private func retryTerminalReplayAfterAckReset( @@ -795,6 +813,7 @@ extension MobileShellComposite { MobileDebugLog.anchormux("terminal.output.reset_replay_ack surface=\(surfaceID)") requestTerminalReplay( surfaceID: surfaceID, + trigger: .outputReset, replayBarrierToken: retryToken, coveredReplayBarrierDroppedOutputCount: terminalReplayBarrierDroppedOutputCountsBySurfaceID[surfaceID] @@ -805,6 +824,19 @@ extension MobileShellComposite { /// Reached from the render-pipeline reset: the surface was rebuilt blank, /// so (like ``terminalOutputDidReset``) no pre-barrier baseline survives. public func terminalOutputNeedsReplay(surfaceID: String) { + terminalOutputNeedsReplay(surfaceID: surfaceID, trigger: .renderPipelineReset) + } + + /// Same repair, naming the codepath that detected the divergence. + /// + /// The protocol entry point above cannot carry a reason, and every + /// detector funnels through here, so without this the whole class of + /// chain, shape, and overflow repairs is one undifferentiated bucket in + /// analytics. + func terminalOutputNeedsReplay( + surfaceID: String, + trigger: MobileTerminalReplayTrigger + ) { guard terminalByteContinuationsBySurfaceID[surfaceID] != nil else { return } if let pendingAckToken = terminalViewportReplayBarrierPendingAckTokensBySurfaceID[surfaceID], terminalReplayBarrierTokensBySurfaceID[surfaceID] == pendingAckToken { @@ -822,7 +854,11 @@ extension MobileShellComposite { terminalAlternateRenderGridBaselineSurfaceIDs.remove(surfaceID) terminalMirrorHydrationNeededSurfaceIDs.insert(surfaceID) MobileDebugLog.anchormux("terminal.output.replay_requested surface=\(surfaceID)") - requestTerminalReplay(surfaceID: surfaceID, replayBarrierToken: replayBarrierToken) + requestTerminalReplay( + surfaceID: surfaceID, + trigger: trigger, + replayBarrierToken: replayBarrierToken + ) } } diff --git a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalReplayLifecycle.swift b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalReplayLifecycle.swift index 504dcf5114c3..e60f0840a859 100644 --- a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalReplayLifecycle.swift +++ b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalReplayLifecycle.swift @@ -1,3 +1,4 @@ +internal import CMUXMobileCore internal import CmuxMobileDiagnostics internal import CmuxMobileRPC public import Foundation @@ -119,13 +120,21 @@ extension MobileShellComposite { /// Supersede every older replay and output acknowledgement for a surface, /// then request one authoritative replacement owned by the new barrier. - func requestAuthoritativeTerminalResync(surfaceID: String, reason: String) { + func requestAuthoritativeTerminalResync( + surfaceID: String, + trigger: MobileTerminalReplayTrigger, + reason: String + ) { guard hasTerminalOutputSink(surfaceID: surfaceID), remoteClient != nil else { return } let replayBarrierToken = beginTerminalReplayBarrierCarryingReplacedWork(surfaceID: surfaceID) MobileDebugLog.anchormux( "CMUX_REPLAY authoritative_resync reason=\(reason) surface=\(surfaceID)" ) - requestTerminalReplay(surfaceID: surfaceID, replayBarrierToken: replayBarrierToken) + requestTerminalReplay( + surfaceID: surfaceID, + trigger: trigger, + replayBarrierToken: replayBarrierToken + ) } func requestColdAttachTerminalReplay(surfaceID: String) { @@ -145,7 +154,11 @@ extension MobileShellComposite { if supportedHostCapabilities.contains(Self.terminalReplayCapability) { let replayBarrierToken = beginTerminalReplayBarrier(surfaceID: surfaceID) terminalColdAttachReplayBarrierTokensBySurfaceID[surfaceID] = replayBarrierToken - requestTerminalReplay(surfaceID: surfaceID, replayBarrierToken: replayBarrierToken) + requestTerminalReplay( + surfaceID: surfaceID, + trigger: .coldAttach, + replayBarrierToken: replayBarrierToken + ) return } if supportedHostCapabilities.isEmpty { @@ -153,7 +166,10 @@ extension MobileShellComposite { } else { terminalColdReplayNeedsBarrierUpgradeSurfaceIDs.remove(surfaceID) } - requestTerminalReplay(surfaceID: surfaceID) + requestTerminalReplay( + surfaceID: surfaceID, + trigger: .coldAttach + ) } func upgradePendingColdTerminalReplaysIfNeeded() { @@ -167,13 +183,20 @@ extension MobileShellComposite { // terminal.replay.v1 still need the pre-connection mount's cold // replay; mirror the unbarriered fallback used when mounting // after the connection resolved. - requestTerminalReplay(surfaceID: surfaceID) + requestTerminalReplay( + surfaceID: surfaceID, + trigger: .coldAttach + ) continue } guard terminalReplayBarrierTokensBySurfaceID[surfaceID] == nil else { continue } let replayBarrierToken = beginTerminalReplayBarrier(surfaceID: surfaceID) terminalColdAttachReplayBarrierTokensBySurfaceID[surfaceID] = replayBarrierToken - requestTerminalReplay(surfaceID: surfaceID, replayBarrierToken: replayBarrierToken) + requestTerminalReplay( + surfaceID: surfaceID, + trigger: .coldAttach, + replayBarrierToken: replayBarrierToken + ) } } @@ -388,6 +411,7 @@ extension MobileShellComposite { @discardableResult func requestTerminalReplayForCurrentBarrier( surfaceID: String, + trigger: MobileTerminalReplayTrigger, replayBarrierToken: UUID?, coveredReplayBarrierDroppedOutputCount: UInt64?, reason: String @@ -401,6 +425,7 @@ extension MobileShellComposite { MobileDebugLog.anchormux("CMUX_REPLAY retry_\(reason) surface=\(surfaceID)") requestTerminalReplay( surfaceID: surfaceID, + trigger: trigger, replayBarrierToken: replayBarrierToken, coveredReplayBarrierDroppedOutputCount: coveredReplayBarrierDroppedOutputCount ) @@ -437,6 +462,7 @@ extension MobileShellComposite { func clearTerminalReplayInFlightIfCurrent(surfaceID: String, requestID: UUID) { guard terminalReplayRequestIDsInFlightBySurfaceID[surfaceID] == requestID else { return } + cancelTerminalReplayStallProbe(surfaceID: surfaceID) terminalReplaySurfaceIDsInFlight.remove(surfaceID) terminalReplayRequestIDsInFlightBySurfaceID.removeValue(forKey: surfaceID) terminalReplayTasksBySurfaceID.removeValue(forKey: surfaceID) @@ -444,6 +470,7 @@ extension MobileShellComposite { } func cancelTerminalReplayInFlight(surfaceID: String) { + cancelTerminalReplayStallProbe(surfaceID: surfaceID) terminalReplayTasksBySurfaceID.removeValue(forKey: surfaceID)?.cancel() terminalReplaySurfaceIDsInFlight.remove(surfaceID) terminalReplayRequestIDsInFlightBySurfaceID.removeValue(forKey: surfaceID) @@ -451,6 +478,7 @@ extension MobileShellComposite { } func cancelAllTerminalReplayTasks() { + cancelAllTerminalReplayStallProbes() for task in terminalReplayTasksBySurfaceID.values { task.cancel() } @@ -546,6 +574,7 @@ extension MobileShellComposite { } shouldRearmAfterTimeout = !self.requestTerminalReplayForCurrentBarrier( surfaceID: surfaceID, + trigger: .viewportTransition, replayBarrierToken: retryToken, coveredReplayBarrierDroppedOutputCount: nil, reason: "viewport_transition_timeout" @@ -597,7 +626,11 @@ extension MobileShellComposite { let replayBarrierToken = beginTerminalReplayBarrier(surfaceID: surfaceID) terminalRenderGridBaselineReplayRequestCountsBySurfaceID[surfaceID] = requestCount + 1 terminalRenderGridBaselineReplayBarrierTokensBySurfaceID[surfaceID] = replayBarrierToken - requestTerminalReplay(surfaceID: surfaceID, replayBarrierToken: replayBarrierToken) + requestTerminalReplay( + surfaceID: surfaceID, + trigger: .missingBaseline, + replayBarrierToken: replayBarrierToken + ) } /// An authoritative replay was accepted: its state supersedes the diff --git a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalReplayRetry.swift b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalReplayRetry.swift index b450fb34b60c..98acbac038f9 100644 --- a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalReplayRetry.swift +++ b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalReplayRetry.swift @@ -1,4 +1,5 @@ import Foundation +internal import CMUXMobileCore internal import CmuxMobileDiagnostics /// Retry accounting for the pending-input render-grid drop path, layered on @@ -40,7 +41,7 @@ extension MobileShellComposite { terminalReplayFailureRetryCountsBySurfaceID.removeValue(forKey: surfaceID) return } - requestTerminalReplay(surfaceID: surfaceID) + requestTerminalReplay(surfaceID: surfaceID, trigger: .pendingInputDrop) } @discardableResult @@ -59,6 +60,7 @@ extension MobileShellComposite { clearTerminalReplayInFlightIfCurrent(surfaceID: surfaceID, requestID: replayRequestID) requestTerminalReplay( surfaceID: surfaceID, + trigger: .failureRetry, replayBarrierToken: retryToken, coveredReplayBarrierDroppedOutputCount: coveredReplayBarrierDroppedOutputCount ?? terminalReplayBarrierDroppedOutputCountsBySurfaceID[surfaceID] @@ -68,7 +70,7 @@ extension MobileShellComposite { if replayBarrierToken == nil, prepareNonBarrierTerminalReplayFailureRetry(surfaceID: surfaceID) { clearTerminalReplayInFlightIfCurrent(surfaceID: surfaceID, requestID: replayRequestID) - requestTerminalReplay(surfaceID: surfaceID) + requestTerminalReplay(surfaceID: surfaceID, trigger: .failureRetry) return true } let retryBudgetExhausted = retryBudgetWasExhausted diff --git a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalReplayStallProbe.swift b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalReplayStallProbe.swift new file mode 100644 index 000000000000..b5df52a420f2 --- /dev/null +++ b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalReplayStallProbe.swift @@ -0,0 +1,97 @@ +internal import CMUXMobileCore +internal import Foundation + +/// Emits evidence while a terminal replay is still outstanding. +/// +/// Every other terminal trace phase is terminal, so a replay that never +/// settles produces no analytics row at all: the worst stalls, where the +/// surface has been rebuilt blank and only the replay response can repaint +/// it, were exactly the ones Axiom could not see. This probe closes that gap +/// by stamping ``DiagnosticTerminalTracePhase/stalled`` on a bounded schedule +/// while the request is in flight, carrying the elapsed time and the context +/// that says whether the user is looking at a blank terminal. +/// +/// The probe is pure telemetry. It never requests, retries, or fails a +/// replay, and cancelling it cannot change delivery behavior. +extension MobileShellComposite { + /// Elapsed marks, in seconds, at which an outstanding replay is stamped. + /// + /// The first mark sits just above the applied-replay p90 so ordinary slow + /// replays stay quiet, and the last mark sits past the RPC deadline so a + /// request the deadline failed to bound still reports. + static let terminalReplayStallProbeMarks: [Duration] = [ + .seconds(2), .seconds(5), .seconds(10), .seconds(20), + .seconds(35), .seconds(60), .seconds(120), .seconds(300), + ] + + func armTerminalReplayStallProbe( + surfaceID: String, + requestID: UUID, + traceID: DiagnosticTerminalTraceID, + startedAt: Date, + context: MobileTerminalReplayTraceContext + ) { + cancelTerminalReplayStallProbe(surfaceID: surfaceID) + let clock = controlPlaneSchedulingClock + let marks = Self.terminalReplayStallProbeMarks + terminalReplayStallProbeTasksBySurfaceID[surfaceID] = Task { @MainActor [weak self] in + var elapsed: Duration = .zero + for mark in marks { + let step = mark - elapsed + guard step > .zero else { continue } + do { + try await clock.sleep(for: step, tolerance: nil) + } catch { + return + } + elapsed = mark + guard !Task.isCancelled, let self else { return } + // The request settled (or was replaced) while this slept; the + // settled phase is the authoritative record from here on. + guard self.terminalReplayRequestIDsInFlightBySurfaceID[surfaceID] == requestID else { + return + } + self.recordTerminalTrace( + operation: .replay, + phase: .stalled, + traceID: traceID, + surfaceID: surfaceID, + startedAt: startedAt, + replayContext: context + ) + } + } + } + + func cancelTerminalReplayStallProbe(surfaceID: String) { + terminalReplayStallProbeTasksBySurfaceID.removeValue(forKey: surfaceID)?.cancel() + } + + func cancelAllTerminalReplayStallProbes() { + for task in terminalReplayStallProbeTasksBySurfaceID.values { + task.cancel() + } + terminalReplayStallProbeTasksBySurfaceID = [:] + } + + /// The categorical context for a replay about to be requested. + /// + /// `surfaceIsBlank` reuses the same condition the request uses to decide + /// whether to ask the Mac for scrollback: the mirror needs hydration, or + /// no baseline was ever delivered. Both mean nothing survives locally to + /// paint, so the surface is blank until this replay lands. + func terminalReplayTraceContext( + surfaceID: String, + trigger: MobileTerminalReplayTrigger, + replayBarrierToken: UUID? + ) -> MobileTerminalReplayTraceContext { + MobileTerminalReplayTraceContext( + trigger: trigger, + surfaceIsBlank: deliveredTerminalByteEndSeqBySurfaceID[surfaceID] == nil + || terminalMirrorHydrationNeededSurfaceIDs.contains(surfaceID), + barrierActive: replayBarrierToken != nil + || terminalReplayBarrierTokensBySurfaceID[surfaceID] != nil, + attempt: terminalReplayFailureRetryCountsBySurfaceID[surfaceID] ?? 0 + ) + } +} diff --git a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalViewport.swift b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalViewport.swift index 3e2edea287b5..ca0a1cc67a24 100644 --- a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalViewport.swift +++ b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+TerminalViewport.swift @@ -304,7 +304,11 @@ extension MobileShellComposite { MobileDebugLog.anchormux( "terminal.output.viewport_resync surface=\(surfaceID) grid=\(effectiveGrid.columns)x\(effectiveGrid.rows)" ) - requestTerminalReplay(surfaceID: surfaceID, replayBarrierToken: replayBarrierToken) + requestTerminalReplay( + surfaceID: surfaceID, + trigger: .viewportTransition, + replayBarrierToken: replayBarrierToken + ) replayRequested = true } else if prearmedReplayBarrierToken == nil, terminalReplayBarrierTokensBySurfaceID[surfaceID] != nil, @@ -318,7 +322,11 @@ extension MobileShellComposite { // barrier's owed work. let replayBarrierToken = beginTerminalReplayBarrierCarryingReplacedWork(surfaceID: surfaceID) MobileDebugLog.anchormux("terminal.output.viewport_rearm_exhausted surface=\(surfaceID)") - requestTerminalReplay(surfaceID: surfaceID, replayBarrierToken: replayBarrierToken) + requestTerminalReplay( + surfaceID: surfaceID, + trigger: .viewportTransition, + replayBarrierToken: replayBarrierToken + ) replayRequested = true } else { replayRequested = finishPrearmedTerminalViewportBarrierWithoutResize( @@ -503,7 +511,11 @@ extension MobileShellComposite { hasTerminalOutputSink(surfaceID: surfaceID), remoteClient != nil { MobileDebugLog.anchormux("terminal.output.viewport_replay_after_\(reason) surface=\(surfaceID)") - requestTerminalReplay(surfaceID: surfaceID, replayBarrierToken: token) + requestTerminalReplay( + surfaceID: surfaceID, + trigger: .viewportTransition, + replayBarrierToken: token + ) return true } clearTerminalReplayBarrierIfCurrent( diff --git a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+WorkspaceListRecovery.swift b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+WorkspaceListRecovery.swift index 3ce1cb513f57..a12e6b620a28 100644 --- a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+WorkspaceListRecovery.swift +++ b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite+WorkspaceListRecovery.swift @@ -440,7 +440,11 @@ extension MobileShellComposite { connectionState == .connected else { return } if subscribed || runtime?.supportsServerPushEvents == false { for surfaceID in surfaceIDs { - requestAuthoritativeTerminalResync(surfaceID: surfaceID, reason: "manual_reconnect") + requestAuthoritativeTerminalResync( + surfaceID: surfaceID, + trigger: .resubscribe, + reason: "manual_reconnect" + ) } } await refreshWorkspaces() diff --git a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite.swift b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite.swift index 8860565d025d..855bdcabab01 100644 --- a/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite.swift +++ b/Packages/iOS/CmuxMobileShell/Sources/CmuxMobileShell/MobileShellComposite.swift @@ -1589,6 +1589,8 @@ public final class MobileShellComposite: MobileTerminalOutputSinking { var terminalReplaySurfaceIDsInFlight: Set var terminalReplayRequestIDsInFlightBySurfaceID: [String: UUID] var terminalReplayTasksBySurfaceID: [String: Task] + /// Telemetry-only probes that stamp an outstanding replay as stalled. + var terminalReplayStallProbeTasksBySurfaceID: [String: Task] var terminalReplayBarrierWatchdogTasksBySurfaceID: [String: Task] var terminalReplayBarrierWatchdogIDsBySurfaceID: [String: UUID] var terminalReplayBarrierWatchdogTokensBySurfaceID: [String: UUID] @@ -2013,6 +2015,7 @@ public final class MobileShellComposite: MobileTerminalOutputSinking { self.terminalReplaySurfaceIDsInFlight = [] self.terminalReplayRequestIDsInFlightBySurfaceID = [:] self.terminalReplayTasksBySurfaceID = [:] + self.terminalReplayStallProbeTasksBySurfaceID = [:] self.terminalReplayBarrierWatchdogTasksBySurfaceID = [:] self.terminalReplayBarrierWatchdogIDsBySurfaceID = [:] self.terminalReplayBarrierWatchdogTokensBySurfaceID = [:] @@ -14606,7 +14609,11 @@ public final class MobileShellComposite: MobileTerminalOutputSinking { "sync.resync reason=\(reason) restart=\(restartEventStream) surfaces=\(surfaceIDs.count)" ) for surfaceID in surfaceIDs { - requestAuthoritativeTerminalResync(surfaceID: surfaceID, reason: reason) + requestAuthoritativeTerminalResync( + surfaceID: surfaceID, + trigger: .resubscribe, + reason: reason + ) } } @@ -14760,6 +14767,7 @@ public final class MobileShellComposite: MobileTerminalOutputSinking { } else { self.requestAuthoritativeTerminalResync( surfaceID: surfaceID, + trigger: .pendingInputDrop, reason: "input_seq_wait_retry" ) } @@ -14771,6 +14779,7 @@ public final class MobileShellComposite: MobileTerminalOutputSinking { for surfaceID in terminalByteContinuationsBySurfaceID.keys { requestAuthoritativeTerminalResync( surfaceID: surfaceID, + trigger: .resubscribe, reason: reason ) } @@ -15093,6 +15102,7 @@ public final class MobileShellComposite: MobileTerminalOutputSinking { /// for TUIs, and a VT export is still a replay stream rather than state. func requestTerminalReplay( surfaceID: String, + trigger: MobileTerminalReplayTrigger, replayBarrierToken: UUID? = nil, coveredReplayBarrierDroppedOutputCount: UInt64? = nil ) { @@ -15171,11 +15181,30 @@ public final class MobileShellComposite: MobileTerminalOutputSinking { ) let diagnosticStartedAt = appDiagnosticNow() let terminalTraceID = DiagnosticTerminalTraceID() + // Captured before the request so the stall probe and the settled + // phases all describe the same episode, even after retries mutate the + // surface's counters. + let replayTraceContext = terminalReplayTraceContext( + surfaceID: surfaceID, + trigger: trigger, + replayBarrierToken: replayBarrierTokenForRequest + ) recordTerminalTrace( operation: .replay, phase: .started, traceID: terminalTraceID, - surfaceID: surfaceID + surfaceID: surfaceID, + replayContext: replayTraceContext + ) + // Nothing else reports an outstanding replay: every other phase is + // terminal, so a request that never settles would otherwise leave no + // trace of a surface that stayed blank waiting for it. + armTerminalReplayStallProbe( + surfaceID: surfaceID, + requestID: replayRequestID, + traceID: terminalTraceID, + startedAt: diagnosticStartedAt, + context: replayTraceContext ) recordAppEvent( .terminalReplayStarted, @@ -15266,6 +15295,18 @@ public final class MobileShellComposite: MobileTerminalOutputSinking { // suspension point, so every staleness guard below already // observes post-decode state. let decoded = await Self.decodeTerminalReplayResponseOffMain(data) + // Splits the round trip: this phase's detail is the host's own + // capture time, so the remainder is transport and queueing. + if let hostElapsed = decoded.payload?.hostElapsedMilliseconds { + self.recordTerminalTrace( + operation: .replay, + phase: .hostCaptureFinished, + traceID: terminalTraceID, + surfaceID: surfaceID, + startedAt: diagnosticStartedAt, + detail: Int(hostElapsed) + ) + } self.recordTerminalTrace( operation: .replay, phase: .decoded, @@ -15300,6 +15341,7 @@ public final class MobileShellComposite: MobileTerminalOutputSinking { transferredInFlightToRetry = true guard self.requestTerminalReplayForCurrentBarrier( surfaceID: surfaceID, + trigger: .failureRetry, replayBarrierToken: replayBarrierTokenForRequest, coveredReplayBarrierDroppedOutputCount: nil, reason: "stale_client" @@ -15476,6 +15518,7 @@ public final class MobileShellComposite: MobileTerminalOutputSinking { transferredInFlightToRetry = true self.requestTerminalReplay( surfaceID: surfaceID, + trigger: .failureRetry, replayBarrierToken: retryToken, coveredReplayBarrierDroppedOutputCount: self.terminalReplayBarrierDroppedOutputCountsBySurfaceID[surfaceID] @@ -15604,6 +15647,7 @@ public final class MobileShellComposite: MobileTerminalOutputSinking { transferredInFlightToRetry = true guard self.requestTerminalReplayForCurrentBarrier( surfaceID: surfaceID, + trigger: .failureRetry, replayBarrierToken: replayBarrierTokenForRequest, coveredReplayBarrierDroppedOutputCount: nil, reason: "stale_client" @@ -15660,6 +15704,7 @@ public final class MobileShellComposite: MobileTerminalOutputSinking { transferredInFlightToRetry = true self.requestTerminalReplay( surfaceID: surfaceID, + trigger: .failureRetry, replayBarrierToken: retryToken, coveredReplayBarrierDroppedOutputCount: coveredReplayBarrierDroppedOutputCountForRequest ) @@ -15828,7 +15873,7 @@ public final class MobileShellComposite: MobileTerminalOutputSinking { // state. Keep the catch-up replay nonblocking so later live // bytes continue while it verifies the missing interval. refreshTerminalOutputSubscription(reason: "seq_gap", restartEventStream: false) - requestTerminalReplay(surfaceID: surfaceID) + requestTerminalReplay(surfaceID: surfaceID, trigger: .byteGap) return } if endSeq <= deliveredSeq { diff --git a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellRenderGridInputCatchUpTests.swift b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellRenderGridInputCatchUpTests.swift index c9bcbef0232b..cc5e3f019c48 100644 --- a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellRenderGridInputCatchUpTests.swift +++ b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellRenderGridInputCatchUpTests.swift @@ -439,7 +439,7 @@ import Testing renderGridFrame(surfaceID: surfaceID, seq: 99, text: "stale-replay"), renderGridFrame(surfaceID: surfaceID, seq: 100, text: "fresh-replay"), ]) - store.requestTerminalReplay(surfaceID: surfaceID, replayBarrierToken: replayBarrierToken) + store.requestTerminalReplay(surfaceID: surfaceID, trigger: .coldAttach, replayBarrierToken: replayBarrierToken) await router.waitForCount(of: "mobile.terminal.replay", atLeast: replayCountAfterMount + 1) let retryRequested = await router.waitForCount( of: "mobile.terminal.replay", @@ -475,7 +475,7 @@ import Testing let transport = try #require(box.get()) await router.holdNextReplayResponses() - store.requestTerminalReplay(surfaceID: surfaceID) + store.requestTerminalReplay(surfaceID: surfaceID, trigger: .coldAttach) let oldReplayInFlight = await router.waitForCount( of: "mobile.terminal.replay", atLeast: replayCountAfterMount + 1 @@ -542,7 +542,7 @@ import Testing renderGridFrame(surfaceID: surfaceID, seq: 98, text: "stale-replay-2"), renderGridFrame(surfaceID: surfaceID, seq: 99, text: "stale-replay-3"), ]) - store.requestTerminalReplay(surfaceID: surfaceID, replayBarrierToken: replayBarrierToken) + store.requestTerminalReplay(surfaceID: surfaceID, trigger: .coldAttach, replayBarrierToken: replayBarrierToken) let exhaustedRetriesSent = await router.waitForCount(of: "mobile.terminal.replay", atLeast: replayCountAfterMount + 3) #expect(exhaustedRetriesSent) let replaySettled = try await pollUntil { diff --git a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellRenderGridReplayRetryExhaustionTests.swift b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellRenderGridReplayRetryExhaustionTests.swift index 01bb92bb2999..e377cbb290e0 100644 --- a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellRenderGridReplayRetryExhaustionTests.swift +++ b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellRenderGridReplayRetryExhaustionTests.swift @@ -24,7 +24,7 @@ import Testing let transport = try #require(box.get()) await router.holdNextReplayResponses() - store.requestTerminalReplay(surfaceID: surfaceID) + store.requestTerminalReplay(surfaceID: surfaceID, trigger: .coldAttach) let oldReplayInFlight = await router.waitForCount( of: "mobile.terminal.replay", atLeast: replayCountAfterMount + 1 diff --git a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellRenderGridReplayStalenessTests.swift b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellRenderGridReplayStalenessTests.swift index 648397c7dd82..d7b3c30ea852 100644 --- a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellRenderGridReplayStalenessTests.swift +++ b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellRenderGridReplayStalenessTests.swift @@ -165,7 +165,7 @@ func screenAnchoredReplayBaselinesNextLiveDelta(historyRows: UInt64) async throw await router.holdNextReplayResponses() let replayCountBeforeHeldReplay = await router.count(of: "mobile.terminal.replay") - store.requestTerminalReplay(surfaceID: "live-terminal") + store.requestTerminalReplay(surfaceID: "live-terminal", trigger: .coldAttach) let heldReplayRequested = try await pollUntil { await router.count(of: "mobile.terminal.replay") > replayCountBeforeHeldReplay } @@ -229,7 +229,7 @@ func screenAnchoredReplayBaselinesNextLiveDelta(historyRows: UInt64) async throw await router.holdNextReplayResponses() let replayCountBeforeHeldReplay = await router.count(of: "mobile.terminal.replay") - store.requestTerminalReplay(surfaceID: "live-terminal") + store.requestTerminalReplay(surfaceID: "live-terminal", trigger: .coldAttach) let heldReplayRequested = try await pollUntil { await router.count(of: "mobile.terminal.replay") > replayCountBeforeHeldReplay } @@ -297,7 +297,7 @@ func screenAnchoredReplayBaselinesNextLiveDelta(historyRows: UInt64) async throw await router.holdNextReplayResponses() let replayCountBeforeHeldReplay = await router.count(of: "mobile.terminal.replay") - store.requestTerminalReplay(surfaceID: "live-terminal") + store.requestTerminalReplay(surfaceID: "live-terminal", trigger: .coldAttach) let heldReplayRequested = try await pollUntil { await router.count(of: "mobile.terminal.replay") > replayCountBeforeHeldReplay } @@ -365,7 +365,7 @@ func screenAnchoredReplayBaselinesNextLiveDelta(historyRows: UInt64) async throw await router.holdNextReplayResponses() let replayCountBeforeHeldReplay = await router.count(of: "mobile.terminal.replay") - store.requestTerminalReplay(surfaceID: "live-terminal") + store.requestTerminalReplay(surfaceID: "live-terminal", trigger: .coldAttach) let heldReplayRequested = try await pollUntil { await router.count(of: "mobile.terminal.replay") > replayCountBeforeHeldReplay } @@ -434,7 +434,7 @@ func screenAnchoredReplayBaselinesNextLiveDelta(historyRows: UInt64) async throw await router.holdNextReplayResponses() let replayCountBeforeHeldReplay = await router.count(of: "mobile.terminal.replay") - store.requestTerminalReplay(surfaceID: "live-terminal") + store.requestTerminalReplay(surfaceID: "live-terminal", trigger: .coldAttach) let heldReplayRequested = try await pollUntil { await router.count(of: "mobile.terminal.replay") > replayCountBeforeHeldReplay } diff --git a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellReplayDropRecoveryTests.swift b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellReplayDropRecoveryTests.swift index 7639baa0a1c4..0773e26f7688 100644 --- a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellReplayDropRecoveryTests.swift +++ b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellReplayDropRecoveryTests.swift @@ -47,7 +47,7 @@ import Testing recoveryRenderGridFrame(surfaceID: surfaceID, seq: 12, text: "current"), recoveryRenderGridFrame(surfaceID: surfaceID, seq: 12, text: "current"), ]) - store.requestTerminalReplay(surfaceID: surfaceID) + store.requestTerminalReplay(surfaceID: surfaceID, trigger: .coldAttach) await router.waitForCount(of: "mobile.terminal.replay", atLeast: replayCountAfterMount + 1) store.terminalReplayBarrierTokensBySurfaceID[surfaceID] = UUID() diff --git a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellReplayFallbackScreenTests.swift b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellReplayFallbackScreenTests.swift index 5043566463b3..52a5809477db 100644 --- a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellReplayFallbackScreenTests.swift +++ b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/MobileShellReplayFallbackScreenTests.swift @@ -1,3 +1,4 @@ +import CMUXMobileCore import Foundation import Testing @testable import CmuxMobileShell @@ -35,6 +36,7 @@ import Testing let replayBarrierToken = store.beginTerminalReplayBarrier(surfaceID: "live-terminal") store.requestTerminalReplay( surfaceID: "live-terminal", + trigger: .coldAttach, replayBarrierToken: replayBarrierToken ) await router.waitForCount( diff --git a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalByteGapRebaseTests.swift b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalByteGapRebaseTests.swift index a22862faef24..839ef266313c 100644 --- a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalByteGapRebaseTests.swift +++ b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalByteGapRebaseTests.swift @@ -1,3 +1,4 @@ +import CMUXMobileCore import Foundation import Testing @testable import CmuxMobileShell @@ -68,7 +69,7 @@ import Testing #expect(firstDelivered) await router.holdNextReplayResponses() - store.requestTerminalReplay(surfaceID: surfaceID) + store.requestTerminalReplay(surfaceID: surfaceID, trigger: .coldAttach) await router.waitForCount(of: "mobile.terminal.replay", atLeast: replayCountAfterMount + 1) #expect(store.terminalReplaySurfaceIDsInFlight.contains(surfaceID)) diff --git a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalOutputDeliveryQueueTests.swift b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalOutputDeliveryQueueTests.swift index 6b5ddb6567f1..50c4b4e1646d 100644 --- a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalOutputDeliveryQueueTests.swift +++ b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalOutputDeliveryQueueTests.swift @@ -548,7 +548,7 @@ import Testing let replayCountAfterExhaustion = await router.count(of: "mobile.terminal.replay") await router.enqueueReplayTexts(["resync-replay"]) - store.requestTerminalReplay(surfaceID: surfaceID) + store.requestTerminalReplay(surfaceID: surfaceID, trigger: .coldAttach) let genericReplayRequested = await waitForReplayRequestCount(router, atLeast: replayCountAfterExhaustion + 1) #expect(genericReplayRequested, "generic resync must still work after fail-open clears the barrier") diff --git a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalReplayBarrierFollowUpTests.swift b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalReplayBarrierFollowUpTests.swift index b9f55244af56..7c4a1f58b7b9 100644 --- a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalReplayBarrierFollowUpTests.swift +++ b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalReplayBarrierFollowUpTests.swift @@ -1,3 +1,4 @@ +import CMUXMobileCore import Foundation import Testing @testable import CmuxMobileShell @@ -121,7 +122,7 @@ import Testing full: true )) let firstBarrierToken = store.beginTerminalReplayBarrier(surfaceID: surfaceID) - store.requestTerminalReplay(surfaceID: surfaceID, replayBarrierToken: firstBarrierToken) + store.requestTerminalReplay(surfaceID: surfaceID, trigger: .coldAttach, replayBarrierToken: firstBarrierToken) await router.waitForCount(of: "mobile.terminal.replay", atLeast: 2) let firstReplayChunk = try #require(await iterator.next()) diff --git a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalViewportResyncTests.swift b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalViewportResyncTests.swift index 68854dcf32bd..29f7b7127581 100644 --- a/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalViewportResyncTests.swift +++ b/Packages/iOS/CmuxMobileShell/Tests/CmuxMobileShellTests/TerminalViewportResyncTests.swift @@ -1,3 +1,4 @@ +import CMUXMobileCore import CmuxMobileShellModel import Foundation import Testing @@ -221,7 +222,7 @@ import Testing rows: 30 ) ) - store.requestTerminalReplay(surfaceID: surfaceID) + store.requestTerminalReplay(surfaceID: surfaceID, trigger: .coldAttach) #expect(store.terminalReplayBarrierTokensBySurfaceID[surfaceID] == nil) #expect( await router.waitForCount( @@ -289,7 +290,7 @@ import Testing store.terminalOutputDidProcess(surfaceID: surfaceID, streamToken: initialViewportChunk.streamToken) await router.failNextReplay(code: "viewport_transition") - store.requestTerminalReplay(surfaceID: surfaceID) + store.requestTerminalReplay(surfaceID: surfaceID, trigger: .coldAttach) let replayRequested = await router.waitForCount(of: "mobile.terminal.replay", atLeast: 3) #expect(replayRequested) let requestSettled = try await pollUntil { @@ -388,7 +389,7 @@ import Testing surfaceID: surfaceID ) #expect(!staleAccepted, "output must be dropped while a resize acknowledgement is in flight") - store.requestTerminalReplay(surfaceID: surfaceID) + store.requestTerminalReplay(surfaceID: surfaceID, trigger: .coldAttach) let replayBeforeAck = await router.waitForCount( of: "mobile.terminal.replay", atLeast: replayCountAfterBaseline + 1, @@ -720,7 +721,7 @@ import Testing // A recovery path (liveness probe repair, resync, advisory) asks for an // authoritative replay. It must defer to the pending acknowledgement, // not fire a competing replay. - store.requestTerminalReplay(surfaceID: surfaceID) + store.requestTerminalReplay(surfaceID: surfaceID, trigger: .coldAttach) let competingReplay = await router.waitForCount( of: "mobile.terminal.replay", atLeast: replayCountAfterBaseline + 1, @@ -1310,7 +1311,7 @@ import Testing let staleToken = store.beginTerminalReplayBarrier(surfaceID: surfaceID) let currentToken = store.beginTerminalReplayBarrier(surfaceID: surfaceID) let replayCountBeforeStaleRequest = await router.count(of: "mobile.terminal.replay") - store.requestTerminalReplay(surfaceID: surfaceID, replayBarrierToken: staleToken) + store.requestTerminalReplay(surfaceID: surfaceID, trigger: .coldAttach, replayBarrierToken: staleToken) let staleReplayRequested = await router.waitForCount( of: "mobile.terminal.replay", @@ -1453,7 +1454,7 @@ import Testing #expect(clearRequest.clearsViewport) let replayCount = await router.count(of: "mobile.terminal.replay") - store.requestTerminalReplay(surfaceID: surfaceID) + store.requestTerminalReplay(surfaceID: surfaceID, trigger: .coldAttach) let replaySent = await router.waitForCount( of: "mobile.terminal.replay", atLeast: replayCount + 1 diff --git a/Sources/TerminalController.swift b/Sources/TerminalController.swift index e2279423ad3d..70015cf4c937 100644 --- a/Sources/TerminalController.swift +++ b/Sources/TerminalController.swift @@ -15374,6 +15374,12 @@ class TerminalController { } } recordTrace("host_capture_finished") + // Hand the phone the host's own share of this round trip. Without it a + // slow replay is unattributable: the phone cannot tell a slow capture + // here from a slow or stalled transport between us. + payload["host_elapsed_ms"] = Int( + (DispatchTime.now().uptimeNanoseconds &- traceStartedAt) / 1_000_000 + ) return .ok(payload) } diff --git a/ios/cmux/AppCompositionRoot.swift b/ios/cmux/AppCompositionRoot.swift index 8f71a878963e..3647700fc973 100644 --- a/ios/cmux/AppCompositionRoot.swift +++ b/ios/cmux/AppCompositionRoot.swift @@ -395,6 +395,7 @@ final class AppCompositionRoot { switch phase { case .active: analytics.terminalLatencyReporter.setForeground(true) + analytics.terminalTraceReporter.setForeground(true) diagnosticLog.recordAppEvent(.appForegrounded) connectionMethodStore.recordConfiguredMethodDiagnostic() let isFullForegroundReturn = !hasForegrounded || wasBackgrounded @@ -429,12 +430,14 @@ final class AppCompositionRoot { hasForegrounded = true case .inactive: analytics.terminalLatencyReporter.setForeground(false) + analytics.terminalTraceReporter.setForeground(false) diagnosticLog.recordAppEvent(.appBecameInactive) // The switcher opened; a swipe-kill from here may skip the // background transition entirely, so snapshot diagnostics now. break case .background: analytics.terminalLatencyReporter.setForeground(false) + analytics.terminalTraceReporter.setForeground(false) diagnosticLog.recordAppEvent(.appBackgrounded) wasBackgrounded = true Task { await irx.didEnterBackground() } diff --git a/web/services/observability/mobileNetworkOutcome.ts b/web/services/observability/mobileNetworkOutcome.ts index 9a6dc36c785e..edc032085ac1 100644 --- a/web/services/observability/mobileNetworkOutcome.ts +++ b/web/services/observability/mobileNetworkOutcome.ts @@ -17,7 +17,7 @@ const phases = new Set([ "endpoint_start", "pairing", "transport_dial", "host_auth", "rpc_ready", "recovery", "relay_policy", "discovery", "initial_connect", "terminal_trace", ]); -const outcomes = new Set(["success", "failure", "timeout", "cancelled", "abandoned"]); +const outcomes = new Set(["success", "failure", "timeout", "cancelled", "abandoned", "stalled"]); const failures = new Set([ "offline", "timedOut", "connectionRefused", "hostUnreachable", "permissionDenied", "dnsFailed", "secureChannelFailed", "unsupportedRoute", @@ -57,13 +57,14 @@ const allowedPropertyKeys = new Set([ "input_failed_count", "histogram_version", "input_to_output_histogram", "input_to_visible_histogram", "render_histogram", "duration_ms", "threshold_ms", "stage", "trace_id", "operation", "terminal_phase", + "replay_trigger", "surface_blank", "barrier_active", "replay_attempt", "app_foreground", "model_count", "phase", "attempt", "retry_delay_ms", "stop_reason", "correlation_id", ]); export type MobileNetworkOutcome = { readonly timestamp: string; readonly phase: string; - readonly outcome: "success" | "failure" | "timeout" | "cancelled" | "abandoned"; + readonly outcome: "success" | "failure" | "timeout" | "cancelled" | "abandoned" | "stalled"; readonly durationMs: number; readonly runtimeRole: "mobileClient"; readonly userUsable: boolean; @@ -90,6 +91,20 @@ export type MobileNetworkOutcome = { readonly traceId?: string; readonly operation?: string; readonly terminalPhase?: string; + /** Why the replay this trace describes was requested. */ + readonly replayTrigger?: string; + /** The surface had been rebuilt blank, so this stall is a blank screen. */ + readonly surfaceBlank?: boolean; + /** A replay barrier was suppressing live output for the surface. */ + readonly barrierActive?: boolean; + /** Zero-based retry index within the replay episode. */ + readonly replayAttempt?: number; + /** + * Whether the app was on screen when this phase was recorded. A suspended + * app runs no code, so elapsed time that spans suspension was never spent + * waiting on screen; percentiles that mix the two are meaningless. + */ + readonly appForeground?: boolean; }; export type MobileTerminalLatencyWindow = { @@ -341,7 +356,15 @@ export function parseMobileTaskModelDiscovery(candidate: unknown): MobileTaskMod } type CoreObservation = Pick; -type Metadata = Pick; +type Metadata = Pick; + +/** Mirrors `MobileTerminalReplayTrigger` in CMUXMobileCore. */ +const replayTriggers = new Set([ + "unknown", "outputReset", "renderPipelineReset", "viewportTransition", + "revisionChainBreak", "historyChainBreak", "coldAttach", "failureRetry", + "droppedFrame", "applyFenceFailure", "pendingInputDrop", "resubscribe", + "screenTransition", "missingBaseline", "byteGap", +]); function validTimestamp(value: unknown): value is string { return typeof value === "string" @@ -420,6 +443,27 @@ function parseInitialConnectionFields( }; } +/// Categorical context for a replay trace. Split out of `parseMetadata` to +/// keep that function under the repository complexity limit. +function parseReplayContextFields( + properties: Record, +): Pick | null { + const replayTrigger = optionalSetValue(properties.replay_trigger, replayTriggers); + const surfaceBlank = optionalBoolean(properties.surface_blank); + const barrierActive = optionalBoolean(properties.barrier_active); + const appForeground = optionalBoolean(properties.app_foreground); + const replayAttempt = optionalDiagnosticInteger(properties.replay_attempt, 0xff); + if (replayTrigger === false || replayAttempt === false) return null; + if (surfaceBlank === null || barrierActive === null || appForeground === null) return null; + return { + ...(typeof replayTrigger === "string" ? { replayTrigger } : {}), + ...(typeof surfaceBlank === "boolean" ? { surfaceBlank } : {}), + ...(typeof barrierActive === "boolean" ? { barrierActive } : {}), + ...(typeof replayAttempt === "number" ? { replayAttempt } : {}), + ...(typeof appForeground === "boolean" ? { appForeground } : {}), + }; +} + function parseMetadata(properties: Record): Metadata | null { const platform = optionalExact(properties.platform, "ios"); const clientChannel = optionalSetValue(properties.client_channel, new Set(["dev", "nightly", "production", "unknown"])) as @@ -433,10 +477,11 @@ function parseMetadata(properties: Record): Metadata | null { const traceId = optionalTraceID(properties.trace_id); const operation = optionalSetValue(properties.operation, new Set(["replay", "artifactScan", "artifactList", "model_list"])); const terminalPhase = optionalSetValue(properties.terminal_phase, new Set([ - "applied", "failed", "discarded", + "applied", "failed", "discarded", "hostCaptureFinished", "stalled", ])); + const replayFields = parseReplayContextFields(properties); if ([platform, clientChannel, appVersion, buildNumber, bundleIdentifier, osVersion, deviceModel, - traceId, operation, terminalPhase].includes(false)) return null; + traceId, operation, terminalPhase].includes(false) || replayFields === null) return null; if (properties.phase === "terminal_trace" && (typeof traceId !== "string" || typeof operation !== "string" || typeof terminalPhase !== "string")) { return null; @@ -451,6 +496,7 @@ function parseMetadata(properties: Record): Metadata | null { ...(typeof deviceModel === "string" ? { deviceModel } : {}), ...(typeof traceId === "string" ? { traceId } : {}), ...(typeof operation === "string" ? { operation } : {}), + ...replayFields, ...(typeof terminalPhase === "string" ? { terminalPhase } : {}), }; } @@ -494,6 +540,11 @@ export async function emitMobileNetworkOutcomes( "cmux.mobile.trace_id": observation.traceId, "cmux.mobile.operation": observation.operation, "cmux.mobile.terminal_phase": observation.terminalPhase, + "cmux.mobile.replay_trigger": observation.replayTrigger, + "cmux.mobile.surface_blank": observation.surfaceBlank, + "cmux.mobile.barrier_active": observation.barrierActive, + "cmux.mobile.replay_attempt": observation.replayAttempt, + "cmux.mobile.app_foreground": observation.appForeground, }, (span) => { if (observation.outcome === "failure" || observation.outcome === "timeout") { @@ -638,6 +689,14 @@ function optionalDiagnosticInteger(value: unknown, maximum = 0xffff_ffff): numbe return parsed === null || parsed > maximum ? false : parsed; } +/// `false` is a legitimate value here, so an invalid one reports `null` +/// rather than joining the `false`-means-rejected convention used by the +/// string and integer helpers. +function optionalBoolean(value: unknown): boolean | undefined | null { + if (value === undefined) return undefined; + return typeof value === "boolean" ? value : null; +} + function optionalExact(value: unknown, expected: T): T | undefined | false { if (value === undefined) return undefined; return value === expected ? expected : false; diff --git a/web/tests/mobile-replay-stall-observability.test.ts b/web/tests/mobile-replay-stall-observability.test.ts new file mode 100644 index 000000000000..a85697069898 --- /dev/null +++ b/web/tests/mobile-replay-stall-observability.test.ts @@ -0,0 +1,75 @@ +import { describe, expect, test } from "bun:test"; + +import { parseMobileNetworkOutcome } from "../services/observability/mobileNetworkOutcome"; + +/** + * A replay that never settles leaves a surface blank with only a cursor. The + * client reports it as a non-terminal `stalled` phase; these lock the contract + * that carries that row through to Axiom. + */ +describe("terminal replay stall telemetry", () => { + const stall = (properties: Record = {}) => ({ + event: "ios_connectivity_latency", + timestamp: "2026-09-23T19:05:25.000Z", + properties: { + runtime_role: "mobileClient", + phase: "terminal_trace", + outcome: "stalled", + duration_ms: 30_000, + user_usable: false, + trace_id: "00000000000b1a4f", + operation: "replay", + terminal_phase: "stalled", + replay_trigger: "outputReset", + surface_blank: true, + barrier_active: true, + replay_attempt: 1, + app_foreground: true, + ...properties, + }, + }); + + test("accepts a stalled replay with its blank-surface context", () => { + const parsed = parseMobileNetworkOutcome(stall()); + expect(parsed).not.toBeNull(); + expect(parsed?.outcome).toBe("stalled"); + expect(parsed?.terminalPhase).toBe("stalled"); + expect(parsed?.replayTrigger).toBe("outputReset"); + expect(parsed?.surfaceBlank).toBe(true); + expect(parsed?.barrierActive).toBe(true); + expect(parsed?.replayAttempt).toBe(1); + }); + + test("keeps surface_blank false distinguishable from an absent value", () => { + const painted = parseMobileNetworkOutcome(stall({ surface_blank: false })); + expect(painted?.surfaceBlank).toBe(false); + const absent = parseMobileNetworkOutcome( + stall({ surface_blank: undefined, barrier_active: undefined }), + ); + expect(absent).not.toBeNull(); + expect(absent?.surfaceBlank).toBeUndefined(); + }); + + test("carries whether the stall was on screen or across suspension", () => { + expect(parseMobileNetworkOutcome(stall())?.appForeground).toBe(true); + expect(parseMobileNetworkOutcome(stall({ app_foreground: false }))?.appForeground).toBe(false); + expect(parseMobileNetworkOutcome(stall({ app_foreground: "yes" }))).toBeNull(); + }); + + test("rejects a non-boolean blank flag and an unknown trigger", () => { + expect(parseMobileNetworkOutcome(stall({ surface_blank: "yes" }))).toBeNull(); + expect(parseMobileNetworkOutcome(stall({ replay_trigger: "madeUp" }))).toBeNull(); + }); + + test("accepts the host capture split on a settled replay", () => { + const parsed = parseMobileNetworkOutcome( + stall({ outcome: "success", terminal_phase: "hostCaptureFinished" }), + ); + expect(parsed?.terminalPhase).toBe("hostCaptureFinished"); + }); + + test("still requires trace id and operation on every terminal trace", () => { + expect(parseMobileNetworkOutcome(stall({ trace_id: undefined }))).toBeNull(); + expect(parseMobileNetworkOutcome(stall({ operation: undefined }))).toBeNull(); + }); +});