diff --git a/FptnVPNTunnel/Diagnostics/TunnelSignposts.swift b/FptnVPNTunnel/Diagnostics/TunnelSignposts.swift new file mode 100644 index 0000000..b88cf29 --- /dev/null +++ b/FptnVPNTunnel/Diagnostics/TunnelSignposts.swift @@ -0,0 +1,91 @@ +#if FPTN_SIGNPOSTS +import OSLog + +// PR3A: Instruments signposts for tunnel lifecycle profiling. +// Compiled only in Debug and Measurement builds. +// Numeric metadata only — no interpolated strings. +enum TunnelSignposts { + static let signposter = OSSignposter( + subsystem: "net.mrmidi.FptnVPN.FptnVPNTunnel", + category: "TunnelLifecycle" + ) + + // MARK: - Intervals + + static func beginTunnelStartup() -> OSSignpostIntervalState { + signposter.beginInterval("TunnelStartup") + } + + static func endTunnelStartup(_ state: OSSignpostIntervalState) { + signposter.endInterval("TunnelStartup", state) + } + + static func beginBridgeLifetime(generation: Int) -> (OSSignpostID, OSSignpostIntervalState) { + let id = signposter.makeSignpostID() + let state = signposter.beginInterval("BridgeLifetime", id: id) + return (id, state) + } + + static func endBridgeLifetime(_ state: OSSignpostIntervalState, generation: Int) { + signposter.endInterval("BridgeLifetime", state) + } + + static func beginNativeTeardown(generation: Int) -> (OSSignpostID, OSSignpostIntervalState) { + let id = signposter.makeSignpostID() + let state = signposter.beginInterval("NativeTeardown", id: id) + return (id, state) + } + + static func endNativeTeardown(_ state: OSSignpostIntervalState, generation: Int, activeOps: UInt32) { + signposter.endInterval("NativeTeardown", state) + } + + static func beginTunnelShutdown() -> OSSignpostIntervalState { + signposter.beginInterval("TunnelShutdown") + } + + static func endTunnelShutdown(_ state: OSSignpostIntervalState) { + signposter.endInterval("TunnelShutdown", state) + } + + static func beginReconnectDelay(attempt: Int) -> (OSSignpostID, OSSignpostIntervalState) { + let id = signposter.makeSignpostID() + let state = signposter.beginInterval("ReconnectDelay", id: id) + return (id, state) + } + + static func endReconnectDelay(_ state: OSSignpostIntervalState, attempt: Int) { + signposter.endInterval("ReconnectDelay", state) + } + + static func beginReadLoopLifetime() -> OSSignpostIntervalState { + signposter.beginInterval("ReadLoopLifetime") + } + + static func endReadLoopLifetime(_ state: OSSignpostIntervalState) { + signposter.endInterval("ReadLoopLifetime", state) + } + + // MARK: - Point events + + static func transportConnected(generation: Int) { + signposter.emitEvent("TransportConnected") + } + + static func transportDisconnected(generation: Int) { + signposter.emitEvent("TransportDisconnected") + } + + static func networkPathChanged(satisfied: Bool) { + signposter.emitEvent("NetworkPathChanged") + } + + static func memoryWarning() { + signposter.emitEvent("MemoryWarning") + } + + static func invariantViolation() { + signposter.emitEvent("InvariantViolation") + } +} +#endif diff --git a/FptnVPNTunnel/PacketTunnelProvider.swift b/FptnVPNTunnel/PacketTunnelProvider.swift index 5c0b112..22a6f52 100644 --- a/FptnVPNTunnel/PacketTunnelProvider.swift +++ b/FptnVPNTunnel/PacketTunnelProvider.swift @@ -8,6 +8,9 @@ import Foundation import Darwin import Network import NetworkExtension +#if FPTN_SIGNPOSTS +import OSLog +#endif private enum TunnelControlAction: String, Codable { case setLogLevel = "set_log_level" @@ -237,6 +240,18 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { private var physicalFootprintPeakBytes: UInt64 = 0 private var latestEventSequence: UInt64 = 0 + // PR3A: Instruments signpost state (Debug/Measurement only). + // Protected by signpostLock — never hold stateLock while emitting. + #if FPTN_SIGNPOSTS + private let signpostLock = NSLock() + private var startupSignpost: OSSignpostIntervalState? + private var bridgeSignpost: (generation: Int, id: OSSignpostID, state: OSSignpostIntervalState)? + private var teardownSignpost: (generation: Int, id: OSSignpostID, state: OSSignpostIntervalState)? + private var shutdownSignpost: OSSignpostIntervalState? + private var reconnectSignpost: (attempt: Int, id: OSSignpostID, state: OSSignpostIntervalState)? + private var readLoopSignpost: OSSignpostIntervalState? + #endif + private var wsClient: WebsocketClientBridge? private var configuration: TunnelConfiguration? private var assignedIPv4: String? @@ -297,6 +312,11 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { options: [String: NSObject]?, completionHandler: @escaping (Error?) -> Void ) { + #if FPTN_SIGNPOSTS + signpostLock.lock() + startupSignpost = TunnelSignposts.beginTunnelStartup() + signpostLock.unlock() + #endif bootstrapLogging() TunnelCrashSignalInstaller.installIfPossible() @@ -333,6 +353,9 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { let runtimeConfig = TunnelConfiguration(providerConfiguration: providerConfig) else { let err = makeError("Missing or incomplete providerConfiguration") logger.error("startTunnel failed: \(err.localizedDescription)") + #if FPTN_SIGNPOSTS + endStartupSignpost() + #endif completionHandler(err) return } @@ -394,16 +417,31 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { ) { let description = describeStopReason(reason.rawValue) let initiator = currentOrDefaultStopInitiator() + #if FPTN_SIGNPOSTS + signpostLock.lock() + shutdownSignpost = TunnelSignposts.beginTunnelShutdown() + signpostLock.unlock() + #endif stateLock.lock() shutdownRequested = true lastStopReasonRawValue = Int(reason.rawValue) lastStopReason = description + let wasReadLoopActive = isReadLoopActive isReadLoopActive = false // PR2: do NOT clear isPacketReadPending — the outstanding // readPackets callback still exists and owns the slot. stateLock.unlock() + // PR3A: end ReadLoopLifetime on true→false transition, outside lock. + #if FPTN_SIGNPOSTS + if wasReadLoopActive { + signpostLock.lock() + if let sp = readLoopSignpost { TunnelSignposts.endReadLoopLifetime(sp); readLoopSignpost = nil } + signpostLock.unlock() + } + #endif + updateRuntimeState(.stopping, reason: "stopTunnel(\(description))") logger.warning( "PacketTunnelProvider stopTunnel reason=\(reason.rawValue) (\(description)) initiator=\(initiator.rawValue)" @@ -424,6 +462,14 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { finishStart(with: makeError("Tunnel stopped before startup completed")) replaceWebSocketClient(with: nil, stopCurrent: true) + #if FPTN_SIGNPOSTS + signpostLock.lock() + if let sp = shutdownSignpost { + TunnelSignposts.endTunnelShutdown(sp) + shutdownSignpost = nil + } + signpostLock.unlock() + #endif completionHandler() } @@ -450,8 +496,17 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { stateLock.lock() localStopInitiator = .appDisconnect shutdownRequested = true + let wasReadLoopActive = isReadLoopActive isReadLoopActive = false stateLock.unlock() + // PR3A: end ReadLoopLifetime outside lock. + #if FPTN_SIGNPOSTS + if wasReadLoopActive { + signpostLock.lock() + if let sp = readLoopSignpost { TunnelSignposts.endReadLoopLifetime(sp); readLoopSignpost = nil } + signpostLock.unlock() + } + #endif cancelPendingReconnect() cancelReadBackpressure() logger.info("Marked local stop initiator via IPC: \(initiator); reconnect will be suppressed") @@ -632,6 +687,9 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { } logger.info("Tunnel transport connected \(activityDiagnosticsDescription())") + #if FPTN_SIGNPOSTS + signpostLock.lock(); TunnelSignposts.transportConnected(generation: generation); signpostLock.unlock() + #endif recordProviderEvent(category: "websocket", message: "transport_connected generation=\(generation)", generation: generation, flightEvent: .bridgeConnected) if shouldApplySettings { @@ -655,11 +713,21 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { self.appliedIPv4 = pendingAppliedIPv4 self.appliedIPv6 = pendingAppliedIPv6 self.didApplyNetworkSettings = true + let shouldBeginReadLoop = !self.isReadLoopActive self.isReadLoopActive = true self.reconnectAttempt = 0 self.lastTransportError = nil self.stateLock.unlock() + // PR3A: begin ReadLoopLifetime only on false→true transition. + #if FPTN_SIGNPOSTS + if shouldBeginReadLoop { + self.signpostLock.lock() + self.readLoopSignpost = TunnelSignposts.beginReadLoopLifetime() + self.signpostLock.unlock() + } + #endif + self.updateRuntimeState(.connected, reason: "websocket connected and settings applied") self.recordProviderEvent(category: "settings", message: "apply_success generation=\(generation)", generation: generation, flightEvent: .tunnelConnected) self.clearReadBackpressure() @@ -722,6 +790,9 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { flightEvent: .transportDisconnected ) updateDiagnosticsHeartbeat(lastEvent: "transport_disconnected") + #if FPTN_SIGNPOSTS + signpostLock.lock(); TunnelSignposts.transportDisconnected(generation: generation); signpostLock.unlock() + #endif applyReadBackpressure(delay: sendFailureBackpressureMaxDelaySeconds, reason: "transport_disconnected") replaceWebSocketClient(with: nil, stopCurrent: false) cancelStartTimeout() @@ -855,6 +926,10 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { return .waitingForNetwork } + // PR3A: end previous ReconnectDelay before replacing. + #if FPTN_SIGNPOSTS + endReconnectDelaySignpost() + #endif reconnectWorkItem?.cancel() workItem = DispatchWorkItem { [weak self] in @@ -863,7 +938,18 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { reconnectWorkItem = workItem stateLock.unlock() + // PR3A: begin ReconnectDelay after work item is accepted. + #if FPTN_SIGNPOSTS + signpostLock.lock() + let rsp = TunnelSignposts.beginReconnectDelay(attempt: nextAttempt) + reconnectSignpost = (attempt: nextAttempt, id: rsp.0, state: rsp.1) + signpostLock.unlock() + #endif + if exceededConfiguredBudget { + #if FPTN_SIGNPOSTS + endReconnectDelaySignpost() + #endif logger.warning( "Reconnect attempt \(nextAttempt) exceeded configured budget \(maxAttempts). Failing tunnel." ) @@ -892,6 +978,10 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { } private func performReconnectAttempt(expectedGeneration: Int) { + // PR3A: end ReconnectDelay when the attempt starts. + #if FPTN_SIGNPOSTS + endReconnectDelaySignpost() + #endif let configuration: TunnelConfiguration? let currentState: TunnelRuntimeState let attempt: Int @@ -1162,6 +1252,9 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { if !alreadyLogged { logger.error("INVARIANT_VIOLATION: \(invariant)") recordProviderEvent(category: "invariant", message: "violation \(invariant)", flightEvent: .invariantViolation) + #if FPTN_SIGNPOSTS + signpostLock.lock(); TunnelSignposts.invariantViolation(); signpostLock.unlock() + #endif } } @@ -1198,6 +1291,17 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { wsClient = nil stateLock.unlock() + // PR3A: begin NativeTeardown after detach. + #if FPTN_SIGNPOSTS + var teardownSP: (id: OSSignpostID, state: OSSignpostIntervalState)? + if previousClient != nil { + signpostLock.lock() + let sp = TunnelSignposts.beginNativeTeardown(generation: generation) + teardownSP = sp + signpostLock.unlock() + } + #endif + // Stop and join the previous bridge. if stopCurrent, let previousClient { _ = previousClient.stop(origin: stopOrigin) @@ -1217,6 +1321,19 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { if finalStatus.liveClients > 1 { logInvariantOnce(.multipleNativeClients) } + + // PR3A: end NativeTeardown + BridgeLifetime after final status. + #if FPTN_SIGNPOSTS + signpostLock.lock() + if let sp = teardownSP { + TunnelSignposts.endNativeTeardown(sp.state, generation: generation, activeOps: finalStatus.activeOperations) + } + if let bsp = bridgeSignpost { + TunnelSignposts.endBridgeLifetime(bsp.state, generation: bsp.generation) + bridgeSignpost = nil + } + signpostLock.unlock() + #endif } // PR2: bridgeReplacementOverlap removed — the previous bridge @@ -1238,6 +1355,16 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { return false } + // PR3A: begin BridgeLifetime for the newly exposed bridge. + #if FPTN_SIGNPOSTS + if newClient != nil { + signpostLock.lock() + let sp = TunnelSignposts.beginBridgeLifetime(generation: generation) + bridgeSignpost = (generation: generation, id: sp.0, state: sp.1) + signpostLock.unlock() + } + #endif + return true } @@ -1444,8 +1571,32 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { reconnectWorkItem = nil stateLock.unlock() workItem?.cancel() + endReconnectDelaySignpost() } + // PR3A: signpost helpers — capture state under lock, emit outside. + #if FPTN_SIGNPOSTS + private func endReconnectDelaySignpost() { + signpostLock.lock() + let sp = reconnectSignpost + reconnectSignpost = nil + signpostLock.unlock() + if let sp { + TunnelSignposts.endReconnectDelay(sp.state, attempt: sp.attempt) + } + } + + private func endStartupSignpost() { + signpostLock.lock() + let sp = startupSignpost + startupSignpost = nil + signpostLock.unlock() + if let sp { + TunnelSignposts.endTunnelStartup(sp) + } + } + #endif + private func startPathMonitor() { stopPathMonitor() @@ -1504,6 +1655,9 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { recordProviderEvent(category: "path", message: "path_satisfied=\(isSatisfied) network=\(pathSummary)", pathSatisfied: isSatisfied, flightEvent: .pathChanged) updateDiagnosticsHeartbeat(lastEvent: "path_satisfied=\(isSatisfied) network=\(pathSummary)") if didPathChange { + #if FPTN_SIGNPOSTS + TunnelSignposts.networkPathChanged(satisfied: isSatisfied) + #endif applyReadBackpressure(delay: pathChangeBackpressureDelaySeconds, reason: "network_path_changed") } if shouldScheduleReconnect { @@ -1693,6 +1847,14 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { } private func finishStart(with error: Error?) { + #if FPTN_SIGNPOSTS + signpostLock.lock() + if let sp = startupSignpost { + TunnelSignposts.endTunnelStartup(sp) + startupSignpost = nil + } + signpostLock.unlock() + #endif var completion: ((Error?) -> Void)? stateLock.lock() @@ -2008,6 +2170,11 @@ final class PacketTunnelProvider: NEPacketTunnelProvider, @unchecked Sendable { stateLock.unlock() guard shouldLog else { return } logger.warning("Tunnel memory pressure \(memory.level.rawValue) \(memory.description)") + #if FPTN_SIGNPOSTS + if memory.level == .warning || memory.level == .emergency { + signpostLock.lock(); TunnelSignposts.memoryWarning(); signpostLock.unlock() + } + #endif } } diff --git a/project.yml b/project.yml index 63e9342..e23de5a 100644 --- a/project.yml +++ b/project.yml @@ -26,8 +26,11 @@ settings: configs: Debug: DEBUG_INFORMATION_FORMAT: dwarf + SWIFT_ACTIVE_COMPILATION_CONDITIONS: $(inherited) FPTN_SIGNPOSTS Release: DEBUG_INFORMATION_FORMAT: dwarf-with-dsym + Measurement: + SWIFT_ACTIVE_COMPILATION_CONDITIONS: $(inherited) FPTN_MEASUREMENT_BUILD FPTN_SIGNPOSTS configs: Debug: debug @@ -213,7 +216,7 @@ targets: # memory-only telemetry path. Build with -configuration Measurement # to produce a clean baseline for native memory profiling. Measurement: - SWIFT_ACTIVE_COMPILATION_CONDITIONS: $(inherited) FPTN_MEASUREMENT_BUILD + SWIFT_ACTIVE_COMPILATION_CONDITIONS: $(inherited) FPTN_MEASUREMENT_BUILD FPTN_SIGNPOSTS info: path: FptnVPNTunnel/Info.plist entitlements: