diff --git a/Sources/LiveKit/Core/Room.swift b/Sources/LiveKit/Core/Room.swift index 8d7b994ce..6d5aa139c 100644 --- a/Sources/LiveKit/Core/Room.swift +++ b/Sources/LiveKit/Core/Room.swift @@ -220,14 +220,19 @@ public class Room: NSObject, @unchecked Sendable, ObservableObject, Loggable { super.init() // log sdk & os versions - log("sdk: \(LiveKitSDK.version), os: \(String(describing: Utils.os()))(\(Utils.osVersionString())), modelId: \(String(describing: Utils.modelIdentifier() ?? "unknown"))") + log("SDK initialized", .info, metadata: [ + "version": LiveKitSDK.version, + "os": String(describing: Utils.os()), + "osVersion": Utils.osVersionString(), + "modelId": Utils.modelIdentifier() ?? "unknown", + ]) signalClient._delegate.set(delegate: self) - log() + log("Room instance initialized") if let delegate { - log("delegate: \(String(describing: delegate))") + log("Room delegate registered", metadata: ["delegate": String(describing: delegate)]) delegates.add(delegate: delegate) } @@ -275,7 +280,9 @@ public class Room: NSObject, @unchecked Sendable, ObservableObject, Loggable { } if (newState.connectionState != oldState.connectionState) || (newState.isReconnectingWithMode != oldState.isReconnectingWithMode) { - self.log("connectionState: \(oldState.connectionState) -> \(newState.connectionState), reconnectMode: \(String(describing: newState.isReconnectingWithMode))") + self.log("State change: [connectionState] \(oldState.connectionState) → \(newState.connectionState)", metadata: [ + "reconnectMode": newState.isReconnectingWithMode as Any, + ]) } self.engine(self, didMutateState: newState, oldState: oldState) @@ -307,7 +314,7 @@ public class Room: NSObject, @unchecked Sendable, ObservableObject, Loggable { } deinit { - log(nil, .trace) + log("Room instance deallocating", .trace) } @objc @@ -317,11 +324,15 @@ public class Room: NSObject, @unchecked Sendable, ObservableObject, Loggable { roomOptions: RoomOptions? = nil) async throws { guard let url = URL(string: url), url.isValidForConnect else { - log("URL parse failed", .error) + log("Operation failed: [room.connect] invalid URL format", .error, metadata: ["url": url]) throw LiveKitError(.failedToParseUrl) } - log("Connecting to room...", .info) + log("Room connecting: initiating connection sequence", .info, metadata: [ + "url": url, + "connectOptions": connectOptions as Any, + "roomOptions": roomOptions as Any, + ]) var state = _state.copy() @@ -396,7 +407,11 @@ public class Room: NSObject, @unchecked Sendable, ObservableObject, Loggable { throw error } - log("Connected to \(String(describing: self))", .info) + log("Room connected: connection established successfully", .info, metadata: [ + "room": String(describing: self), + "sid": _state.sid as Any, + "serverVersion": _state.serverInfo?.version as Any, + ]) } @objc @@ -405,9 +420,13 @@ public class Room: NSObject, @unchecked Sendable, ObservableObject, Loggable { if case .disconnected = connectionState { return } do { + log("Room disconnecting: sending leave request") try await signalClient.sendLeave() } catch { - log("Failed to send leave with error: \(error)") + log("Operation failed: [room.disconnect] error sending leave message", .warning, metadata: [ + "error": error, + "connectionState": connectionState, + ]) } await cleanUp() @@ -421,7 +440,11 @@ extension Room { func cleanUp(withError disconnectError: Error? = nil, isFullReconnect: Bool = false) async { - log("withError: \(String(describing: disconnectError)), isFullReconnect: \(isFullReconnect)") + log("Room cleanup: releasing resources", metadata: [ + "error": disconnectError as Any, + "isFullReconnect": isFullReconnect, + "connectionState": _state.connectionState, + ]) // Reset completers _sidCompleter.reset() @@ -466,7 +489,11 @@ extension Room { extension Room { func cleanUpParticipants(isFullReconnect: Bool = false, notify _notify: Bool = true) async { - log("notify: \(_notify)") + log("Room cleanup: removing participants", metadata: [ + "notify": _notify, + "isFullReconnect": isFullReconnect, + "remoteParticipantCount": _state.remoteParticipants.count, + ]) // Stop all local & remote tracks var allParticipants: [Participant] = Array(_state.remoteParticipants.values) diff --git a/Sources/LiveKit/Core/SignalClient.swift b/Sources/LiveKit/Core/SignalClient.swift index f119ae07a..59b408b35 100644 --- a/Sources/LiveKit/Core/SignalClient.swift +++ b/Sources/LiveKit/Core/SignalClient.swift @@ -64,7 +64,9 @@ actor SignalClient: Loggable { do { // Prepare request data... guard let data = try? request.serializedData() else { - self.log("Could not serialize request data", .error) + self.log("Operation failed: [signalClient.sendRequest] request serialization error", .error, metadata: [ + "requestType": String(describing: request.message), + ]) throw LiveKitError(.failedToConvertData, message: "Failed to convert data") } @@ -72,7 +74,10 @@ actor SignalClient: Loggable { try await webSocket.send(data: data) } catch { - self.log("Failed to send queued request \(request) with error: \(error)", .warning) + self.log("Operation failed: [signalClient.sendRequest] unable to send request", .warning, metadata: [ + "requestType": String(describing: request.message), + "error": error, + ]) } }) @@ -99,19 +104,19 @@ actor SignalClient: Loggable { let _state = StateSync(State()) init() { - log() + log("SignalClient instance initialized") _state.onDidMutate = { [weak self] newState, oldState in guard let self else { return } // ConnectionState if oldState.connectionState != newState.connectionState { - self.log("\(oldState.connectionState) -> \(newState.connectionState)") + self.log("State change: [connectionState] \(oldState.connectionState) → \(newState.connectionState)") self._delegate.notifyDetached { await $0.signalClient(self, didUpdateConnectionState: newState.connectionState, oldState: oldState.connectionState, disconnectError: self.disconnectError) } } } } deinit { - log(nil, .trace) + log("SignalClient instance deallocating", .trace) } @discardableResult @@ -124,9 +129,12 @@ actor SignalClient: Loggable { { await cleanUp() - if let reconnectMode { - log("[Connect] mode: \(String(describing: reconnectMode))") - } + let reconnectModeStr = reconnectMode.map { String(describing: $0) } ?? "none" + log("SignalClient connecting: preparing connection", metadata: [ + "reconnectMode": reconnectModeStr, + "participantSid": participantSid as Any, + "adaptiveStream": adaptiveStream, + ]) let url = try Utils.buildUrl(url, token, @@ -135,11 +143,10 @@ actor SignalClient: Loggable { participantSid: participantSid, adaptiveStream: adaptiveStream) - if reconnectMode != nil { - log("[Connect] with url: \(url)") - } else { - log("Connecting with url: \(url)") - } + log("SignalClient connecting: initiating WebSocket connection", metadata: [ + "url": url, + "reconnectMode": reconnectModeStr, + ]) _state.mutate { $0.connectionState = (reconnectMode != nil ? .reconnecting : .connecting) } @@ -147,12 +154,15 @@ actor SignalClient: Loggable { let socket = try await WebSocket(url: url, connectOptions: connectOptions) let task = Task.detached { - self.log("Did enter WebSocket message loop...") + self.log("SignalClient socket: message loop started", .debug, metadata: [ + "url": url, + ]) do { for try await message in socket { await self._onWebSocketMessage(message: message) } } catch { + self.log("SignalClient socket: message loop terminated with error", .error, metadata: ["error": error]) await self.cleanUp(withError: error) } } @@ -192,16 +202,23 @@ actor SignalClient: Loggable { adaptiveStream: adaptiveStream, validate: true) - log("Validating with url: \(validateUrl)...") + log("SignalClient connecting: validating connection URL", metadata: [ + "validateUrl": validateUrl, + ]) let validationResponse = try await HTTP.requestString(from: validateUrl) - log("Validate response: \(validationResponse)") + log("SignalClient connecting: received validation response", metadata: [ + "response": validationResponse, + ]) // re-throw with validation response throw LiveKitError(.network, message: "Validation response: \"\(validationResponse)\"") } } func cleanUp(withError disconnectError: Error? = nil) async { - log("withError: \(String(describing: disconnectError))") + log("SignalClient cleanup: releasing resources", metadata: [ + "error": disconnectError as Any, + "connectionState": _state.connectionState, + ]) // Cancel ping/pong timers immediately to prevent stale timers from affecting future connections _pingIntervalTimer.cancel() @@ -234,7 +251,9 @@ private extension SignalClient { // Send request or enqueue while reconnecting func _sendRequest(_ request: Livekit_SignalRequest) async throws { guard connectionState != .disconnected else { - log("connectionState is .disconnected", .error) + log("Operation failed: [signalClient.sendRequest] client disconnected", .error, metadata: [ + "requestType": String(describing: request.message), + ]) throw LiveKitError(.invalidState, message: "connectionState is .disconnected") } @@ -251,7 +270,9 @@ private extension SignalClient { }() guard let response else { - log("Failed to decode SignalResponse", .warning) + log("Message processing failed: [signalClient.onWebSocketMessage] invalid message format", .warning, metadata: [ + "messageType": String(describing: message), + ]) return } @@ -269,12 +290,16 @@ private extension SignalClient { func _process(signalResponse: Livekit_SignalResponse) async { guard connectionState != .disconnected else { - log("connectionState is .disconnected", .error) + log("Operation skipped: [signalClient.processResponse] client disconnected", .error, metadata: [ + "message": String(describing: signalResponse.message), + ]) return } guard let message = signalResponse.message else { - log("Failed to decode SignalResponse", .warning) + log("Message processing failed: [signalClient.processResponse] missing message content", .warning, metadata: [ + "response": String(describing: signalResponse), + ]) return } @@ -310,7 +335,10 @@ private extension SignalClient { _delegate.notifyDetached { await $0.signalClient(self, didUpdateRoom: update.room) } case let .trackPublished(trackPublished): - log("[publish] resolving completer for cid: \(trackPublished.cid)") + log("Track published: received server confirmation", metadata: [ + "trackCid": trackPublished.cid, + "trackInfo": String(describing: trackPublished.track), + ]) // Complete await _addTrackCompleters.resume(returning: trackPublished.track, for: trackPublished.cid) @@ -350,10 +378,10 @@ private extension SignalClient { await _onReceivedPongResp(pongResp) case .subscriptionResponse: - log("Received subscriptionResponse message") + log("Message received: [subscription] subscription response from server") case .requestResponse: - log("Received requestResponse message") + log("Message received: [request] request response from server") case let .trackSubscribed(trackSubscribed): _delegate.notifyDetached { await $0.signalClient(self, didSubscribeTrack: Track.Sid(from: trackSubscribed.trackSid)) } @@ -613,7 +641,10 @@ extension SignalClient { } // Log timestamp and RTT for debugging - log("Sending ping with timestamp: \(timestamp)ms, reporting RTT: \(rtt)ms", .trace) + log("Network ping: sending ping to server", .trace, metadata: [ + "timestamp": timestamp, + "reportingRTT": rtt, + ]) // Send both requests try await _sendRequest(pingRequest) @@ -626,13 +657,18 @@ extension SignalClient { private extension SignalClient { func _onPingIntervalTimer() async throws { guard let jr = _state.lastJoinResponse else { return } - log("ping/pong sending ping...", .trace) + log("Network ping: interval timer triggered", .trace, metadata: [ + "pingInterval": jr.pingInterval, + "pingTimeout": jr.pingTimeout, + ]) try await _sendPing() _pingTimeoutTimer.setTimerInterval(TimeInterval(jr.pingTimeout)) _pingTimeoutTimer.setTimerBlock { [weak self] in guard let self else { return } - self.log("ping/pong timed out", .error) + self.log("Network ping: timeout waiting for server response", .error, metadata: [ + "timeoutMs": jr.pingTimeout, + ]) await self.cleanUp(withError: LiveKitError(.serverPingTimedOut)) } @@ -640,7 +676,7 @@ private extension SignalClient { } func _onReceivedPong(_: Int64) async { - log("ping/pong received pong from server", .trace) + log("Network ping: received basic pong response", .trace) // Clear timeout timer _pingTimeoutTimer.cancel() } @@ -649,7 +685,10 @@ private extension SignalClient { let currentTimeMs = Int64(Date().timeIntervalSince1970 * 1000) let rtt = currentTimeMs - pongResp.lastPingTimestamp _state.mutate { $0.rtt = rtt } - log("ping/pong received pongResp from server with RTT: \(rtt)ms", .trace) + log("Network ping: received enhanced pong response", .trace, metadata: [ + "rttMs": rtt, + "timestamp": pongResp.lastPingTimestamp, + ]) // Clear timeout timer _pingTimeoutTimer.cancel() } @@ -665,7 +704,10 @@ private extension SignalClient { jr.pingTimeout > 0, jr.pingInterval > 0 else { return } - log("ping/pong starting with interval: \(jr.pingInterval), timeout: \(jr.pingTimeout)") + log("Network ping: starting ping service", metadata: [ + "pingInterval": jr.pingInterval, + "pingTimeout": jr.pingTimeout, + ]) // Update interval... _pingIntervalTimer.setTimerInterval(TimeInterval(jr.pingInterval)) @@ -689,7 +731,9 @@ extension Livekit_SignalRequest { private extension SignalClient { func requireWebSocket() async throws -> WebSocket { guard let result = _state.socket else { - log("WebSocket is nil", .error) + log("Operation failed: [signalClient.requireWebSocket] missing WebSocket connection", .error, metadata: [ + "connectionState": _state.connectionState, + ]) throw LiveKitError(.invalidState, message: "WebSocket is nil") } diff --git a/Sources/LiveKit/Core/Transport.swift b/Sources/LiveKit/Core/Transport.swift index cd2678261..c62bbc588 100644 --- a/Sources/LiveKit/Core/Transport.swift +++ b/Sources/LiveKit/Core/Transport.swift @@ -70,7 +70,11 @@ actor Transport: NSObject, Loggable { do { try await self._pc.add(iceCandidate.toRTCType()) } catch { - self.log("Failed to add(iceCandidate:) with error: \(error)", .error) + self.log("Operation failed: [transport.addIceCandidate] couldn't add ICE candidate", .error, metadata: [ + "target": self.target, + "iceCandidate": iceCandidate, + "error": error, + ]) } }) @@ -90,14 +94,18 @@ actor Transport: NSObject, Loggable { _pc = pc super.init() - log() + log("Transport instance initialized", metadata: [ + "target": target, + ]) _pc.delegate = self _delegate.add(delegate: delegate) } deinit { - log(nil, .trace) + log("Transport instance deallocating", .trace, metadata: [ + "target": target, + ]) } func negotiate() async { @@ -217,7 +225,10 @@ extension Transport { extension Transport: LKRTCPeerConnectionDelegate { nonisolated func peerConnection(_: LKRTCPeerConnection, didChange state: RTCPeerConnectionState) { - log("[Connect] Transport(\(target)) did update state: \(state.description)") + log("Transport state changed", metadata: [ + "target": target, + "state": state.description, + ]) _delegate.notify { $0.transport(self, didUpdateState: state) } } @@ -226,32 +237,52 @@ extension Transport: LKRTCPeerConnectionDelegate { } nonisolated func peerConnectionShouldNegotiate(_: LKRTCPeerConnection) { - log("ShouldNegotiate for \(target)") + log("Transport negotiation needed", metadata: [ + "target": target, + ]) _delegate.notify { $0.transportShouldNegotiate(self) } } nonisolated func peerConnection(_: LKRTCPeerConnection, didAdd rtpReceiver: LKRTCRtpReceiver, streams: [LKRTCMediaStream]) { guard let track = rtpReceiver.track else { - log("Track is empty for \(target)", .warning) + log("Transport received empty track", .warning, metadata: [ + "target": target, + "rtpReceiver": String(describing: rtpReceiver), + ]) return } - log("type: \(type(of: track)), track.id: \(track.trackId), streams: \(streams.map { "Stream(hash: \($0.hash), id: \($0.streamId), videoTracks: \($0.videoTracks.count), audioTracks: \($0.audioTracks.count))" })") + log("Transport received new track", metadata: [ + "target": target, + "trackType": String(describing: type(of: track)), + "trackId": track.trackId, + "streams": streams.map { "\($0.streamId) (v:\($0.videoTracks.count), a:\($0.audioTracks.count))" }, + ]) _delegate.notify { $0.transport(self, didAddTrack: track, rtpReceiver: rtpReceiver, streams: streams) } } nonisolated func peerConnection(_: LKRTCPeerConnection, didRemove rtpReceiver: LKRTCRtpReceiver) { guard let track = rtpReceiver.track else { - log("Track is empty for \(target)", .warning) + log("Transport received empty track for removal", .warning, metadata: [ + "target": target, + "rtpReceiver": String(describing: rtpReceiver), + ]) return } - log("didRemove track: \(track.trackId)") + log("Transport removed track", metadata: [ + "target": target, + "trackId": track.trackId, + ]) _delegate.notify { $0.transport(self, didRemoveTrack: track) } } nonisolated func peerConnection(_: LKRTCPeerConnection, didOpen dataChannel: LKRTCDataChannel) { - log("Received data channel \(dataChannel.label) for \(target)") + log("Transport opened data channel", metadata: [ + "target": target, + "label": dataChannel.label, + "channelId": dataChannel.channelId, + ]) _delegate.notify { $0.transport(self, didOpenDataChannel: dataChannel) } } diff --git a/Sources/LiveKit/Extensions/Logger.swift b/Sources/LiveKit/Extensions/Logger.swift index a685b257e..007892d75 100644 --- a/Sources/LiveKit/Extensions/Logger.swift +++ b/Sources/LiveKit/Extensions/Logger.swift @@ -44,6 +44,27 @@ extension Loggable { function: function, line: line) } + + /// Log with structured metadata + func log(_ message: Logger.Message, + _ level: Logger.Level = .debug, + file: String = #fileID, + type type_: Any.Type? = nil, + function: String = #function, + line: UInt = #line, + metadata: [String: Any]? = nil) + { + var scopedMetadata = ScopedMetadataContainer() + metadata?.forEach { scopedMetadata[$0.key] = String(describing: $0.value) } + + logger.log(message, + level, + file: file, + type: type_ ?? type(of: self), + function: function, + line: line, + metaData: scopedMetadata) + } } extension Logger { diff --git a/Sources/LiveKit/Track/Track.swift b/Sources/LiveKit/Track/Track.swift index 49f6d8478..b8ee414ab 100644 --- a/Sources/LiveKit/Track/Track.swift +++ b/Sources/LiveKit/Track/Track.swift @@ -220,10 +220,6 @@ public class Track: NSObject, @unchecked Sendable, Loggable { await _resumeOrSuspendStatisticsTimer() } - func set(trackState: TrackState) { - _state.mutate { $0.trackState = trackState } - } - // Intended for child class to override func startCapture() async throws {}